Search Unity

  1. Unity Asset Manager is now available in public beta. Try it out now and join the conversation here in the forums.
    Dismiss Notice

Bug Deep Profiler is broken in 2019.3.0b11? Can't turn it off

Discussion in '2019.3 Beta' started by my_little_kafka, Nov 18, 2019.

  1. my_little_kafka

    my_little_kafka

    Joined:
    Feb 6, 2014
    Posts:
    87
    I think I'm losing my mind, and it all started after I enabled Deep Profiling in Profiler for the first time (and it took me quite a lot of hours to find the culprit).

    So I'm working on an inventory system. In order to test it, instead of writing automation tests and such I use the good old approach of assigning various functions to key on a keyboard. These functions add various items to the inventory and sort it. It all works pretty fast, even with more than 8k of items (there will be never that much items in my game though). It worked quite well on 2019.3.0b10, but it had a nasty bug where Canvas Scaler component was messing with the Canvas and it was basically unusable. I migrated to 2019.3.0b11 and everything worked fine. I was mashing the keys to add more items to the inventory and it worked without any lags.

    Then I decided to remove every possible GC allocation that is possible to remove, so I used Deep Profile function in Profiler. After that, it seems like my Editor runs in constant Deep Profile mode and I can't turn it off.
    Even if create an empty scene, place Graphy object to test the performance, and start mashing the buttons (that don't do anything), the performance will be dropping.
    I first noticed it when I started to spam the functions to add items again, and the editor started to drop frames like crazy. At first I thought that I did something wrong with inventory Lists and LINQ operations, but I started to disable these functions to find a culprit - in the end I just stopped to call these functions - and to my surprise, when I was mashing these now empty keys, the performance was still dropping. I started an investigation and this is what I found:

    If I mash every key in the Unity Editor while in the Game Mode, the performance will take a hit. A lot of hits. Down to 15-20 FPS if I mash the buttons constantly. Even in the empty scenes.

    If I mash key that do call functions in the scripts, in the build with Deep Profiler enabled, the game will drop frames. Mashing empty keys do nothing.

    If I make a non-debug build without Profile connected, there will be just small spikes when I start to mash buttons, it doesn't seem to lower the FPS that much (though it's weird that mashing keys in an empty scene does something, I guess it's because every button press is being caught by Unity or something).


    So, everything tells me that the Editor now runs in a constant Deep Profile mode, where it calculates all the calls. I can't turn it off, it seems, even if the button looks like it's turned off.

    TL;DR;
    Used Deep Profiler once in the Editor, now it looks like the Editor runs in constant Deep Profile mode, which is a lot slower.

    Is it something with the profiler? Or is it by design and I'm just losing it? I remember that before I moved to 2019.3.0b11, mashing the keys was never an issue in the Editor and in builds.
     
  2. alexeyzakharov

    alexeyzakharov

    Joined:
    Jul 2, 2014
    Posts:
    507
    Deep Profiler mode in the Editor is toggled by the button in the Profiler timeline - it is unlikely that it is broken.
    What happens if you toggle it off? Do you still see your C# method calls which are not directly called as unity callbacks?
    Deep Profiler is off by default as we don't want any perf overhead for normal usage.

    I would also try enabling allocation callstacks to see if you can pin point those without deep profiler.
     
    my_little_kafka likes this.
  3. my_little_kafka

    my_little_kafka

    Joined:
    Feb 6, 2014
    Posts:
    87
    The thing is - it was already off, but the editor works with freezes now when I just mash keys that are not tied to any functions in scripts.

    I'm not sure I understand. I see the calls of my methods only when I press buttons that call them. When I mash just empty keys, it just lags — when I used Deep Profiler in the Editor, it says that they're called by EditorLoop (the amount of time to compute the frame could jump up to ~80ms and it will be on the EditorLoop), if I make a build and Deep Profile it, the spikes are called by this:



    The screenshot is made in a new and empty project, only standard camera+light source+skybox+Graphy prefab.

    I never noticed it before. If I disable the Deep Profile button and run the empty project and mash the buttons, the performance will drop anyways:

    I'm at loss. I realize that it sounds weird and unprofessional ("mashing buttons like crazy"), but something changed after I tried to turn Deep Profile on after I upgraded to the recent 2019.3 beta version
    Edit:
    Clicking mouse buttons also counts towards the spikes on the graph
     
    Last edited: Nov 18, 2019
    alexeyzakharov likes this.
  4. alexeyzakharov

    alexeyzakharov

    Joined:
    Jul 2, 2014
    Posts:
    507
    Thanks for the screenshot!
    As I can see from the screenshot this is the capture from a Player with Deep Profiler Support enabled in the Build Window. Deep Profiler being builtin introduces an overhead to the player - this should be stated in the tooltip and https://docs.unity3d.com/2019.3/Documentation/Manual/BuildSettings.html.

    Do you happen to do editor profiling after player profiling? Perhaps "Deep Profiler" state carried over and caused scripts in the Editor being compiled with profiler hooks.
    Could you please try toggling off/on/off the "Deep Profiler" button before entering play mode and see if that helps.
     
    my_little_kafka likes this.
  5. my_little_kafka

    my_little_kafka

    Joined:
    Feb 6, 2014
    Posts:
    87
    I didn't, but I could have tried it to reset the state, I think I just changed the profiling to the editor and back.

    Did this for both Playmode and Editor settings, nothing changed. It also acts the same way between my current game project where I was implementing an inventory and an empty project I created just to test this issue. Should I report a bug with the empty project (just Graphy, a free performance graph tool from the Asset Store to see the lag spikes)?
     
  6. my_little_kafka

    my_little_kafka

    Joined:
    Feb 6, 2014
    Posts:
    87
    Are Profile settings are shared between projects or even Unity versions? I'm getting the same spikes in Unity 2019.1.0f2:



    Homestly, I'm at loss. Is it even a normal thing - mashing buttons in the Editor with Profiler turned off lowering the FPS in the Play mode?
    I thought maybe it's because I got some virus or a keylogger or something - but this doesn't happen at all on non-debug builds.
     
  7. Peter77

    Peter77

    QA Jesus

    Joined:
    Jun 12, 2013
    Posts:
    6,618
    You could turn on the "Profile Editor" option and then check where these spikes are coming from. The last screenshot you posted shows it's an editor thing. With "Profiler Editor" enabled, you should be able expand the "EditorLoop" node and then drill down to the entry which causes the spike.
     
    my_little_kafka likes this.
  8. my_little_kafka

    my_little_kafka

    Joined:
    Feb 6, 2014
    Posts:
    87
    Oh, didn't know this, thanks!

    This is what mashing buttons do on 2019.3.0b11 in a completelly empty scene:



    Tick timer unfolded:


    And this one has OnKeyDown/Up calls from IMGUI (is this the source of the lag?):
     
  9. my_little_kafka

    my_little_kafka

    Joined:
    Feb 6, 2014
    Posts:
    87
    Is there any info on how and where the settings of the Profiler are stored? Is it hooked inside the project itself (doesn't look like it because it lags even in newly created projects)?
    Maybe there's some cache in AppData which I could delete? Should I just reinstall all the unity versions I have (would be quite bothersome), deleting UnityHub and cleaning my system from every Unity trace to revert to the non-glitched Editor state? I'm desperate.
     
  10. alexeyzakharov

    alexeyzakharov

    Joined:
    Jul 2, 2014
    Posts:
    507
    Most of profiler settings are session-only - they are stored in memory while Editor is running. Deep profiler toggle is one one those - when you restart Editor it is off by default (unless you use cmdline param).
    TBH I don't see any traces of Deep Profiler being enabled - the hierarchy view looks normal and doesn't have any deeply nested scripting calls. The issue might be that profiler window rendering itself takes time but this for sure has no impact on players.
    If you do profiling, but have e.g. Console window focused and Profiler Window hidden do you still have lags?
     
  11. my_little_kafka

    my_little_kafka

    Joined:
    Feb 6, 2014
    Posts:
    87
    The lag still happens, even if I'm not profiling anything (the lag spikes are seen on Graphy's FPS graph in that case).

    Maybe it was always like this in the editor and I'm just remembering wrong? Obviously there's an editor overhead, is it a normal thing when excessive input can cause lag spikes? Everything is normal in the build with no Profiler attached.

    Unfortunately, I don't have an access to other machines to test the behaviour. That would be quite embarrassing if I created this thread for naught and it was always like that and I just didn't notice it before I implemented an advanced technique in a form of button mashing.
     
  12. alexeyzakharov

    alexeyzakharov

    Joined:
    Jul 2, 2014
    Posts:
    507
    I'm pretty sure it wasn't like that and there are reasons that you see those spikes in the beta. The question is what is the reason. And
    this might be the potential reason.
    If you can spot the lag excluding the profiler window impact into the editor itself (hiding it, but keeping enabled with Editmode profiling enabled), the help would be much appreciated.
     
  13. my_little_kafka

    my_little_kafka

    Joined:
    Feb 6, 2014
    Posts:
    87
    So I did this: I enabled the recording of Profiler with Editmode enabled, switched the window to a console (presumably so the Editor won't spend time rendering the Profiler's information? I didn't close it, just switched) and produced some lag with button mashing, the Profiler now shows something different (but it is still in OnGUI):
     
    alexeyzakharov likes this.
  14. alexeyzakharov

    alexeyzakharov

    Joined:
    Jul 2, 2014
    Posts:
    507
    Thanks!
    I can still see profiler window UI part here and the JIT calls which happen only once after domain reload.
    This spike is somewhat expected due to Mono always doing compilation and slowing down the first code execution for everything including Editor code.
    Could that be that this spike is the first frame after hitting Play and before switching to the Console widow?
     
  15. my_little_kafka

    my_little_kafka

    Joined:
    Feb 6, 2014
    Posts:
    87
    No, I specially waited for ~30 seconds before I started to mash buttons. And even if switching to the Profiler causes a natural spike too, I didn't screenshot the first spike, only those which I sure were caused by button mashing.

    Did the same thing again, waited for 30 seconds (you can see there's no spikes in the beginning of the graph because I didn't mash buttons). The spikes show this:


     
    alexeyzakharov likes this.
  16. my_little_kafka

    my_little_kafka

    Joined:
    Feb 6, 2014
    Posts:
    87
    Checked my system for viruses just in case, the system was clean, so it's 100% something in the Editor
     
  17. alexeyzakharov

    alexeyzakharov

    Joined:
    Jul 2, 2014
    Posts:
    507
    @my_little_kafka have you filed a bug for this case yet? I think the issue might be related to locked domain reload which prevents deep profiler from being correctly initialized
     
    my_little_kafka likes this.
  18. my_little_kafka

    my_little_kafka

    Joined:
    Feb 6, 2014
    Posts:
    87
    Oh, sorry, didn't get from the thread whether I should file a bug report or not. Created a simple project with easily replicated problem and reported a bug
     
    Last edited: Jan 15, 2020
    charlesb_rm and alexeyzakharov like this.
  19. alexeyzakharov

    alexeyzakharov

    Joined:
    Jul 2, 2014
    Posts:
    507
    Thank you, this is helpful!
     
    my_little_kafka likes this.
  20. jonathans42

    jonathans42

    Unity Technologies

    Joined:
    Jan 25, 2018
    Posts:
    514
    The deep profiling toggling will be fixed in the next release of 2020.1 and will get backported to 19.3.
     
  21. esbenjon

    esbenjon

    Joined:
    Aug 20, 2018
    Posts:
    7
    In case someone else is searching for a workaround.

    I had a similar problem in 2021.3.13f1
    Even when the profiler was turned off with the red button, it would keep starting up. The workaround for me was to turn off deep profiling which caused a recompile.