Profiler Deep Profile in build shows bogus data?

The version is 2019.3.f3
I'm deep profiling performance of computationally intensive generation, which suppose to be done on the background. Some of it is done in .net Task, some is done with unity jobs system. When the generation starts, time values of methods, that have absolutely nothing to do with the generation itself scale up.

For example:

Here we have a method, called 27 times, that has nothing to do with the generation, that updates some positions. It costs 0.87ms.


And here we have absolutely the same method with absolutely the same 27 objects costing 40.53ms:



Is there a bug, or am i doing something wrong? Please help! I'm sure i successfully profiled my game with Tasks prior to version 2019.3.f1.



This is how timeline looks.

 

Having issues with deep profiling in 2019.3.f3 as well (worked fine in the past). Fps drops to single digits when enabled. Tested on two phones, and it also happens while running game in editor.

On a empty scene EditorLoop takes up 82ms.

 

Perhaps related to this known issue:
https://issuetracker.unity3d.com/is...-deep-profiling-is-on-with-no-complex-scripts

However, one way to speed it up a little is to close all profiler tabs but the one you actually need. For example, if you only want to profile CPU, just all the other ones like Memory, UI, etc.

 

Closing down profiler modules seems to help a little while running in editor, but not much. Profiling the phone is not possible, it almost stalls.

 

Are you profiling the Player? Is it possible to file a bug with a project? I think slow down happens due to large amount of data generated by deep profiling and the pooling buffer in the player in not large enough to accommodate it. So we spend more time than usually on memory allocations.
There is https://docs.unity3d.com/ScriptReference/Profiling.Profiler-maxUsedMemory.html api/cmdline parameter which might help in this situation if you set it to e.g. 256MB. By default the pooling buffer we use in Players is 4MB.

 

Is this happening when Deep Profiling is enabled in BuildWindow?

 

Yes. "Development build" and "Deep profiling support" enabled.

 

Yes, this is IL2CPP build with Deep Profile turned on.

Sadly, i would not be able to file the project. Yes, the amount of stuff happening there is very big. Thank you, i will try the walkaround and let you know, if it fixes stuff.

 

Thanks!
No worries, if I understand the issue correctly increasing the default buffer size for profiler should fix the slow down. I'll make a fix which increases default max allowed memory for profiler to 128MB in case of deep profiling.

 

@Lynxed one more question - if you disable deep profiling in the player using "Deep Profile" button, do you see better performance?
(I can assume so from the shape of the screenshot you posted, but want to confirm my theory )

 

Hi! Tried this:


But in Deep Profile i still get the same result as before:



To answer your question: no. I measured the same method, which is not involved in generation process with non-Deep Profile (with Profiler.BeginSample-Profiler.EndSample) and here are the results:

Before generation starts:


after generation started:


Although i have only 3 frames, where time is different, i think that is still a strange result.

This method consistently does a number of of Vec3 and Quaterion operations per call, so nothing changes there during generation process.

 

I've tried -profiler-maxusedmemory 268435456 in cmd, but have the same result:

 

Thank you for trying this out! The buffer limit has nothing to do with the slow downs then.

This unfortunately points to the fundamental issue with deep profiling. I suspect there are a lot of calls to those methods.
So my explanation would be that the slow down by design due to the nature of instrumentation profilers like Unity Profiler:
1) Large amount of samples.
2) Fixed cost per sample.
The overhead from deep profiler is also significantly larger compared to the normal profiler beign/end api calls. It is usually 0.1-0.8us, so 10K calls can easily contribute to the 1-8ms perf frame. (Normal profiler begin/end api cost is ~0.01-0.02us).
We have an idea how to decrease a fixed cost for deep profiling to be on pair with simple api, and have a dynamic instrumentation to skip profiling of high frequency loops. But ultimately instrumentation profilers fundamentally do not fit some use cases.

I can suggest to use a sampling profiler to get a performance picture without an invasive instrumentation.
For this particular case I've added an integration with Intel® VTune™ Amplifier of Unity Editor and Player x64 for Windows for 2019.2. There is a small guide available as a doc we are told we can share . We use it mostly internally, but if you find it useful I can add improve it and add to the manual.

 

Did it work better(faster) in the Editor in the previous versions of Unity when profiling Playmode?
Perhaps we got a performance regression in deep profiling our tests didn't surface. I'm asking because we didn't change actually Deep Profiling mechanism itself in 2019.3, and only added support to players.
If so, do you mind filing a bug?

 

Thank you for all the help! This doc is very interesting.

It's not about speed for me, it's about inconsistent evaluation of time for samples and inadequate sorting in Hierarchy.
Sadly, i don't really have time to dig deeper right now, but what i noticed is Timeline chart makes more sense then Hierarchy mode. Can it be about Hierarchy mode making weird sorting and combining of samples?

I would not be able to recompile the project in 2019.2 now, but if i'll have the time (or when the perf will become an unacceptable issue and profiling will be impossible), i'll try to file a bug report.

 

A question: What are the best practices for profiling coroutunes and async methods? I use UniTask library for my stuff, where i can await UniTask.Yield(), which has similar effect to "yield return null" in an IEnumerator. Those things break Profiler.BeginSample(). Should we never have such things between Profiler.BeginSample() - Profiler.EndSample() or is there more convenient way? Oftentimes you would have yield return null in a loop, which you want to profile.

 

I know there's a large overhead while running the deep profiler in editor mode, but I don't remember it being this bad. At the moment my project runs around 10 fps when launched for ~5 seconds before it becomes somewhat responsive again (most likely due to my game populating object pooler).

I just don't remember it being this bad, like ever, but I guess it could be me.