Single frame spikes even in an empty project

[ghost]

Godot version: 3.1.1, 3.2b2

OS/device including version: Windows 10 Pro 1909 x64

Issue description: Every ~10 seconds i get a one-frame spike followed by 1-3 really short frames. At first i thought it was my fault, but problem persists even in an empty project.

Exported project exhibits same behavior.

My specs are i5 7300, 16gb DDR4, GTX 1050

Profiler screenshots:

Frame before the spike:

Spike:

Frame after the spike:

Steps to reproduce: 1) Attach a script with empty "_process" method anywhere in the scene, so that Editor may pause the scene (only for a profiler screenshot) 2) Run project and wait for ~10 sec

EDIT: So, in trying to narrow down the issue(at least as far as my abilities go), i tested this on some other machines

i7 - 9750H / 16 Gb DDR4 / RTX-2060 w/ Windows 10 - same thing, i3 - 3240 / 4 Gb RAM (didn't check at the time, i believe DDR3) / GeForce 8600GT w/ Windows 8.1 - same thing

I tried to check the first machine (i5 7300, 16gb DDR4, GTX 1050) with Manjaro 18.1.5 and didn't notice any of similar problems (although i couldn't get Vsync to work). Project, exported on Manjaro to Windows exhibits same behavior

3.2 rc4 didn't help.

EDIT 2: The Editing I decided to try Vulkan branch just to see if something different happens. Spikes aren't there, but i noticed really strange things happen with everything that is normalized for time (with delta), i haven't noticed this before because of short lag, but in Vulkan that short lag isn't there, and after some investigating, i found that sometimes delta is negative(with same frequency as spikes in stable version). Going back to 3.2, negative delta does happen at the same time as spikes, but not everytime.

So i guess, question is, could VSync issues and negative delta be related?

[ghost]

So, pull request #33414 fixes it in windowed mode, but in fullscreen it still happens, and sometimes its only short frame and visible stutter (without the spike)

[FeralBytes]

@sigma0x How many FPS are you running? Is it possibly related to heat, or for that matter you are on Windows, are there other processes that are causing the bump? What happens if you implement the low processor mode in the project? Also some jitter at max FPS is definitely unavoidable as you computer could be doing any number of things. Even with Low Processor Mode jitter still maybe unavoidable, as the OS gets to determine scheduling, not Godot. Was this Jitter absent in previous versions?

[lawnjelly]

Also for things like this you really need to run it as an exported release and not from the IDE, to compare. When running in the IDE afaik it does all kinds of stuff which could lead to spikes (including communication with the IDE presumably, and there may even be some Sleeps in there when running in the IDE).

[Zylann]

One of the most obvious IDE things is the "remote scene tree", make sure it's not enabled when checking performance.

[ghost]

@sigma0x How many FPS are you running? Is it possibly related to heat, or for that matter you are on Windows, are there other processes that are causing the bump? What happens if you implement the low processor mode in the project? Also some jitter at max FPS is definitely unavoidable as you computer could be doing any number of things. Even with Low Processor Mode jitter still maybe unavoidable, as the OS gets to determine scheduling, not Godot. Was this Jitter absent in previous versions?

@FeralBytes FPS is stable 60 except for the issue itself. Heat is not a problem for sure (61 C at most on CPU package), but im not sure how to track down if any other processes cause this problem (no browser, or anything like that was active). Low processor mode seems to make issue appear less frequently, but more noticable. I didnt try versrions older than 3.1.1

[ghost]

Also for things like this you really need to run it as an exported release and not from the IDE, to compare. When running in the IDE afaik it does all kinds of stuff which could lead to spikes (including communication with the IDE presumably, and there may even be some Sleeps in there when running in the IDE).

@lawnjelly I double-checked everything in an exported project, profiler screenshots are just for demonstration. The issue behaves identically in editor and in exported release.

[ghost]

One of the most obvious IDE things is the "remote scene tree", make sure it's not enabled when checking performance.

@Zylann It wasnt enabled.

[qdwang]

Same issue here.

And my three computers have different results.

i5 2300 + 750Ti has the spike issue(the spike frametime is about 77ms). i7 8550u + intel 620 doesn't have the spike issue. amd r5 3600 + 1660super also has the spike issue(the spike frametime is about 44ms).

Maybe it's related with nvidia card only?

[Calinou]

To advance this issue's resolution, it might be worth trying to run Godot in an external profiler like Tracy to see what it's doing exactly when there are frame time spikes.

