Search Unity

Bug Case 1318018 Dots Profiling not showing custom code

Discussion in 'Editor & General Support' started by MNNoxMortem, Feb 21, 2021.

  1. MNNoxMortem

    MNNoxMortem

    Joined:
    Sep 11, 2016
    Posts:
    723
    I try to analyze a spike with my Dots based application and the profiler does not show all the information I would have expected. I feel there are huge gaps in the profiling information:
    upload_2021-2-21_21-17-51.png

    This 1.9s frame shows 1.7s in IUpdate but only shows 286ms in GC.Collect, 19ms LogStringToConsole and the rest is minor.

    Where is the rest of my 1.7? I am missing roughly 1.4s without any entry in the hierarchy?

    If I show the timeline I see many chained
    upload_2021-2-21_21-25-22.png
    Gfx.WaitForGfxCommandsFromMainThread. What lies behind those?

    The RenderThread hierarchy only shows
    Semaphore.WaitForSignal (1733.23ms/1733.28ms)

    I have posted this in the Dots section as with MonoBehaviours or plain C# classes I usually was able to quickly identify which of my code is slow. Now with dots I feel a bit blind.
     
    Last edited: Feb 21, 2021
    MNNoxMortem, Feb 21, 2021
    #1

  2. MNNoxMortem

    MNNoxMortem

    Joined:
    Sep 11, 2016
    Posts:
    723
    Just an assumption, but I assume this is the same spike from a player build and this looks much more than I would expect:
    upload_2021-2-21_21-43-38.png
    MaterializingControlller is my code and this is where I would have expected the spike to occur. Why is this fully missing in the editor profiler hierarchy?
     
    Last edited: Feb 21, 2021
    MNNoxMortem, Feb 21, 2021
    #2

  3. MartinTilo

    MartinTilo

    Unity Technologies

    Joined:
    Aug 16, 2017
    Posts:
    2,460
    Hi there,
    In the editor, did you have "Deep Profile" turned on while recording (it is in the screenshots but I can't definitely tell if that was flipped on afterwards or not)? And is IUpdate a DOTS update call? It seems like a bug to me that there is no scripting information below IUpdate. Have you filed a bug report on that?
     
    Last edited: Feb 27, 2021
    MartinTilo, Feb 27, 2021
    #3

  4. MartinTilo

    MartinTilo

    Unity Technologies

    Joined:
    Aug 16, 2017
    Posts:
    2,460
    That means the Render thread is idle/sleeping and waiting for more work from main thread. Same for Semaphore.WaitForSignal. They are not taking up any CPU cycles on the Render thread and the Sample are just there for informational purposes. Further explanations on these and similar samples can be found in this page of our documenation.
     
    Last edited: Feb 27, 2021
    MartinTilo, Feb 27, 2021
    #4
    MNNoxMortem likes this.

  5. MNNoxMortem

    MNNoxMortem

    Joined:
    Sep 11, 2016
    Posts:
    723
    Deep Profile: Yes
    IUpdate is a registration with the custom player loop. I have not filed a bug report, as I was not sure what was happening here. In short it does something similar to:
    Code (CSharp):
    1.  
    2.  
    3. PlayerLoopSystem loop = PlayerLoop.GetCurrentPlayerLoop();
    4. for (var systemIndex = 0; systemIndex < loop.subSystemList.Length; systemIndex++)
    5. ref PlayerLoopSystem system = ref loop.subSystemList[systemIndex];
    6. if (system.type == typeof(Update))
    7. RegisterUpdate(ref system);
    8. ....
    9.  
    10. //RegisterUpdate
    11.   var subSystem = new PlayerLoopSystem[system.subSystemList?.Length + updateHooks ?? updateHooks];
    12. ... // copy existing systems
    13. // add new custom system
    14. subSystem[++i] = new PlayerLoopSystem {
    15.                     type           = typeof(IUpdate),
    16.                     updateDelegate = Update
    17.                 };
    18. system.subSystemList = subSystem;
    and this way adds custom systems to be run after all update calls
     
    Last edited: Feb 27, 2021
    MNNoxMortem, Feb 27, 2021
    #5

  6. MartinTilo

    MartinTilo

    Unity Technologies

    Joined:
    Aug 16, 2017
    Posts:
    2,460
    Alright, thanks for those details. I'm not 100% sure if this is a bug or a feature gap yet, but if you could please file a bug and let me know what issue ID you get back from that, I can take this up with the team and see if we take it as a bug or put on our feature request list. :)
     
    MartinTilo, Feb 27, 2021
    #6

  7. MNNoxMortem

    MNNoxMortem

    Joined:
    Sep 11, 2016
    Posts:
    723
    @MartinTilo Case 1318018 - sorry for the below mediocre bug report. Currently time is a bit scarce.
     
    MNNoxMortem, Feb 27, 2021
    #7

  8. MartinTilo

    MartinTilo

    Unity Technologies

    Joined:
    Aug 16, 2017
    Posts:
    2,460
    Thank you, I understand, its important to validate that this works though, so I fixed up that code example. Can't reproduce it yet though, neither on 2020.2, nor 2021.2. I've send you the script I've used.
    Would be cool if you could give that a spin or correct it in case my implementation differs from yours in a way that this brakes?
     
    MartinTilo, Mar 1, 2021
    #8

  9. MartinTilo

    MartinTilo

    Unity Technologies

    Joined:
    Aug 16, 2017
    Posts:
    2,460
    Hello @MNNoxMortem ,

    Thank you again for submitting this bug report and I hope you can forgive the delay in our response. We've considered the issue and concluded that this is behaving as it should at this moment, but we have filed a feature request on your behalf to insert instrumentation for custom PlayerLoop delegates.

    The time that looks like it is missing is attributed to the higher level markers in the column 
    Self ms
    . lacking more markers or Managed Code that would get automatically instrumented by turning on Deep Profiling, there is no way to attribute that time in a more granular fashion. Also, some time could genuinely be spend within those functions.

    So to conclude, right now this is considered as a Feature Request where the workaround is to manually place ProfilerMarkers in custom PlayerLoop delegates to get them to show up in the profiler, or to turn on Deep Profiling.

    I hope this works for you and thank again for raising this :)
     
    MartinTilo, Oct 3, 2022
    #9