Profiler missing most of my functions.

[Zoomulator]

Godot version:
3.2.2

OS/device including version:
Windows 10
Version 1903
Build 18362.900

Issue description:
The profiler fails to detect a large portion of my functions and shows a suspiciously low Script Function time.
Using Measure: Frame Time (sec) and Time: Inclusive.

Here's a screenshot of the profiler on one of the spikes I'm investigating:

It states that the frame takes 34ms in Idle time, but the Script Function total is only 0.19ms!

Further more, the time for Script Function seemingly drops when the load spike occurs. (Pink: Idle, Yellow: Script)

The spike occurs at the start of a turn in my game. It's spread out since each enemy character's turn takes at least one frame, ends its turn and then moves on to next until its the players turn. All of this is triggered by signals and some use of yield(get_tree(), "idle_frame")

I've checked and doubled checked, by using OS.get_ticks_usec() and Engine.get_idle_frames(), that one of the missing functions actually runs during these frames and is a time hog, but it won't show up in the profiler (and I double checked the neighboring frames too)!

In fact most of the functions that I'd expect to show in the profiler for that frame are missing.

I managed to optimize the function, so I'm convinced its my own code and not any server or file loading that occurs during these frames.

I've tried twiddling the Max Functions setting, but no change. Made a grep for func definitions and only got ~750, so it seems hardly an issue with the default setting of 16k, but I've tried 32k and 64k to make sure.

The drop in Script Function time as the load increases suggests to me that there's some silent overflow besides the Max Function setting.

Steps to reproduce:
Unfortunately I've failed to pinpoint what causes it. Hope this report is informative enough anyway! I'll make another attempt at reproducing it at a small scale.

Minimal reproduction project:

[pouleyKetchoupp]

Do you have a minimal reproduction project you could provide us? It would help pinpoint the part of your scripts that cause the spikes and then figure out if that could be added to the profiling data.

[Calinou]

Related to #23715 (but not identical, according to your description).

[pouleyKetchoupp]

@Calinou Yes it's the same problem but in a different area it seems. I don't know if it's already part of the plan for profiling improvements, but both cases show we need to start adding more details into profiling information (and I'm sure there's more).

We could have some extra sub-categories to get more details about the main loop, physics and possibly rendering (if some areas can be clearly identified).

Maybe that could be just for debug, or disabled in release by default and based on some project settings.

[Ariorick]

I have this issue that though idle time might be over 100 millis, script functions are only shown close to 5-10ms. What's interesting is that when i comment some of my code, lowering frame time for about two times, the rest of script functions start to show up in profiler. This thing really messed up my profiling...
Im using latest 3.2.3 stable godot.
ALSO PLEASE ADD AVERAGE TIME OVER MORE THAN ONE FRAME

[Calinou]

ALSO PLEASE ADD AVERAGE TIME OVER MORE THAN ONE FRAME

Please open a proposal for that 🙂

[lekoder]

@Zoomulator I had a similar issue - then I noticed that there is an option in editor "Profiler Frame Max Functions" that's defaulting to 64 - and I had 2000-5000 calls per frame. See if raising that helps your case.

[Calinou]

Are there any negative side effects to increasing this value? Maybe we should increase its default value.

[lekoder]

I personally never saw a side effect, but I imagine it can allow the editor to allocate much more memory and will probably introduce higher load when profiling - but then when I'm profiling I'm expecting to have bad performance. I would assume value like 8192 would be enough for my use-case; I'd personally opt for unlimited - because there is absolutely no use-case I can see myself doing that would benefit from hiding some function calls from me. But the easy way is to increase that by default.

[Zoomulator]

@lekoder I actually mentioned trying to increase that value in the bug report. It made no difference in my case.

[lekoder]

Oh, sorry, I searched through for the full name.

[Calinou]

I just noticed Profiler Frame Max Functions is silently clamped between 16 and 512 in master:

godot/editor/debugger/script_editor_debugger.cpp

Lines 940 to 943 in c9bd11a

	Array opts;
	int max_funcs = EditorSettings::get_singleton()->get("debugger/profiler_frame_max_functions");
	opts.push_back(CLAMP(max_funcs, 16, 512));
	data.push_back(opts);

This is also the case in the 3.2 branch:

godot/editor/script_editor_debugger.cpp

Lines 1676 to 1680 in 3a8e1f3

	Array msg;
	msg.push_back("start_profiling");
	int max_funcs = EditorSettings::get_singleton()->get("debugger/profiler_frame_max_functions");
	max_funcs = CLAMP(max_funcs, 16, 512);
	msg.push_back(max_funcs);

[Faless]

I just noticed Profiler Frame Max Functions is silently clamped between 16 and 512

Oh, that's great... I probably just copy pasted it in 4.0.
I think we can safely remove the clamp in 4.0 (or raise the maximum to something more reasonable like 32768), not sure in 3.2 since the network layer there is pretty messy, and if the data is too big it might hang or even crash the editor (like for prints, etc).

[Calinou]

@Faless What do you think would be a good default value for master and 3.2 respectively?

[Faless]

In current master, there will be one message for each function at first to assign ID-names association, so size is number * (avg_name_size + 4 + 8) (4 bytes is the ID, 8 bytes the variant encoding), then only new functions will be sent.
On every frame, a single message will be sent, containing all functions info, where each function will take ~32 bytes.

Considering that we have a 8 MiB buffer, I think for master 4096 could be reasonable, maybe even 8192 (I fear too much might be confusing for the user, but again, we should easily go above those values when it comes to the network layer).

In 3.2, I honestly don't know. That debugger code gives me headache, we probably need to look at empirical data.

[Zoomulator]

@lekoder Oh I'm mistaken, I though you meant debug/settings/profiler/max_functions but you pointed at debugger/profiler_frame_max_functions. Sorry about missing that!

Setting debugger/profiler_frame_max_functions to 512 made a significant improvement, but still not all the way there. I'd really need a higher upper limit.

[lekoder]

@Zoomulator this is not an upper limit, but merely a default. As you can see from screenshot I have absurdly high value there, on grounds that I'd actually prefer the engine to work sluggish or crash with out-of-memory error when profiling to missing a function in profiler output.

[Zoomulator]

@lekoder I'm referring to what @Calinou just said, that it's being silently clamped to the range [16, 512]. Or am I missing something? I saw no improvement from setting it higher than 512.

[lekoder]

Oh, I missed that, sorry. Luckily I'm running a custom-built editor, so I can just raise that myself.

[lekoder]

I raised the limit to 8192 in my build and only problem I spotted is some kind of artifact when you stop the profiling process:

during normal execution profiler behaves as expected:

[SaffronStreams]

If I understand correctly that the script functions should more or less equal idle time then I'm suffering from the same problem. I have a high idle time (making me noticeably drop to 30 fps), but my script functions time is very low.

(I upped the max frame functions in profiler to 2500 (before reading 512 was the limit currently))

[Calinou]

If I understand correctly that the script functions should more or less equal idle time then I'm suffering from the same problem. I have a high idle time (making me noticeably drop to 30 fps), but my script functions time is very low.

This isn't the case as servers (physics, rendering, …) don't count as script functions: #23715

[SaffronStreams]

Worded differently, I ran into a problem making it difficult to see where I lost time and wondered if a new ticket was needed. So it's not this ticket but there was already a relevant created then. Sadly, neither have a milestone planned yet.

I'll have to try and track it differently. I use really big textures (3000*3000) for my Polygon2D's that a lot of the time I zoom out to (giving a scale of 0.1). I'm thinking this might be problematic (despite earlier tests not giving problems, far as I could tell).