[nathanfranke]

So i guess, question is, could VSync issues and negative delta be related?

Probably related to https://github.com/godotengine/godot/issues/26887

a one-frame spike followed by 1-3 really short frames

See this comment by @zmanuel who knows a lot more about this stuff than I do:

The system here tries to keep the outgoing deltas stable within the given bounds by physics_jitter_fix, and that sometimes means the "game clock" (sum of outgoing deltas) is ahead of the real clock (sum of incoming deltas), this will happen if the framerate increased from one moment to the next. And then again sometimes, the system decides that being ahead was a mistake and that it should resync game and real clock while the current incoming delta is very small, smaller than the difference between the two times. The bug was that it would do so by letting the game clock snap back, creating a negative delta. Now it just stops for a bit.

---

Can someone check if this is reproducible in Master? If so, try locally merging https://github.com/godotengine/godot/pull/35617 and testing it again.

[lawnjelly]

One question is whether the profiler measured frame time is the same as the frame time processed by jitter fix which is fed to _process(delta).

A quick glance looks like it may not be, if the profiling is done on this line in main.cpp Main::iteration:

script_debugger->profiling_set_frame_times(USEC_TO_SEC(frame_time), USEC_TO_SEC(idle_process_ticks), USEC_TO_SEC(physics_process_ticks), frame_slice);

As nathanfranke says there is a fix in for zmanuel's jitter fix #35617 which may or may not cure the negative delta issue, although the 2 may not be directly related. You may even be getting the negative deltas as a result of the frame spike, rather than the other way around.

