Time spent waiting for servers not included in functions profiler (e.g. physics)

[lekoder]

Godot version: 3.1 alpha c025f526c

OS/device including version: Windows 10

Issue description: When script call spends bulk of the time waiting for a game server, it is not included in the profiler. This makes finding function/nodes that abuse servers difficult to pinpoint and fix.

Specific use case: One of components of the game was doing excessive raycasts queries that could bump up the "Idle time" up to >0.1s, dropping FPS down to 10. This was in no way visible it the profiler. Had to resort to bisecting the nodes with inspector to find the problem.

Steps to reproduce: Write a gdscript that interacts a lot with one of game servers (ie. raycasts with direct_space_state). Run and observe that time spent on raycasts is not included in the profiler output for scripts.

Misc: I would suggest renaming Idle time to Waiting time in debugger. This is how profilers usually show time spent on waiting for other subsystems.

[zhengying]

I have a similar problem， In my case I don't known what make my game fps dropped to 2. In profiler: Frame Time 100% but physics time 12.9% idle Time 0.6% script function less then 2%, but what else is ? 100% - 12.9% - 0.6% - 0.2%?

I want to known what is not traced in profiler? who can help clarify this for me？

(I used godot 3.1 )

[and3rson]

Same here. It makes using profiler really tricky and ambiguous :/

[and3rson]

I feel like this should be prioritized - this problem currently renders the profiler really useless because there's no way of knowing what actually causes the increase in processing time. :(

Sorry for excessive bumping. We're currently building a very complex game in Godot and it's really hard to debug performance-related things without the percentages summing up to 100%...

[thetoblin]

I'm running a rather unusual code where I'm simulating biological cells that divide, bump into each other in physics, and communicate with each other. Long story short: it gets quite heavy to run at around 1k-2k instances.

To optimize the code I've been using the profiler. My code eventually gets really high FPS: the frame time given by the profiler has been as high as 31.1 sec per frame. To my surprise however I noticed a discrepancy between the reported Frame time, and the time for the function calls. When I counted the time that is listed in the sub-calls I got it to be 12.7 sec per frame when the Frame time was 31.1 sec. Hence it was missing around 18.4 seconds PER FRAME, which is a LOT (more than 50%!).

I understand that the root cause is unknown, and I don't think I can contribute to that. But I hope that my info can at least provide some munitions for prioritizing the issue.

[Calinou]

I would suggest renaming Idle time to Waiting time in debugger. This is how profilers usually show time spent on waiting for other subsystems.

I'm not 100% sure about this, as "idle time" is a relatively frequent term used throughout Godot. For instance, in the AnimationPlayer playback options:

[RPicster]

I know that bumping issues is not well received but this is a massive problem which makes it almost impossible to optimize a big project.

[mrimvo]

I'm not 100% sure about this, as "idle time" is a relatively frequent term used throughout Godot. For instance, in the AnimationPlayer playback options:

And I think you are right. From what I understand, Idle time refers everything not spent on physics. That is, for example, everything that happens in _process().

I think an idle frame is the counter part to a physics frame. Eg, when you do yield(get_tree(), "idle_frame") the script waits for the next frame.

[and3rson]

Is 3.x profiler going to get some love with this issue? I understand there's a lot of hype for 4.x and I'm really excited about it, but it will take a while until it's production-ready, which means one should either wait until 4.x is ready or proceed with 3.x (we chose the latter.) However, using the profiler in 3.x is a frustrating experience. I've been with Godot for over 4 years and always spent way too much time fighting with the engine because it failed to tell me which specific subsystem was wasting most of my frame quota. I'm in the same situation as many times before - "Process time" is abnormally high but all other metrics are very low.

If Godot could at least tell me what exactly took it so long, it would greatly help me to narrow down the root cause and fix those annoying jitters.

Update: some things are also not being accounted for in "Script Functions":

[Calinou]

Is 3.x profiler going to get some love with this issue?

Probably not, unless a motivated contributor is interested in improving it. Most feature work is going towards 4.0 nowadays.

Update: some things are also not being accounted for in "Script Functions":

Try increasing the Profiler Frame Max Functions editor setting, then the Debug > Settings > Profiler > Max Functions in the project settings.

[lekoder]

TBH I'm bit torn on this.

On the one hand, it's great to see that the engine development is going forward so rapidly. On the other hand, I begun work on my game when 3.x was still in alpha stage, compiling the engine from sources; I went through to Early Access and I am still not released and sometimes it feels like the 3.x is already abandoned before I could do a full release.

