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).
If someone doesn’t believe that the profiler gets extremely slow, I’ve just profiled the profiler.
I’ve recorded data as normal (but with “Profile Editor” also selected, in order to profile the profiler)
stopped recording
selected a peak frame
got through to some call deep in the hierarchy, as shown in the previous screenshot
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().
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.
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.
Hi.
From looking at the screenshot, the Deep Profiling is still enabled. This adds significant overhead to all managed calls.
Could you try the following:
Enable Deep Profiling
Capture your frame
Stop profiling, and disable deep profiling
Investigate the frame you are interested in
As the deep profiling is only recommended for small scenes, because of the overhead, it is expected that profiling the editor will have a very large performance overhead - and specially when drilling into that frame when deep profiling is enabled.
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).
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:
using UnityEngine;
using System.Collections;
public class Test : MonoBehaviour
{
IEnumerator Start ()
{
yield return new WaitForSeconds(1f);
aa();
}
void aa() { ab(); }
void ab() { ac(); }
void ac() { ad(); }
// ...lots of functions here...
void zx() { zy(); }
void zy() { zz(); }
void zz() { Debug.Log("Print!"); }
}
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.
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?
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.
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.
using System.IO;
using System.Reflection;
using UnityEditor;
using UnityEditorInternal;
public class ProfilerUtil
{
private const string HtmlOutputPath = "profiler.html";
[MenuItem("Tools/Dump selected profiler frame to HTML")]
public static void DumpProfilerFrame()
{
var property = new ProfilerProperty();
property.SetRoot(GetSelectedFrame(), ProfilerColumn.TotalPercent, ProfilerViewType.Hierarchy);
property.onlyShowGPUSamples = false;
if (File.Exists(HtmlOutputPath))
File.Delete(HtmlOutputPath);
var stream = File.OpenWrite(HtmlOutputPath);
var writer = new StreamWriter(stream);
writer.WriteLine(@"<html>
<head>
<title>Unity Profiler Data</title>
<style type=""text/css"">
html, body {
font-family: Helvetica, Arial, sans-serif;
}
table {
width: 100%;
border-collapse: collapse;
}
th:first-child, td:first-child {
text-align: left;
}
th:not(:first-child), td:not(:first-child) {
text-align: right;
}
tbody tr:nth-child(odd) {
background-color: #EEE;
}
th, td {
margin: 0;
padding: 5px;
}
th {
padding-bottom: 10px;
}
td {
font-size: 12px;
}
</style>
</head>
<body>
<table>
<thead>
<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>
</thead>
<tbody>");
while (property.Next(true))
{
writer.Write("<td style=\"padding-left:" + property.depth*10 + "px\">");
writer.Write(property.GetColumn(ProfilerColumn.FunctionName));
writer.Write("</td>");
writer.Write("<td>");
writer.Write(property.GetColumn(ProfilerColumn.TotalPercent));
writer.Write("</td>");
writer.Write("<td>");
writer.Write(property.GetColumn(ProfilerColumn.SelfPercent));
writer.Write("</td>");
writer.Write("<td>");
writer.Write(property.GetColumn(ProfilerColumn.Calls));
writer.Write("</td>");
writer.Write("<td>");
writer.Write(property.GetColumn(ProfilerColumn.GCMemory));
writer.Write("</td>");
writer.Write("<td>");
writer.Write(property.GetColumn(ProfilerColumn.TotalTime));
writer.Write("</td>");
writer.Write("<td>");
writer.Write(property.GetColumn(ProfilerColumn.SelfTime));
writer.Write("</td>");
writer.WriteLine("</tr>");
}
writer.WriteLine(@"</tbody>
</table>
</body>
</html>");
writer.Close();
}
private static int GetSelectedFrame()
{
var editorAssembly = Assembly.GetAssembly(typeof(EditorApplication));
var profilerWindowType = editorAssembly.GetType("UnityEditor.ProfilerWindow");
var profilerWindowsField = profilerWindowType.GetField("m_ProfilerWindows", BindingFlags.NonPublic | BindingFlags.Static);
var firstProfilerWindow = ((System.Collections.IList) profilerWindowsField.GetValue(null))[0];
var getFrameMethod = profilerWindowType.GetMethod("GetActiveVisibleFrameIndex");
return (int) getFrameMethod.Invoke(firstProfilerWindow, null);
}
}
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…