Why is Unity's profiler so slow and unresponsive in a frame that has a lot of data?

The answer might seem obvious from the question (lot of data == bad performance), but it I don't think it is. When I'm in deep profile mode and I select a frame where a peak happened, I expect the profiler to hang for a while as it processes useful information out of the recorded data for the frame (percentages, durations, cumulative sums...). It does. That's fine.

Then I have to find what function is mainly causing the peak, and it is sometimes buried behind a couple dozen calls, for example from a button click event. I have to select a call, press "right" and "down" to expand and move to the first child, and so on. Each expansion should be almost instant, though some more calculations might happen for it.

But that is not the case! I can report that I've had to successively expand children in loooong chains of calls and waited more than 10 seconds after each action. It got worse the further down the chain I got, so the profiler seems to be doing more and more stuff at each deeper level. Scrolling becomes excruciatingly slow, dragging the profiler window too, selecting items, etc.

Correct me if I'm wrong, but with each OnGUI draw, it might be trying to recalculate every number that the user can see in the function hierarchy. This happens every time an item is expanded or the window is dragged. Could it be that values are not being cached in the profiler?


A user submitted an issue about this but it was marked as "By Design". This is not by design. It is a performance problem and I'm pretty sure it can be done better.

The attached screenshot is an example of a long call hierarchy, but this one "only" took a little over a second to expand each item (got worse as more items were expanded).

- Daniel

 

If someone doesn't believe that the profiler gets extremely slow, I've just profiled the profiler.

1. I've recorded data as normal (but with "Profile Editor" also selected, in order to profile the profiler)
2. stopped recording
3. selected a peak frame
4. got through to some call deep in the hierarchy, as shown in the previous screenshot
5. continued recording

You can see the difference between normal data recording and lagging recording, which is the blue "mass" at the end. The culprits are also highlighted and yes, the problem is related to the profiler's GUI methods and most notably ProfilerProperty.Next().

Can anyone from Unity comment this, please?

 

Does anyone have any insight? I might report this but I don't want to get a simple "By Design" reply. This profiler issue seems a bit more than that.

 

It would seem to be that there is no culling drawing that massive tree. We have had the same problem.

 

Yes, the calls that are offscreen might still be drawn. But I would say that even in that case, it shouldn't be this slow. I've made OnGUI scroll lists with many more items and no culling, and they would still react rather fast (scrolling suffers the most). Unless collapsed items are still calculating stuff... but in that case it shouldn't get worse further down...

It becomes veeeeeeery slow, so that's why I though that some values might be calculated more than once because of all the items. This is all just a guess and might be completely wrong, though.

I would like this to be solved. The frames I normally want to profile are generally ones with a lot of things happening.

 

Agreed. When trying to nail down any deep performance issue, especially where recursion might be employed, the profiler GUI gets unusably slow. I've had to wait for 30s for a single expansion before.

 

Same here, i really hope they improve that. It's almost unusable in real situations where you actually need to profile (spiking frame to profile = often more calls = less responsive profiler window).

 

I have just reported this issue as a bug and sent an attached example project to the Unity team. Let's hope they acknowledge the issue and improve this!

If anyone else wants to add something, please do! I've sent a link to this thread in the problem description, so they should be able to see this.

- Daniel

 

Just to update those interested in this problem, the Unity team just replied to my report, saying:

To which I replied with:

 

Yeah, if the deep profiler is parsing the C# code more then once after you have selected a frame, that's bonkers.

I tried to profile serializing our save files to YAML, and I had to give up because there was a ten second delay between clicking in the profiler and having the click registered. It was impossible to expand past two levels.

Either the profiler is calculating all of the information about the call stack every GUI frame, which would be fixable, or the profiler's GUI code is broken. I doubt any of those are by design.

 

Exactly! It's very difficult or even impossible to use the profiler in frames with large peaks, which is a very common case where the profiler could be useful.

I also doubt that this is by design. I apologize to the Unity team if this sounds like a user assuming things without knowing the way things work (I might be, of course), but I still suspect that this could be fixed to a point with almost no lag at all, even if selecting a frame had to take more time instead.

 

I always disable all profiling toggles after profiling, even though it never made a difference for the window (i suspect using the immediate mode gui, it recalculates the window with 'all' the captured calls every frame or similar).

 