I'm not sure if I'm working extraordinarily slowly on the game or if the engine progresses that rapidly, but in all honesty I feel like I'm being abandoned; "we moved on to make cool features for 4.x and if you committed to base your business on 3.x, well, sucks to be you".

[akien-mga]

@lekoder I agree with you and @and3rson that this issue is an important one to solve as it's needed to be able to properly profile and optimize code used in production, and that of course includes the 3.x branch. AFAIK it's not particularly better in 4.0 yet so it's not just a matter of priorities for 3.x vs 4.0, it's just a matter of priorities among all features and bugs, and contributors' time, knowledge and interests. Maybe @lawnjelly would be intereted in this one.

---

That being said I don't think you're being fair with the above rant. The following major feature releases for the 3.x branch happened in parallel to Godot 4.0 development:

• 3.2.2 - despite the "maintenance release" name, this was actually a fairly big feature release - which eventually led us to reconsider our versioning and reopen active development of 3.x minor releases with a 3.x branch.
• 3.3
• 3.4
• 3.5 - barely a month ago!

I don't think you can read these release notes for 4 significant updates to the 3.x branch, and say fairly that we've abandoned users of the 3.x branch. It's unfortunate if you didn't notice any difference and didn't get any benefit for your Early Access game from releases between 3.2 and 3.5, but it's not fair to say we've abandoned you.

[lekoder]

@akien-mga yes, you are right - I'm sorry, emotions got out of hand, and I should really know better than post like that. There are releases and they improve stuff - just not some of the bugs that really annoy me day-to-day, that's probably why I feel bitter. But you are completely right, I can't deny the progress made.

[lawnjelly]

Yes as @akien-mga says, there is still plenty of development going on with 3.x. The official advise for contributors is to aim for 4.x, which is why most PRs / features are being made for 4.x and filtering down to 3.x where possible.

Some naughty contributors have totally ignored this advise and spend most of their time on 3.x, which has received a tonne of new features (e.g. web builds, android editor, batching, portals, occluders, mesh merging, navigation, debugging features, core improvements), and optimizations and bug fixes. It will also get support long after most users have migrated to 4.0.

For profiling, the in built profiler works well for gdscript, but for serious stuff you will want to break out the big guns, there is a section in the docs on profiling and external profilers: https://docs.godotengine.org/en/stable/tutorials/performance/cpu_optimization.html#cpu-profilers

I can have a look at improving the built in profiler if there is any low hanging fruit there. Also feel free to contact myself or the team for bespoke performance advise (I often do this for game developers who are working on larger games, it's fun and it often doesn't take a long time).

Also consider that in many cases games are bottlenecked by the GPU rather than CPU, in which case the godot profiler (which is for CPU only) will tell you little. One indicator is a large difference between the overall frame time and the total of the subareas measured below.

You can test fill rate bottleneck (which is GPU) by changing the window size to 100x100 pixels, and use very small shadow maps, and see if the frame rate goes up. You could alternatively be bottlenecked by e.g. vertex throughput, upload to the GPU, or drawcall / state changes.

This is described in: https://docs.godotengine.org/en/stable/tutorials/performance/gpu_optimization.html

Also, don't forget viewports, if you are using these it can also have huge effects on performance, especially if these are high resolution, or are rendering their own shadow maps.

[reach-satori]

So I've been digging into this, and this is what it looks like:

The problem happens when profiler frames are created and the self-time calculated inside GDScriptFunction::call, in gdscript_vm.cpp. Issue is, when there's a call to one of the affected server functions, the time spent inside them is subtracted from self-time, even though they have no mechanism to create profiler frames of their own. The profiler's view of the stack gets cut off there. So rather than a 'bug', it's more like there's no profiler implemented for those functions at all. So far as I can tell, only the GDScriptFunction class has the Profile struct and records all that.

Good news is this means there's a possible partial fix. Just by removing the self-time subtraction from those specific functions that don't interact with the profiler, you'd stop the time from vanishing into nothing, and the profiler at least tells you which of the user's gdscript functions is the one at the root of any performance problems. I managed to get a trivial version of this fix working for one server function call.

But I haven't figured out how exactly to tell GDScriptFunctions that profile from native c++ functions that don't. I looked around and couldn't find any documentation about the gdscript vm and all its OPCODEs or the parser, and they're quite intimidating and complex with all the macros and reflection. Is there any? A high-level explanation will do.