Help me understand these profiler results

I'm trying to optimize an Android (Oculus Go) app, but I don't fully understand what the profiler is telling me.

While looking at a fairly busy part of the scene, it seems that I usually get frames in 16 ms, but occasionally there is a 1-frame doubling of that. I assume these are missed frames, where something just couldn't complete before the vsync, so it had to wait for the next one. I need to eliminate those skips, but I'm still not sure exactly what's causing them.

Here's the frame before the spike:


Here's the frame of the spike, with what appears to be a whole lot of not much going on:



And here's the frame after the spike:


So I guess the problem is the Render thread, which isn't starting until 8.5 ms in, and I guess not finishing in time for the frame. But when you look at the graph at the top, the Rendering time plus everything else (except vsync) is always well below 16 ms. And when I compare the pre-hitch frame to any other frame in the middle where it's getting a solid 60 fps, I don't see any significant difference — the green bars in the render thread always start around 8-10 ms in, and last for 8 or 9 msec, except for Gfx.ProcessCommands. That one normally takes between 16 and 17 ms, but on the pre-skip frames it takes 32 ms and change. I don't know whether that's cause or effect, though.

Do you people who understand these profiler results see any smoking gun here? What should I focus on to prevent these missed frames?

 

WaitForPresent/WaitForGPU and similar usually means the CPU is waiting for the GPU to finish, so probably your previous frame submitted too much geometry or geometry with complex shaders that couldn't complete before the next frame wanted to start submitting geometry to the GPU. So the CPU has to wait for the GPU to finish.

It could also mean that your CPU took more than 16ms and you're vsync locked. In this case, WaitForPresent is waiting for the next vsync and the GPU might not be doing a lot. That might be your problem - the frame right before the hitch looks like it took 17.75ms. When it's running at 60fps what is the average frame time? I would also check the breakdown of CPU usage in the hierarchy view on that previous frame.

There are some tools listed here along with some suggestions. I don't know if the Remote Monitor can be used but it looks pretty handy. It looks like you can't do GPU profiling in Unity on Android sadly. Here's a blog post also that has some suggestions.

Sam

 

Right, I gathered that the frame took slightly longer than 16.66 ms; what I don't get is how to see exactly how much time it's taking. I have the ability to turn large parts of the environment on or off, and I thought I'd be able to see that feature A takes x milliseconds, feature B adds y more milliseconds, etc. But I'm not seeing that at all, though probably I'm just not looking in the right place.

Here's a profile with everything (the whole environment, mostly looking at a blank screen) turned off:

As expected, you can see we're getting a steady 60 FPS, no trouble. Yet the CPU time for the above randomly-selected frame is still 16.78 ms, GPU 0.0 ms, just like in the spiking case in my first message.

As I turn one one or two big parts of the environment, nothing much changes... here are thumbnails, but click for the full images:

Well, I guess one thing that changes is the green region (rendering, on top of other stuff except vsync) in the top graph grows from about 5 msec to 10 msec or so. But I'm not sure what to make of that, because it's still stays at that same level in the frame-dropping case (with all environment features turned on). Note that the one-feature snapshot shows a frame with CPU listed as 18.42 ms, which is well beyond what we saw in the dropped-frame case, yet no frames here were dropped.

Finally, this thumbnail shows the full-environment case, selecting a frame well between the spikes:

...and right before a spike, as in my original post:


And even looking at the Camera.Render bar near the bottom, it jumps from 1.86 ms (no features) to 7.86 ms (one feature), but then pretty much holds there — 8.6 ms with two features (fine) and 7.28 ms with three features (frames dropping). What's the important difference between two and three, that makes us suddenly start dropping frames?

So that's my question. Looking at all these bars, where can I see something increasing as I add more complex stuff to the environment? Right now all I know is that with one or two features I'm OK, but with all three features I start dropping frames. But somewhere in this data there ought to be what I need to say, feature A costs this, feature B costs that, etc. Right?

 

I have been having the same issue on the GO and GO only. I'm actually getting better perf on the GearVR S7 than on the GO. Unity 2018.3.0 OVR 1.32 / Unity 2018.3.4 OVR 1.34
As of now, the sync issue here is caused by multithreaded rendering, not the GPU itself. See the 2 images attached:

Multithreading Off

Multithreading On


Answer right now: Turn multithreaded rendering off on the GO.

Also, Unity reports way better perf but the Oculus Monitor tools don't match up, which they do with GearVR which is leading me to think there is an issue there as well. Will report back with more info if I get it.

 

Very helpful. Thanks @RMGK

 

You're my hero.