Resolved Frames dropping regularly in profiler

Hi,

I've noticed weird spikes in the profiler for my project and I couldn't find an explanation online, and haven't been able to figure it out on my own using the profiler/memory profiler.

• The functions that hang in the main thread generally seem random, it's rarely ever the same (e.g. sometimes it's URP rendering functions, sometimes it's the behavior tree package I'm using, etc.)
• The memory usage rises progressively leading up to those spikes, and on the problematic frames themselves the memory overview indicates that there's no data for that frame.
• I can't seem to find anything that looks wrong with the other threads, they mostly seem to be waiting as well while that spike/dropped frame happens.
• I'm using a multi-step setup in my URP pipeline, to render outlines and such in multiple passes, but the memory profiler didn't seem to indicate any leak in that (I can see all the render textures in memory and they don't fluctuate much.) This is still what I suspect may be causing the issue, as I'm a noob with URP and may have messed up something.
• This is not linked to GC, I actually discovered those issues while profiling to remove GC Allocations and most frames currently don't allocate any GC. Instead, it's randomly attributed to the scripts or rendering, but that seems to just be based on which function was the one that was pending when the issue happened.

I wanted to ask, because my googling didn't yield anything, if anyone has ever seen this situation and how they have approached identifying the issue. My next step is finding a platform-specific memory inspector as the Unity one couldn't show me what the Unknown memory allocations were, but I can't help but feel like I might be missing something obvious, or that maybe it's just a side effect of profiling with 600 frames buffer, etc.

Note: those profiles were taken by connecting the profiler to a build of the game, not within the editor. I'm on Unity 2022.2.11f, on Windows 10.

Example frame dropped that has no memory data:


Example frame timeline, but that changes for every spike:


Memory evolution over time:


Thank you!

 

I would say it's absolutely related to GC! If memory usage drops after each of these spikes, then it's very likely that the hitch is due to the garbage collector running.

I'm guessing the garbage collector is getting triggered once there's enough junk in the heap.

This does seem pretty extreme, though...

 

The thing that makes me assume it's not is that I was debugging GC specifically over the last few days to get it down to 0 GC.Alloc and those GC calls are gone now (if I hide all other types of CPU Usage I don't see any jumps caused by GC). I essentially had lots of spikes before, because I was accidentally doing a lot of GC Allocs each frame. Then I cleaned that up and am now not seeing any GC.Alloc by default in frames, but those weird spikes are left and I'm struggling to explain them.

But I'm still new to profiling in Unity so I may be getting something off here, thanks for the input.

 

I found this in the build's latest log:

Will attempt to determine if it is indeed caused by the profiler settings. It would at least make sense regarding the frames that have no memory data at all, if that's caused by the profiler restarting.

EDIT: Using -profiler-maxusedmemory ### on the build controls how often the profiler runs out of memory and restarts (the time between each spike), but it seems like it'll always run out of memory at some point. I wonder if it's something to do with my project, or my hardware.

 

Seems like turning off Deep Profiling in the profiler actually gets rid of the issue. I don't know why, I would have thought that whether it's deep or not, the limited frames count would ensure there's a cap on the memory needed to store the frames, but it seems like if I have Deep Profiling on, eventually the profiler has to stop/restart. If I don't, either it will take a very long time to do so, or it doesn't happen at all (I waited a few minutes and didn't see any spikes).

The documentation does say that Deep Profiling is very expensive/memory-consuming, I just didn't realize it would be the cause of this behavior.

 

Hi!
The issue is related to the profiler data serialization bandwidth - we are able to process around 100MB/s and if game generates more we stop to not run out of memory.

Profiler is instrumentation based, so that every sample you see if written to the data. When there are too many samples in the stream we can't process data fast enough and stop profiler once the write buffer is full. Profiler.maxUsedMemory can increase the buffer and increase capture intervals.

Deep profiler is a mode where we auto instrument every single C# method from all assemblies. And it generates significantly more data points (plus skews the timings due to some methods may cost less than taking timestamp for them). It is very likely to not being able to process those with sufficient pace.
With more C# code we need to review its usability/granularity

 

Thanks for the explanations!

So, to repeat back to you to see if I understand it, the problem is that the buffer fills up over time because my hardware cannot process what's getting queued in the buffer fast enough to reach an equilibrium, so increasing the size of the buffer just gives it more runway before it eventually reaches the buffer's limit size and has to stop.

Out of curiosity, is it safe to assume that the bottleneck would be tied to my hard-drive's speed? I admit I'm a bit clueless about where the data that's pushed to the write buffer is supposed to end up once processed.

 

No, this is CPU/algorithm bottleneck

I can illustrate the how profiler writes data as

Each thread produces events which are then put to the queue and streamed to 1) memory file (Editor), 2) PlayerConnection (remote player), 3) file on disk (Profiler.logFile api).
Editor consumes data realtime in cases 1) and 2) . The speed of that consumption is the key factor of the bottleneck - if Editor can't consume and process data faster than it is being produced we have a stall.

In the 1) case the bottleneck is tied to: how quickly we convert events into the profiler ui representation - this is CPU speed and # of cores (and ofc our code)
In the 2) case it is bounded primarily by socket speed (and also by 1)
In the 3) case it is bounded by hard-drive speed (and 1)

Hope that clarifies the details

 

Oooh, that makes a lot more sense! Thank you for the explanation.

So would it be correct to say that this has nothing to do with GC?

 

Thanks a lot Alexey for taking the time to explain all that!

 

I must say, this behavior can be very confusing to folks encountering it for the first time. I was doing some stress tests, and somehow the Painter2D APIs triggered this Profiler oddity for me. And I ended up making a thread about it under UI Toolkit's forum. https://forum.unity.com/threads/why-does-painter2d-stroke-generate-huge-lag-spikes.1543967/

Took me a couple days to realize what was really going on. And I don't remember seeing this behavior in earlier verions of Unity. ¯\_(ツ)_/¯