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 #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 #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 #35996, you could try to measure how long this line takes to execute:

godot/platform/windows/context_gl_windows.cpp

Line 86 in 00949f0

SwapBuffers(hDC);

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 #33969 (comment) ?

[muno777]

@Zylann yep, remote scene tree is disabled:

[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 #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.

[Keelar]

I've spent the past few hours trying to further track down where the issue is. I started by searching for all code that executes as a result of OS::get_singleton()->is_stdout_verbose() being true and taking some educated guesses and forcing/preventing code from running until the lag spikes start/stop. Doing that for a little while led me to this code:

godot/drivers/gles3/rasterizer_gles3.cpp

Lines 163 to 171 in 7610409

	if (OS::get_singleton()->is_stdout_verbose()) {
	if (GLAD_GL_ARB_debug_output) {
	glEnable(_EXT_DEBUG_OUTPUT_SYNCHRONOUS_ARB);
	glDebugMessageCallbackARB(_gl_debug_print, NULL);
	glEnable(_EXT_DEBUG_OUTPUT);
	} else {
	print_line("OpenGL debugging not supported!");
	}
	}

If I run with verbose stdout enabled and prevent that code from running by changing the if condition to OS::get_singleton()->is_stdout_verbose() && false, verbose stdout no longer prevents the lag spikes. If I disable verbose stdout and force that code to run by changing the if condition to OS::get_singleton()->is_stdout_verbose() || true, the lag spikes stop again. I've put at least 2 hours into testing this and forcing that code to run has consistently resulted in no lag spikes, while preventing it from running consistently has. I have absolutely no clue why forcing debug code to run would result in better performance, but it seems to be the case.

Around a year ago I checked to see if the lag spikes were present on the GLES2 renderer as well and they were and I just checked and rasterizer_gles2.cpp appears to have a similar bit of code:

godot/drivers/gles2/rasterizer_gles2.cpp

Lines 221 to 229 in 7610409

	if (OS::get_singleton()->is_stdout_verbose()) {
	if (GLAD_GL_ARB_debug_output) {
	glEnable(_EXT_DEBUG_OUTPUT_SYNCHRONOUS_ARB);
	glDebugMessageCallbackARB(_gl_debug_print, NULL);
	glEnable(_EXT_DEBUG_OUTPUT);
	} else {
	print_line("OpenGL debugging not supported!");
	}
	}

While I haven't yet tested if forcing/preventing this code from running has the same effect on GLES2, I presume it would, but don't know for sure.

So it seems to be related to OpenGL, which I am clueless about so I don't think there is much more I can help with at this point. Just hoping this info will be helpful to someone more knowledgeable.

[lawnjelly]

That's very useful info and you could be well right about the OpenGL debugging. 👍 I don't get this on my Linux machine (hence difficult to investigate), and the other reports seem to be about windows, so there is also a possibility it could be windows specific.

There is a _WGL_CONTEXT_DEBUG_BIT_ARB in context_gl_windows.cpp but as far as I can see it is switched off. We can have a look through and see if there's anything we can spot.

One possibility is that there is a load of OpenGL error spam which is getting hidden, and that is causing problems, possibly related to #7171 and the linked PR. I'm not sure I can really investigate effectively this as it needs someone running windows I think, possibly someone who also gets the spikes.

[joemicmc]

I've seen the same issue on my setup

• Godot 4.0 alpha 14
• Windows 10 x64
• AMD Ryzen 5 3600
• AMD Radeon RX 5600 XT
• Vulkan Rendering

Every 10 seconds or so I was seeing 'Process Time' take double the amount of time on a frame.

• Frame 11646 looks normal and 'Process Time' is 16.1 ms
• Frame 11647 is 29.5 ms
• Frame 11648 is 3.51 ms
• Frame 11649 is 16.8 ms
• Frames afterwards are ~16 ms

This was happening in a new project with empty scene. Enabling verbose stdout, whilst not completely eliminating the issue has definitely reduced the issue, and it could be that the few spikes I'm seeing are unrelated.

I haven't build Godot from source for a while, but happy to test out any changesets if needed.

[lawnjelly]

I've seen the same issue on my setup

• Godot 4.0 alpha 14

This probably needs a separate issue for Godot 4, especially for Vulkan. This issue seems to have been narrowed down to something to do with OpenGL debugging. Obviously OpenGL debugging doesn't happen in Vulkan.

Incidentally, not having looked at this for some time, I had a little look and the debugging section is followed by a whole load of:

		glDebugMessageControlARB(GL_DEBUG_SOURCE_API_ARB,GL_DEBUG_TYPE_ERROR_ARB,GL_DEBUG_SEVERITY_HIGH_ARB,0,NULL,GL_TRUE);
		glDebugMessageControlARB(GL_DEBUG_SOURCE_API_ARB,GL_DEBUG_TYPE_DEPRECATED_BEHAVIOR_ARB,GL_DEBUG_SEVERITY_HIGH_ARB,0,NULL,GL_TRUE);
		glDebugMessageControlARB(GL_DEBUG_SOURCE_API_ARB,GL_DEBUG_TYPE_UNDEFINED_BEHAVIOR_ARB,GL_DEBUG_SEVERITY_HIGH_ARB,0,NULL,GL_TRUE);
		glDebugMessageControlARB(GL_DEBUG_SOURCE_API_ARB,GL_DEBUG_TYPE_PORTABILITY_ARB,GL_DEBUG_SEVERITY_HIGH_ARB,0,NULL,GL_TRUE);
		glDebugMessageControlARB(GL_DEBUG_SOURCE_API_ARB,GL_DEBUG_TYPE_PERFORMANCE_ARB,GL_DEBUG_SEVERITY_HIGH_ARB,0,NULL,GL_TRUE);
		glDebugMessageControlARB(GL_DEBUG_SOURCE_API_ARB,GL_DEBUG_TYPE_OTHER_ARB,GL_DEBUG_SEVERITY_HIGH_ARB,0,NULL,GL_TRUE);

What could be happening is that on some drivers this output is defaulting to true (maybe something is overriding the debug settings, in the driver settings perhaps?). This suggests that it could possibly be solved by explicitly setting all this output to FALSE when not in verbose mode.

In addition, it looks like we don't set WGL_CONTEXT_DEBUG_BIT_ARB on windows, so in theory this stuff shouldn't be outputting, but hey ho.

An alternative is to set the callback even in non-verbose mode, then totally ignore any debug output.

Again, this probably needs someone who uses windows and has this problem to investigate, but these are some ideas.

https://sites.google.com/site/opengltutorialsbyaks/introduction-to-opengl-4-1---tutorial-05

[EIREXE]

I asked around and apparently enabling _EXT_DEBUG_OUTPUT_SYNCHRONOUS_ARB disables threaded optimization, which AFAIK is only enabled by default on windows, hence why we are seeing the issue only there

[lawnjelly]

I asked around and apparently enabling _EXT_DEBUG_OUTPUT_SYNCHRONOUS_ARB disables threaded optimization, which AFAIK is only enabled by default on windows, hence why we are seeing the issue only there

That could well be it 👍 , a google search reveals a lot of people having issues with stuttering and this threaded optimization driver setting. As such I don't know if there's anything we can do about it our side, aside from mention it as a solution (or force debug output lol) 😁 .

https://en.sfml-dev.org/forums/index.php?topic=23506.0
https://stackoverflow.com/questions/36959508/nvidia-graphics-driver-causing-noticeable-frame-stuttering/37632948#37632948

It may be something we do for error checking (glGetError?) that is causing a stall with this driver setting, as some of the people report the problem disappearing in release builds of their game.

[EIREXE]

I asked around and this is what I got:

Does it disappear on release builds? I know that for nvidia we can make a profile and force threaded optimization off, as its done here: https://stackoverflow.com/questions/36959508/nvidia-graphics-driver-causing-noticeable-frame-stuttering/37632948#37632948

Someone should attach a debugger like nvidia nsight to the engine to see where the stalls are, i'll do it myself if I have time later.

Not sure if this option can be disabled on intel, does anyone know?

[EIREXE]

Can someone confirm if this is happening in 4.0 with opengl? I might just add some code at initialization to disable threaded optimization, since it seems like a better way to go