Hi Kim,

I understand what you wrote in your post and in the e-mail you sent me, but the problem seems to persist. I ran my test scene again, selected a frame where a large peak happened, disabled recording and deep profile, and then tried to successively expand items of the function call that was mainly causing the peak. I've found that the problem remains and the lag is essentially the same as when I had deep profiling enabled.

Note that I was not deep profiling the editor/profiler now. That was just to show the difference in lag after selecting a peak frame.

I annexed my test project (I probably sent it with my bug report too, but I can't remember). It runs an extremely long chain of calls after 1 second, like this:

Code (CSharp):

1. using UnityEngine;
2. using System.Collections;
3.  
4. public class Test : MonoBehaviour
5. {
6.     IEnumerator Start ()
7.     {
8.         yield return new WaitForSeconds(1f);
9.         aa();
10.     }
11.  
12.     void aa() { ab(); }
13.     void ab() { ac(); }
14.     void ac() { ad(); }
15.     // ...lots of functions here...
16.     void zx() { zy(); }
17.     void zy() { zz(); }
18.     void zz() { Debug.Log("Print!"); }
19. }

This is an oversized chain, but serves its purpose. Try running the scene with deep profile enabled, selecting the profiler peak at 1s and then, with or without first disabling recording and deep profile, dragging the profiler window around. It should lag immensely.

Also try expanding the function calls. Depending on your machine, you should immediately notice the lag after each click, or maybe later on after having expanded some more calls.

I appreciate the time you took to reply to us on this issue.

- Daniel

 

Hi again, Kim

I'm glad that I could help (and that there are indeed things to improve in the profiler!). The lag always felt very wrong and made the profiler unusable most of the time. Please do keep us updated!

On a side note, Gintautas of the QA team mentioned today in an e-mail that this could be related to a regression bug here. I'm not sure if that affects anything, seeing that that issue appeared in version 5.4 and I'm still using stable 5.3.4, and you also confirmed the other problems. Should I reply? Or are you in sync about this issue?

Cheers,
Daniel

 

I was just looking into the feasibility of grabbing the frame data via reflection and writing my own simple little GUI to display it. The reason why I was looking to do that is that any kind of deep profiling results in ~10 second frame times while using the Profiler window (like others mentioned).

It's good to see that Kim from Unity is looking these performance problems. If the Profiler was open source it would've allowed me to fix the problems myself, but of course I'm still happy it's looked at officially.

 

Hey @Kim Riber, I just wanted to know if there are any updates about this. Unity 5.4 hasn't released outside of beta and I'm not using it, so I'm not aware if any of it was fixed there.

Thanks!
Daniel

 

Any update on this issue? It does make the profiler impossible to use to identify which method in a deep callchain is responsible for a large hitch. We're using 5.3.4p5.

 

Also had this issue with data-rich frames (aka spikes, aka those being the interesting ones). Waiting several seconds for a tree node to expand is no fun. And super unproductive. So I wrote a small helper method to export the data of the currently selected frame to an HTML table. Only needed a little bit of reflection to get the selected frame. Adjust as necessary. Works in 5.4, no guarantees for this to work in other versions as it uses UnityEditorInternal.

Code (CSharp):

1. using System.IO;
2. using System.Reflection;
3. using UnityEditor;
4. using UnityEditorInternal;
5.  
6. public class ProfilerUtil
7. {
8.     private const string HtmlOutputPath = "profiler.html";
9.  
10.     [MenuItem("Tools/Dump selected profiler frame to HTML")]
11.     public static void DumpProfilerFrame()
12.     {
13.         var property = new ProfilerProperty();
14.         property.SetRoot(GetSelectedFrame(), ProfilerColumn.TotalPercent, ProfilerViewType.Hierarchy);
15.         property.onlyShowGPUSamples = false;
16.  
17.         if (File.Exists(HtmlOutputPath))
18.             File.Delete(HtmlOutputPath);
19.         var stream = File.OpenWrite(HtmlOutputPath);
20.         var writer = new StreamWriter(stream);
21.  
22.         writer.WriteLine(@"<html>
23. <head>
24. <title>Unity Profiler Data</title>
25. <style type=""text/css"">
26. html, body {
27. font-family: Helvetica, Arial, sans-serif;
28. }
29. table {
30. width: 100%;
31. border-collapse: collapse;
32. }
33. th:first-child, td:first-child {
34. text-align: left;
35. }
36. th:not(:first-child), td:not(:first-child) {
37. text-align: right;
38. }
39. tbody tr:nth-child(odd) {
40. background-color: #EEE;
41. }
42. th, td {
43. margin: 0;
44. padding: 5px;
45. }
46. th {
47. padding-bottom: 10px;
48. }
49. td {
50. font-size: 12px;
51. }
52. </style>
53. </head>
54. <body>
55. <table>
56. <thead>
57. <tr><th>Path</th><th>Total</th><th>Self</th><th>Calls</th><th>GC Alloc</th><th>Total ms</th><th>Self ms</th></tr>
58. </thead>
59. <tbody>");
60.  
61.         while (property.Next(true))
62.         {
63.             writer.Write("<td style=\"padding-left:" + property.depth*10 + "px\">");
64.             writer.Write(property.GetColumn(ProfilerColumn.FunctionName));
65.             writer.Write("</td>");
66.  
67.             writer.Write("<td>");
68.             writer.Write(property.GetColumn(ProfilerColumn.TotalPercent));
69.             writer.Write("</td>");
70.  
71.             writer.Write("<td>");
72.             writer.Write(property.GetColumn(ProfilerColumn.SelfPercent));
73.             writer.Write("</td>");
74.  
75.             writer.Write("<td>");
76.             writer.Write(property.GetColumn(ProfilerColumn.Calls));
77.             writer.Write("</td>");
78.  
79.             writer.Write("<td>");
80.             writer.Write(property.GetColumn(ProfilerColumn.GCMemory));
81.             writer.Write("</td>");
82.  
83.             writer.Write("<td>");
84.             writer.Write(property.GetColumn(ProfilerColumn.TotalTime));
85.             writer.Write("</td>");
86.  
87.             writer.Write("<td>");
88.             writer.Write(property.GetColumn(ProfilerColumn.SelfTime));
89.             writer.Write("</td>");
90.  
91.             writer.WriteLine("</tr>");
92.         }
93.  
94.         writer.WriteLine(@"</tbody>
95. </table>
96. </body>
97. </html>");
98.  
99.         writer.Close();
100.     }
101.  
102.     private static int GetSelectedFrame()
103.     {
104.         var editorAssembly = Assembly.GetAssembly(typeof(EditorApplication));
105.         var profilerWindowType = editorAssembly.GetType("UnityEditor.ProfilerWindow");
106.         var profilerWindowsField = profilerWindowType.GetField("m_ProfilerWindows", BindingFlags.NonPublic | BindingFlags.Static);
107.         var firstProfilerWindow = ((System.Collections.IList) profilerWindowsField.GetValue(null))[0];
108.         var getFrameMethod = profilerWindowType.GetMethod("GetActiveVisibleFrameIndex");
109.         return (int) getFrameMethod.Invoke(firstProfilerWindow, null);
110.     }
111. }

 

Great use of reflection!

 

You're a life saver! Profiling is actually possible again! I've been using this and solved lots of problems.

 

I decided to make a profiler viewer that is actually able to handle larger amounts of data - where Unity's profiler would grind to halt: https://github.com/AquaGeneral/Snappy-Profiler-Viewer

Also of course, it's open source.

 

Nice work, @AquaGeneral! I completely missed the notification for your post. By the way, on my Unity (5.5.0), ProfilerColumn.DontSort doesn't exist anymore, but the rest works.

Now, about the profiler fix for Unity itself... last time I checked (in September) I asked @Kim-Riber via personal message and at the time someone named Alexey was looking into this. I wonder how this is going now. I don't see anything related in recent release notes (up to 5.5.1). Does anyone know?

 

@CanisLupus Strange, I'm using Unity 5.5.0 as well and PorfilerColumn.DontSort still exists for me. I will see if Unity 5.6 (or the beta at least) is any different soon.

I must also say, the only reason why my Snappy Profiler Viewer is actually super quick compared to Unity's Profiler is down to some pretty trivial optimizations. I am caching the profiler data, while Unity's profiler is grabbing it every frame, and I am only rendering data that's visible, while Unity's profiler is rendering all data.

 

I think all the developers really hate messing with Unity's GUI stuff, that's why simple things take ages to be improved.

 

I looked at the Unity Profiler's code using a dissembler, and that is how I created Snappy Profiler Viewer. Had the source code been available to Unity, I could've actually optimized it within a day or less.

I sorely doubt the Unity developers are afraid of touching GUI code, because the truth of it is that it's not that daunting, and if they created the functionality to begin with they find it relatively trivial to come back to.

 

I don't know how you have DontSort (UnityEditorInternal.ProfilerColumn.DontSort, right?) and I don't, but it was easily "fixed". And yeah, having to code scroll views to render only the needed data in the old GUI is tedious but needed for performance. Caching in this case is also essential.

As for the Unity developers, if I had to guess I would say that the original creators of the GUI system (which is now ancient by Unity's timeline) and the profiler are working on other things. This task could go into other hands. But I don't think it would be difficult to fix on their part. I don't find OnGUI coding fun, though.

I feel that they generally prioritize "technological" features and work on the different export platforms. Most of the essential windows of the Editor are still almost the same after many years and they have much room for improvement. But this issue with the Profiler is, in my opinion, a big priority.

 

Hi guys,

Thanks a lot for your comments!
We've fixed the Hierarchy view issue when traversing the whole hierarchy every draw. The fix will be available in 5.6.

Also we've added an option to disable detailed view which shows objects related to the selected call.
That saves one more hierarchy traversal when you walk through the view.
Just Hierarchy View:

With Related Objects:


Profiler is getting much more attention now and we are working on low level improvements as well as on UI improvements (addressing first of all suggestions mentioned in https://forum.unity3d.com/threads/official-profiler-improvements.404899/).

P.S.:
Please vote for the issues which are annoying you the most. E.g. we had this issue as https://issuetracker.unity3d.com/is...performance-even-when-profiler-isnt-recording, but it didn't get much tracking. Voting helps us prioritize fixes and features development.

 

@alexeyzakharov So you're Alexey!

Woohoo, faster profiler. Thank you! I really appreciate the update.

I didn't know that thread existed until now, or I would have definitely posted there. If the 5.6 beta has this fix already, I may try downloading it soon and see. Then I'll probably comment about what other things may be improved in that thread.

As for votes, I just noticed that I have them back. I had them all used up before, but those issues were probably fixed by now. Consider it a suggestion for the issue tracker: emailing you when a voted feature is solved and gives you your points back.

Thanks again,
Daniel

 

Very good work! Thanks for the update!

Your voting system gives us 10 votes, ever. There's more than 10 issues that are important at any time, and most of them gets stuck in Feedback limbo. The system desperately needs to be completely reworked.

All of my votes are already tied up in issues that were posted at one point between 2009 and 2015. Since you just let issues that you can't work on float forever without setting them as "won't fix" or "under research", all long-time users will eventually get their votes tied up permanently. The end result is that new issues will only be voted on by new users.

The profiler being slow is also an annoying issue, but it's not preventing us from doing certain things. When that's the case, it's not got a chance when people need to weigh their votes between that and eg. very important stuff.

 

It should be in the next beta (5.6b7).

Yes, you are right - you should get your votes back once the issue is resolved.

I understand, I'll relay this to the right people.

 

Hey everyone,

It has been a while but today I finally moved our current project to Unity 5.6 (actually 5.6.1f1) to test the profiler. It seems faster by a good deal, but... it's still extremely slow!

I wanted to profile the startup frame of our project, which does quite a lot in loading, processing and instantiating, but it takes about 13 seconds to expand each call (it was worse before, surely).

Isn't it possible to fully process the frame data once when we select the frame, cache everything, and then let the GUI paint normally without extra calculations? Dragging the profiler window around is still worse than a slideshow when a busy frame is selected, and that's my first cue that something is wrong.

Should I post in the other thread about improvements? It seems this (this!) thread is more focused on the performance problem instead of new features, so it felt better.

Cheers!
Daniel

PS: I have the "Show related objects" option off already.

 

So... I just posted in the profiler improvements thread. There's not too much going on there now, so I hope this is getting the appropriate attention!

 

Hi, I am using 5.6.1f1, and Deep Profile is still so slow its unusable, when expanding the nodes. Please fix it.

 

Hi,
Thanks for the feedback!

Yes, we have plans to improve this. First of all use new TreeView component for Hierarchy View which provides ModelViewController pattern flexibility and doesn't require walking through entire tree when unfolding a node. Secondly, add a filtering at assembly level (e.g. don't profiler System or UnityEngine assemblies). And also do deserialization at C# reducing amount of generated managed allocations when passing data from a model to view.

We are definitely watching profiler improvements thread and are working on Profiler improvements!

 

Thanks for the feedback!
As mentioned in the previous reply we are aware of the issue and are working on the improvements. Hierarchy View is one of the top priorities.

 

On 5.5.x, currently taking - literally - several minutes to expand each item in a single frame in a fresh, amost-empty project, with only 5 classes, 10 gameobjects ... running on a 12-core CPU with 16 GB RAM.

Unity is taking less than 20% CPU time to do ... nothing. Just hang.

The tweaks described above do not sound like fixes to the fundamental problems in the profiler: it uses algorithms inappropraite for a profiler interface. Especially when Unity itself hangs on a system that has 11 idle cores, and even the core Unity's running on (single threaded - not a good idea) is a long long way short of saturated.

(NB: can't upgrade to 5.6 because of the bugs and lack of backwards compatibility)

 

Still incredibly slow...

 

Just found this thread because I am currently trying to find out what is the reason for the 3seconds freeze. Each and every single expansion takes 1-2 minutes. This is insane...

 

Only found this thread just now, looking for another issue ... Why isn't this post in the profiler improvements thread in the first place? I think if you're gathering feedback in such an official stickied thread giving this info there would be just fair (and more visible ).

Technical question: I like the idea of filtering certain stuff from deep profiling, but I hope this will be configurable by the user? E.g. sometimes it's also interesting to see where System. classes do their bad stuff, sometimes they have callbacks into the dev' code like for Linq etc.

Glad to see the Profiler does indeed get adressed

Regards,
Chris

 

Hey, @alexeyzakharov, any news on the profiler performance? (GUI redraws, expanding nodes, etc) Cheers!

 

Thanks for the feedback, we'll update that thread once improvements land.

Yes, at some degree. Basic idea is to allow per-assembly instrumentation with deep profiling. E.g. enable game assemblies and system assemblies profiling, but not unity assemblies. Or just game code.

Yes! As of today, the performance improvements for hierarchy views of Profiler Window landed to 2018.1a5. With a new TreeView and a slightly changed data representation, redraws are constant for any samples count (depends on view size only) and expansion depends only on number of direct children (lazy view data population). Gif demo attached.

 

But no way to do that on a per method or at least per class level? There's methods in game code that runs thousands to millions of times a frame that I obviously often would like to exclude so it doesn't impact profiling too much whereas other game code should be profiled. Couldn't it maybe be done somehow with attributes to methods/classes that specify if it should be profiled (or maybe rather excluded from deep profiling)?

Does that also mean that the crash due to memory usage when reading the profiler data is also fixed? Referring to this post but this also happens in those cases when expanding some nodes in a big deep profiling snapshot. Unity tries to allocate too much memory for the profiler in ProfilerProperty.Next and crashes.

 

Woohoo! I expect that 2018.1 won't be available for a while, but that looks nice. Thank you very much to the team for working on this issue.

 

It is still in early prototype phase. There are multiple approaches to this feature. And yes, ideally we would like to have per-function granularity, so you can inject instrumentation into a specific function from a specific assembly. Idea with attributes is interesting, however changing the code would require recompilation.

Unfortunately, no. ProfilerProperty will be deprecated in the future. We are planning to expose slightly different frame data reader from a file and later data stream format (when it is more or less settled).

 

Sounds good. I assume there's no (tentative) timeline for this yet, like you *plan* to get this in 2018.1?

 

I guess 2018.1 is for Q1 2018

 

I reported this issue a few years ago and the reply from Unity Technologies was quite underwhelming:

(Case 745488) Profiler window is unresponsive

 

technically it's not a bug, just bad design, so they are not wrong