UnityEngine.Profiling.Recorder.elapsedNanoseconds not working as expected

So I'm trying to profile a bit of code that generates meshes. It doesnt run every frame though and it was getting annoying to have to pause execution and click over the frames that spiked the cpu in the profiler window. So I wrote up some custom samplers and used their .GetRecorder().elapsedNanoseconds to try and make a little ui that just shows how long they took the last frame they actually ran. The problem is elapsedNanoseconds is reporting 0 in my code most of (but not all of) the time even when it shouldn't and indeed even when the profiler window shows my custom samplers taking significant time.

Code (CSharp):

1.    
2. private void Awake()
3. {
4. alterSampler = CustomSampler.Create("_ProfAlter");
5. marchCubeSampler = CustomSampler.Create("_ProfMarch Cubes");
6. edgeFlagSampler = CustomSampler.Create("_ProfEdge Flags");
7. voxAspectSampler = CustomSampler.Create("_ProfVox Aspect");
8. triangleConnectionSampler = CustomSampler.Create("_ProfTriangle Connection");
9. }
10. private void OnGUI()
11. {
12. int w = 420;
13. int x = Screen.width - w;
14. int y = Screen.height - 64;
15. int h = 20;
16.  
17. if(alterSampler.GetRecorder().isValid && alterSampler.GetRecorder().elapsedNanoseconds > 0)
18.             prof_strings[0] = alterSampler.name + ": " + (double)alterSampler.GetRecorder().elapsedNanoseconds / 1000000000.0;
19.  
20. //then I repeat for 4 other custom samplers
21.  
22.         for(int iii = 0; iii < prof_strings.Length; iii++)
23.             GUI.TextField(new Rect(x, y - iii * h, w, h), prof_strings[iii]);
24. }

Problem is it just doesnt work.

Even on the frame where this was recorded elapsedNanoseconds for the recorders of 4 of these custom samplers reported 0. The one that did seem to work was the triangle connection recorder so I suspect that it may have something to do with elapsedNanoseconds just not working when they take too long?

I'm using Unity 2019.3.0f6 and I'm not doing anything threaded, everything is in the main thread.

Anyone know what I'm doing wrong, or is there just a better way of doing what I'm trying to do?

 

If your system is running not every frame I would expect it returning 0.

One thing to note is that elapsedNanoseconds returns the accumulated time for the _previous_ frame. Perhaps try to dump numbers to the log to see if they correlate with profiler.
Also make sure you set enabled to true in Awake.

 

Thank you.

Yes, I grab the values of elapsedNanoseconds every frame and just only store it when it's > 0 so I can more easily see the last time the functions ran how long they took since it's a bit awkward to use the built in profiler window to do that.

I was grabbing it in OnGui but I just tried moving the code that checks the values to Update() to see if maybe it was something odd about how OnGui is called but the same behaviour continues.

I wasn't setting the recorders to enabled but I just tried and it didnt seem to change anything, indeed they all appear to be enabled at creation.

Code (CSharp):

1.     private void Awake()
2.     {
3.  
4.         alterSampler = CustomSampler.Create("_ProfAlter");
5.         marchCubeSampler = CustomSampler.Create("_ProfMarch Cubes");
6.         edgeFlagSampler = CustomSampler.Create("_ProfEdge Flags");
7.         voxAspectSampler = CustomSampler.Create("_ProfVox Aspect");
8.         triangleConnectionSampler = CustomSampler.Create("_ProfTriangle Connection");
9.  
10.         Debug.Log(alterSampler.isValid);
11.         Debug.Log(alterSampler.GetRecorder().isValid);
12.         Debug.Log(alterSampler.GetRecorder().enabled);
13.        
14.         Debug.Log(marchCubeSampler.isValid);
15.         Debug.Log(marchCubeSampler.GetRecorder().isValid);
16.         Debug.Log(marchCubeSampler.GetRecorder().enabled);
17.  
18.         Debug.Log(edgeFlagSampler.isValid);
19.         Debug.Log(edgeFlagSampler.GetRecorder().isValid);
20.         Debug.Log(edgeFlagSampler.GetRecorder().enabled);
21.  
22.         Debug.Log(voxAspectSampler.isValid);
23.         Debug.Log(voxAspectSampler.GetRecorder().isValid);
24.         Debug.Log(voxAspectSampler.GetRecorder().enabled);
25.  
26.         Debug.Log(triangleConnectionSampler.isValid);
27.         Debug.Log(triangleConnectionSampler.GetRecorder().isValid);
28.         Debug.Log(triangleConnectionSampler.GetRecorder().enabled);
29.        
30.         alterSampler.GetRecorder().enabled = true;
31.         marchCubeSampler.GetRecorder().enabled = true;
32.         edgeFlagSampler.GetRecorder().enabled = true;
33.         voxAspectSampler.GetRecorder().enabled = true;
34.         triangleConnectionSampler.GetRecorder().enabled = true;
35.  
36.     }

All of the Debug.Log calls display true.

This problem only seems to occur when the frame I'm trying to profile takes more than a second or so. Any time I'm building a really small mesh, that takes just a few dozen or hundred ms, my code operates as expected and elapsedNanoseconds gives me the correct time.

But whenever the mesh takes longer than a second to build there's a chance one or more, seemingly at random, of the samplers tells me the elapsed time was 0 for the frame the mesh was built, but reports the correct time to the profiler window in the editor despite that. And the longer it takes the more of them that will start reporting 0 elapsedNanoseconds. Contrary to my previous post, however, it's definitely not the longest ones that errors out first all the time. It really seems to be arbitrary.

 

Ok, thank you for the information! This is not expected - if the activity happens on a main thread recorders should not be reset no matter how long frame took (the overlap should happen for much more than a couple of seconds).
Could you please file a bug for this behavior and post the # here so I can pick it up quickly.

 

Done, the # is 1219431