Personally I'm of the opinion we should have a pass through reference timing method available which doesn't use jitter fix code at all for this kind of thing (I included one in #30798). Perhaps we'll get to revisit timing code properly in 4.x it sorely needs an overhaul.

If the spikes are not jitter fix related, they could be related to something like garbage collection on the CPU (including driver) or GPU, or something OS related. Having a profile of the spike frame compared to the normal frames would be useful, maybe a GPU debugger might help with this to see if anything special was happening on these frames.

[qdwang]

I've tried to turn the Physics Jitter Fix to 0, the issue is still occurred.

[ghost]

Can someone check if this is reproducible in Master? If so, try locally merging #35617 and testing it again.

i cannot reproduce it in master at all right now. neither performance spikes, nor negative deltas

[ghost]

To advance this issue's resolution, it might be worth trying to run Godot in an external profiler like Tracy to see what it's doing exactly when there are frame time spikes.

i am sorry if i sound stupid, but i can't understand how would i integrate something like tracy to profile the problem. i am eager to help, just don't get how to do that.

[Zylann]

Looking at https://github.com/godotengine/godot/issues/35996, you could try to measure how long this line takes to execute: https://github.com/godotengine/godot/blob/00949f0c5fcc6a4f8382a4a97d5591fd9ec380f8/platform/windows/context_gl_windows.cpp#L86 Just to verify. To do this you'd need to recompile the engine with some code added around it, to log something in case the call takes more than 32 ms?

[lawnjelly]

i cannot reproduce it in master at all right now. neither performance spikes, nor negative deltas

This would fit in with the hypothesis that it is caused by OpenGL (possibly garbage collection), rather than directly by Godot code (and negative deltas being a consequence rather than a cause).

[noidexe]

I'm using 3.2.2.rc2 and I'm getting a lag spike at almost exactly 30 seconds just like in #38815 I'm on windows 64 bits with a GTX 1050 and 60hz monitors.

It happens with GLES2, GLES3, vsync on/off, vsync via compostor on/off, windowed/fullscreen, setting jitter fix to 0, and even leaving the window unfocused and doing other tasks. Then after around 200000 ms of runtime I start getting lagspikes more often.

I wrote this to keep track and see if the spikes where really happening at around the same time:

extends Label

# Called every frame. 'delta' is the elapsed time since the previous frame.
var last_frame_time = OS.get_system_time_msecs()
var config:ConfigFile
var run_id
var config_path = "user://lagspikes.ini"

func _ready():
    randomize()
    run_id = str(randi()) + str(randi())
    config = ConfigFile.new()
    var err = config.load(config_path)
    if err == ERR_FILE_NOT_FOUND:
        config.save(config_path)

func _process(delta):
    if delta > 0.08:
        var spike = [str(OS.get_ticks_msec()), str(delta)]
        text += "Time: %s, dt: %s\n" % spike
        config.set_value(run_id, spike[0], spike[1])
    pass

func _notification(what):
    if what == NOTIFICATION_WM_QUIT_REQUEST:
        config.set_value(run_id, "total_run_time", str(round(OS.get_ticks_msec())))
        config.set_value(run_id, "vsync", ProjectSettings.get_setting("display/window/vsync/use_vsync"))
        config.set_value(run_id, "vsync_comp", ProjectSettings.get_setting("display/window/vsync/vsync_via_compositor"))
        config.set_value(run_id, "windowed", !OS.window_fullscreen)
        config.set_value(run_id, "driver", ProjectSettings.get_setting("rendering/quality/driver/driver_name"))
        config.set_value(run_id, "batching", ProjectSettings.get_setting("rendering/batching/options/use_batching"))
        config.save(config_path)

I also tracked it by hand with a cronometer just in case and the script doesn't seem to have any effect in whether the spikes happen or not, or their timestamps.

[clayrone]

I am also experiencing this issue both in editor and exported version. It is clearly visible stutter when moving the player, but it also happens on idle run, always around 30 seconds in.

Godot Version 3.2.2 stable

Spec Ryzen 3800X, GeForce RTX 2070 SUPER, Windows 10 PRO

---

[qdwang]

Can this issue be fixed in the future 3.2.x version? Or we have to wait until the 4.0 release?

[Calinou]

@qdwang We don't know when this will be fixed, as no definite cause has been identified yet. That said, a fix can likely be cherry-picked to the 3.2 branch once it's merged in master.

[muno777]

just chiming in to say that i'm also experiencing this.

this isn't an empty project - but all of my code is in _physics_process(), not _process().

(notably, it seems to repeat less often than the 10 seconds detailed in the OP - but it does repeat - and isn't followed by shorter frames)

[Zylann]

@muno777 did you check https://github.com/godotengine/godot/issues/33969#issuecomment-559589248 ?

[muno777]

@Zylann yep, remote scene tree is disabled:

[Zylann]

Is there any test project around that has this issue so we can have a look? Or is an empty project enough?

[noidexe]

Haven't checked with 3.3.2 but an empty project should be enough

On Fri, May 28, 2021, 11:08 Marc @.***> wrote:

Is there any test project around that has this issue? Or is an empty project enough?

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/godotengine/godot/issues/33969#issuecomment-850445398, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAEAT3JWULMHZJ6XAVCRM3LTP6PXNANCNFSM4JSWAVWA .

[muno777]

@Zylann here is an empty project (just a node2d and sprite in the scene) that gives the below graph on my end

test_proj.zip

[lawnjelly]

Looking back at this, it is actually possible this is a false flag, caused by queue stuffing. It depends whether there is a larger delta in output frames, or this is purely caused by a large delta in input frames. If there is no delta problem at output, then #48390 may be able to help / possibly cure this, ideally in conjunction with #48555.

[muno777]

false flag as in it's just a quirk of the graph / not an actual performance dip?

in my project, the fps also dips when it happens, so i don't think that's the case

[Zylann]

After about 1 (or 2?) minutes that's what I recorded in Godot's monitor:

Initial spike is when I started the game, second spike happened spontaneously without me doing anything special. It's hard to cross-check because the profiler and monitors are different tabs and update at different rates...

However this "process" monitor, where does it come from? Is it how long process takes? I had a look at scene_tree.cpp in SceneTree::idle, I don't see where such a monitor value is picked up. Instead it comes from a different place.

[Zylann]

I captured this in Tracy:

And it confirms my guess from https://github.com/godotengine/godot/issues/33969#issuecomment-633156246 :

The spike directly occurs from inside SwapBuffers, which includes v-sync so it takes most of the idle time (that's where it flushes OpenGL commands also?). It might be driver-related then, which means, out of our control? It also happens with vsync off. What ends up here might also be a result of commands issued earlier by Godot but that's outside my area of expertise.

[muno777]

It might be driver-related then, which means, out of our control?

i'm not technical enough to know how one might apply this,

but from looking up "opengl swapbuffers slow" on google, it sounds like there might be some room to improve this on the application's end?

not sure. this definitely doesn't seem like a novel problem, in any event - lots of results for the search query

[ibe-denaux]

I am having the same issue on two of my machines. Godot version 3.3.2-stable

specs machine 1: windows 10, GTX2060 super machine 2: windows 10, MX330 GPU drivers up to date.

Single frame spikes followed or preceded by a drop-off. pull request #33414 relieves the drop-off in windowed mode, but not the spike itself. The effects are not monitoring errors, since they can be noticed in-game.

What I have gathered so far is that it is unaffected by the way animations are done (process, physics_process, or animation/tween node as demonstrated in #33414), but it is dependent on the size of the project. An empty project will still spike, but the frequency is reduced (+- once every 30 seconds). A more complex project seems to spike more often (+- once every 5-10 seconds).

@Zylann seems to be on the right track with the opengl SwapBuffers call, but I also don't have opengl expertise to look into the issue further. Has anyone found a temporary workaround to deal with this for now?

[Calinou]

@ibe-denaux Could you test with https://github.com/godotengine/godot/pull/48390 to see if that PR improves the situation? You could also test with https://github.com/godotengine/godot/pull/48555 independently.

[ibe-denaux]

I have tested the issue with #48390 and have gotten some interesting results:

godot version 3.4.beta-custom-build

specs windows 10, AMD Ryzen 5 3600, GTX2060 super, 16G DDR4.

Single frame spikes keep persisting even with delta smoothing on, but the visual effect of them is barely noticeable. What I suspect is that what I thought were the effects of the spike, were likely the effects of improper delta's. Both occur roughly at the same time though, as mentioned before.

What I also noticed however, is that the delta smoothing was not at all compatible with the v-sync via compositor pulled in #33414. Aside from clear screen tearing, the stutters were visually more noticeable than without the v-sync via compositor.

The frequency of the spikes has not changed, they still seem to roughly correlate with project complexity.

In any case, very impressed with the performance of the delta smoothing option. The spikes are not solved yet, but I doubt many users would notice them when delta smoothing is used.

Thank you @Calinou for the quick response, and @lawnjelly for the impressive delta smoothing feature.

[lawnjelly]

Thank you @Calinou for the quick response, and @lawnjelly for the impressive delta smoothing feature.

I did write a long post earlier explaining a lot of this, but it is quite difficult to explain. This scene is actually quite helpful in explaining: https://www.youtube.com/watch?v=uAXtO5dMqEI

What you may be seeing as a glitch, is the spoon bending, something you do not expect. But the key thing to realise with timing, is that it is not the spoon that bends, it is yourself. It is your viewpoint that determines how you see the spoon. Delta smoothing acts to correct the errors in your viewpoint, to enable you to see the spoon in a way that matches your expectations.

[ibe-denaux]

After some further testing, I have determined that the majority of the remaining spikes in my particular project are due to multithreading and the thread collection that comes with it. After disabling multithreading for my project, I only see the spikes occur every one to two minutes. I assume the remaining spikes are due to garbage collection or the like.

As far as I'm concerned, the issue is fixed with @lawnjelly's delta-smoothing option.

[L4Vo5]

I was having this exact issue on the latest stable release (3.3.2) and it seems to have "magically" fixed itself upon activating the "Verbose Stdout" option in the project settings. Turning it off makes the issue return. The prints are slightly annoying, but I'll take this 'quick fix' until future versions. I hope it can help someone else too.

[Calinou]

I was having this exact issue on the latest stable release (3.3.2) and it seems to have "magically" fixed itself upon activating the "Verbose Stdout" option in the project settings. Turning it off makes the issue return. The prints are slightly annoying, but I'll take this 'quick fix' until future versions. I hope it can help someone else too.

Which OS and graphics card model do you have?

[L4Vo5]

I was having this exact issue on the latest stable release (3.3.2) and it seems to have "magically" fixed itself upon activating the "Verbose Stdout" option in the project settings. Turning it off makes the issue return. The prints are slightly annoying, but I'll take this 'quick fix' until future versions. I hope it can help someone else too.

Which OS and graphics card model do you have?

OS is Windows 10 Pro, GPU is NVIDIA GeForce GTX 1070 Ti I had tried the "Nvidia Rect Flicker Workaround" and it didn't help. I have it turned off now

[Keelar]

I just tested this and can confirm that enabling verbose stdout seems to entirely fix the stuttering issues for me which have been haunting me for the past 2 years and has basically caused me to stop working on one of my projects. This seems like a very strange issue. Why would verbose stdout reduce stuttering? It makes no sense to me. I really hope whatever is causing this can be tracked down and fixed.

I'm using 3.3.2 Mono stable, GTX 1660 Super and a Ryzen R7 5800X.

[Zireael07]

@Keelar: --verbose has also been known to fix the "one frame behind" visual lag on some Intel cards, and AFAIK no one has any idea why exactly it happens :P

[Keelar]

I've done a bit more testing on this and also tried @lawnjelly's delta smoothing fix which I think did make the spikes a bit less noticeable, but they were definitely still noticeable to me. The spikes usually occur around once every minute or two on average.

I also tested a couple things with the "verbose stdout" fix. The first was a little ironic which is enabling 'verbose stdout' as well as 'disable stdout' still fixes the issue and stops the stuttering. The second is that enabling 'verbose stdout' still fixes the stuttering even after exporting the project without debug, despite the fact that 'verbose stdout' is a debug setting...

[Calinou]

The first was a little ironic which is enabling 'verbose stdout' as well as 'disable stdout' still fixes the issue and stops the stuttering. The second is that enabling 'verbose stdout' still fixes the stuttering even after exporting the project without debug, despite the fact that 'verbose stdout' is a debug setting...

I wonder if this is due to https://github.com/godotengine/godot/issues/47725. However, stdout is never flushed when printing in a build exported in release mode (unless you enable the related project setting).

[lawnjelly]

I've done a bit more testing on this and also tried @lawnjelly's delta smoothing fix which I think did make the spikes a bit less noticeable, but they were definitely still noticeable to me. The spikes usually occur around once every minute or two on average.

The delta smoothing will often help with all kinds of glitches like this, but there's a limit to how much it can compensate for. In this case it does sounds as though we need to fix the logging.

[Javad9s]

I've done a bit more testing on this and also tried @lawnjelly's delta smoothing fix which I think did make the spikes a bit less noticeable, but they were definitely still noticeable to me. The spikes usually occur around once every minute or two on average.

I also tested a couple things with the "verbose stdout" fix. The first was a little ironic which is enabling 'verbose stdout' as well as 'disable stdout' still fixes the issue and stops the stuttering. The second is that enabling 'verbose stdout' still fixes the stuttering even after exporting the project without debug, despite the fact that 'verbose stdout' is a debug setting...

Are these methods effective on other platforms (like android, ios) too?

[svendixon]

Windows 10 Pro AMD Ryzen 9 5950X GeForce GTX 980 Ti

I wish I knew about this "Verbose Stdout" check box in project settings a long time ago. Not only did it get rid of the lag spike you are all talking about, but it fixed several other lag spikes in my game that have been plaguing me for years. So this one check box fixed...

1. The occasional but constant lag spike.
2. A spike with a particle effect in my state machine every time the player enters the jump state (even though I was precompiling shaders).
3. And lag spikes when scene transitioning. An issue I thought might have been related to my save and load code or loading and adding the scene to the tree. But nope...

All these issues were do to whatever Godot is doing under the hood, and checking "Verbose Stdout" magically fixes. The only down side is all the print statements it throws out. So I have to turn it off when debugging then turn it back on if I want smooth gameplay or when I export my game.

[Zireael07]

verbose stdout has also been known to affect one-frame lag on some Intel cards for some arcane reason, just fyi

[lawnjelly]

I noticed a couple of days that even the normal print_line does not print to the console in QT Creator when debugging, which is very frustrating. It turned out it looked like the print_lines were getting posted to another thread to deal with, hence the lack of logging. This thread protection could possibly be responsible for the stalling. If there's a system that has the stalling, someone could try changing the print_line routines to directly just print to standard output on the current thread, and see if that helps.

[Calinou]

All these issues were do to whatever Godot is doing under the hood, and checking "Verbose Stdout" magically fixes. The only down side is all the print statements it throws out. So I have to turn it off when debugging then turn it back on if I want smooth gameplay or when I export my game.

To avoid having to flip the project setting manually, you can enable the Verbose Stdout project setting only when the standalone feature tag matches.

[Keelar]

I noticed a couple of days that even the normal print_line does not print to the console in QT Creator when debugging, which is very frustrating. It turned out it looked like the print_lines were getting posted to another thread to deal with, hence the lack of logging. This thread protection could possibly be responsible for the stalling. If there's a system that has the stalling, someone could try changing the print_line routines to directly just print to standard output on the current thread, and see if that helps.

If that were the case wouldn't disabling stdout in project settings also fix it? Since print_line returns immediately if _print_line_enabled is false? I modified print_line to do nothing when called and the problem persists unless verbose_stdout is enabled.

I have next to no experience with C++ or with any low level languages for that matter, so maybe it's a bit more complicated and I just don't have the experience to see it. Are there multiple print_line implementations and I just messed with the wrong one? I was modifying the one in print_string.cpp.