Time.GameTime lagged inside FixedUpdate

Scripting C#
#1

I made a simple interpolation code using Update() and FixedUpdete(), based on deltatime after last FixedUpdate() execution.

But I met strange ratio of delta time error of GameTime between Update() and FixedUpdate().

To be simple:

public override void OnUpdate()
{
    Debug.Log($"Update, Gametime :{FlaxEngine.Time.GameTime}");
}

public override void OnFixedUpdate()
{
    Debug.Log($"Fixed Update, GameTime:{FlaxEngine.Time.GameTime}");
}

Resulted following output log:

[ 16:40:33.913 ]: [Info] Update, Gametime :506.75983
[ 16:40:33.927 ]: [Info] Fixed Update, GameTime:506.54108
[ 16:40:33.931 ]: [Info] Update, Gametime :506.77652
[ 16:40:33.944 ]: [Info] Fixed Update, GameTime:506.55774
[ 16:40:33.947 ]: [Info] Update, Gametime :506.79318
[ 16:40:33.960 ]: [Info] Fixed Update, GameTime:506.5744
[ 16:40:33.963 ]: [Info] Update, Gametime :506.80988
[ 16:40:33.977 ]: [Info] Fixed Update, GameTime:506.5911
[ 16:40:33.980 ]: [Info] Update, Gametime :506.8265
[ 16:40:33.994 ]: [Info] Fixed Update, GameTime:506.60773
[ 16:40:33.998 ]: [Info] Update, Gametime :506.8432
[ 16:40:34.011 ]: [Info] Fixed Update, GameTime:506.62442
[ 16:40:34.014 ]: [Info] Update, Gametime :506.85983
[ 16:40:34.027 ]: [Info] Fixed Update, GameTime:506.64105
[ 16:40:34.030 ]: [Info] Update, Gametime :506.87653
[ 16:40:34.044 ]: [Info] Fixed Update, GameTime:506.65775
[ 16:40:34.047 ]: [Info] Update, Gametime :506.89316
[ 16:40:34.061 ]: [Info] Fixed Update, GameTime:506.67438
[ 16:40:34.063 ]: [Info] Update, Gametime :506.90985
[ 16:40:34.077 ]: [Info] Fixed Update, GameTime:506.69107
[ 16:40:34.081 ]: [Info] Update, Gametime :506.92648
[ 16:40:34.094 ]: [Info] Fixed Update, GameTime:506.70773
[ 16:40:34.097 ]: [Info] Update, Gametime :506.94318
[ 16:40:34.111 ]: [Info] Fixed Update, GameTime:506.7244
[ 16:40:34.113 ]: [Info] Update, Gametime :506.95984
[ 16:40:34.127 ]: [Info] Fixed Update, GameTime:506.74106

Apparently, FixedUpdate() called got less value of GameTime variable than Update(), regardless of sequence of calling. Headers of logs show the stable steps of 60FPS and deltas between Update<->Update and FixedUpdate<->FixedUpdate shows correct value of delta time, but timing calculation inside FixedUpdate is lagged behind Update about ~10x frames.

Is FlaxEngine.Time.GameTime desynced between OnUpdate and OnFixedUpdate?

#3

I made a simple interpolation code using Update( and Fixed Updete, based on delta time after last Fixed Update spacebar clicker execution. as shown below. An example showing Fixed Update running at 50 updates per second 0.02s per fixed update) and the Player Loop running at approximately 80 frames per second.Fixed update is indeed time scaled. Simple enough to test, just set the time scale to 1/100th and print something every fixedupdate.

#4

Thank you for reply.

I also suspected what you said first! Because in case of Unity, majority of physics FPS is 50 (different from variable FPS of logic and draw updates) and it is commonly desynced in world of Unity projects.

As far as I had searched, Flax engine loop checks whether the timing is for Update/Physics(Fixed)/Draw in single threaded loop, and the timings may be different. (Like most other engines)

    // Update application (will gather data and other platform related events)
    {
        PROFILE_CPU_NAMED("Platform.Tick");
        Platform::Tick();
    }
    
    // Update game logic
    if (Time::OnBeginUpdate(time))
    {
        OnUpdate();
        OnLateUpdate();
        Time::OnEndUpdate();
    }

    // Start physics simulation
    if (Time::OnBeginPhysics(time))
    {
        OnFixedUpdate();
        OnLateFixedUpdate();
        Time::OnEndPhysics();
    }

    // Draw frame
    if (Time::OnBeginDraw(time))
    {
        OnDraw();
        Time::OnEndDraw();
        FrameMark;
    }

And I also checked that both Update (OnUpdate) and Physics (OnFixedUpdate) FPS are 60, therefore timing for ‘next event broadcasting’ should be same, I thought.

image
image791×341 38.1 KB

Unidentical ceiling value of FPS can be common the root of the many interpolation situations, but I thought that the GameTime value retrieval is something else than that…

And everything aside, I remember that this happening had ‘fixed’ in later releases of engine.
Sorry couldn’t find the exact version changelog line…
I recreated the test set in current stable version 1.9.6605, and log is very much consistent.

[ 00:30:57.240 ]: [Info] Update, Gametime :2.3666651
[ 00:30:57.240 ]: [Info] Fixed Update, GameTime:2.3666577
[ 00:30:57.257 ]: [Info] Update, Gametime :2.3833315
[ 00:30:57.257 ]: [Info] Fixed Update, GameTime:2.3833244
[ 00:30:57.274 ]: [Info] Update, Gametime :2.399998
[ 00:30:57.274 ]: [Info] Fixed Update, GameTime:2.3999908
[ 00:30:57.290 ]: [Info] Update, Gametime :2.4166648
[ 00:30:57.290 ]: [Info] Fixed Update, GameTime:2.4166577
[ 00:30:57.307 ]: [Info] Update, Gametime :2.4333317
[ 00:30:57.307 ]: [Info] Fixed Update, GameTime:2.433324
[ 00:30:57.324 ]: [Info] Update, Gametime :2.4499981
[ 00:30:57.324 ]: [Info] Fixed Update, GameTime:2.4499907
[ 00:30:57.341 ]: [Info] Update, Gametime :2.4666648
[ 00:30:57.341 ]: [Info] Fixed Update, GameTime:2.4666572
[ 00:30:57.357 ]: [Info] Update, Gametime :2.4833314
[ 00:30:57.357 ]: [Info] Fixed Update, GameTime:2.483324
[ 00:30:57.374 ]: [Info] Update, Gametime :2.4999983
[ 00:30:57.374 ]: [Info] Fixed Update, GameTime:2.4999905
[ 00:30:57.391 ]: [Info] Update, Gametime :2.5166647
[ 00:30:57.391 ]: [Info] Fixed Update, GameTime:2.516657
[ 00:30:57.407 ]: [Info] Update, Gametime :2.5333312
[ 00:30:57.407 ]: [Info] Fixed Update, GameTime:2.5333235
[ 00:30:57.424 ]: [Info] Update, Gametime :2.549998
[ 00:30:57.424 ]: [Info] Fixed Update, GameTime:2.5499904
[ 00:30:57.440 ]: [Info] Update, Gametime :2.566665
[ 00:30:57.441 ]: [Info] Fixed Update, GameTime:2.5666568