Navigation Menu

Skip to content

Instantly share code, notes, and snippets.

@benblo
Created February 11, 2019 11:47
Show Gist options
  • Star 5 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save benblo/6eb3fe9c8007df81d0fa5fed6fddc07c to your computer and use it in GitHub Desktop.
Save benblo/6eb3fe9c8007df81d0fa5fed6fddc07c to your computer and use it in GitHub Desktop.
Measure compilation times in Unity (import, compilation, domain reload). Can export results to a json Chrome trace file.
using System;
using System.Collections;
using System.Collections.Generic;
using System.IO;
using System.Linq;
using System.Text;
using UnityEngine;
using UnityEditor;
using UnityEditor.Compilation;
namespace Swing.Editor
{
/// <summary>
/// Measure compilation times (import, compilation, domain reload).
/// Can export results to a json Chrome trace file.
/// </summary>
public class CompilationTimeTracker : ScriptableObject
{
#region prefs
const string menuRoot = "Swing/Debug/Compilation Time Tracker/";
enum LogLevel
{
Off,
Low,
Verbose,
}
static LogLevel logLevel
{
get { return (LogLevel)EditorPrefs.GetInt("CompilationTimeTracker/logLevel", (int)LogLevel.Low); }
set { EditorPrefs.SetInt("CompilationTimeTracker/logLevel", (int)value); }
}
[MenuItem(menuRoot + "Log Off", true)]
static bool menu_logOff_validate()
{
Menu.SetChecked(menuRoot + "Log Off", logLevel == LogLevel.Off);
return true;
}
[MenuItem(menuRoot + "Log Off")]
static void menu_logOff_execute()
{
logLevel = LogLevel.Off;
}
[MenuItem(menuRoot + "Log Low", true)]
static bool menu_logLow_validate()
{
Menu.SetChecked(menuRoot + "Log Low", logLevel == LogLevel.Low);
return true;
}
[MenuItem(menuRoot + "Log Low")]
static void menu_logLow_execute()
{
logLevel = LogLevel.Low;
}
[MenuItem(menuRoot + "Log Verbose", true)]
static bool menu_logVerbose_validate()
{
Menu.SetChecked(menuRoot + "Log Verbose", logLevel == LogLevel.Verbose);
return true;
}
[MenuItem(menuRoot + "Log Verbose")]
static void menu_logVerbose_execute()
{
logLevel = LogLevel.Verbose;
}
static bool shouldDumpTrace
{
get { return EditorPrefs.GetInt("CompilationTimeTracker/shouldDumpTrace", 0) != 0; }
set { EditorPrefs.SetInt("CompilationTimeTracker/shouldDumpTrace", value ? 1 : 0); }
}
[MenuItem(menuRoot + "Dump Chrome Trace", true)]
static bool menu_shouldDumpTrace_validate()
{
Menu.SetChecked(menuRoot + "Dump Chrome Trace", shouldDumpTrace);
return true;
}
[MenuItem(menuRoot + "Dump Chrome Trace", priority = 1100)]
static void menu_shouldDumpTrace_execute()
{
shouldDumpTrace = !shouldDumpTrace;
}
#endregion
#region singleton / events registration
static CompilationTimeTracker s_instance;
static CompilationTimeTracker instance
{
get
{
if (!s_instance)
{
// don't use Object.FindObjectOfType<> as it doesn't find DontSave objects
s_instance = (CompilationTimeTracker)Resources.FindObjectsOfTypeAll(typeof(CompilationTimeTracker)).FirstOrDefault();
bool existing = s_instance;
if (!existing)
{
s_instance = CreateInstance<CompilationTimeTracker>();
s_instance.hideFlags = HideFlags.DontSave;
s_instance.init();
}
EditorUtility.SetDirty(s_instance);
//Debug.Log(existing ? "retrieved existing CompilationTimeTracker" : "created new CompilationTimeTracker");
}
return s_instance;
}
}
[InitializeOnLoadMethod]
static void registerEvents()
{
CompilationPipeline.assemblyCompilationStarted += assemblyPath =>
{
instance.onAssemblyCompilationStarted(assemblyPath);
};
CompilationPipeline.assemblyCompilationFinished += ( assemblyPath, messages ) =>
{
instance.onAssemblyCompilationFinished(assemblyPath);
};
AssemblyReloadEvents.beforeAssemblyReload += () => { instance.onBeforeAssemblyReload(); };
AssemblyReloadEvents.afterAssemblyReload += () => { instance.onAfterAssemblyReload(); };
}
class ScriptPostprocessor : AssetPostprocessor
{
protected void OnPreprocessAsset()
{
double time = EditorApplication.timeSinceStartup;
if (assetPath.EndsWith(".cs", StringComparison.OrdinalIgnoreCase) ||
assetPath.EndsWith(".dll", StringComparison.OrdinalIgnoreCase))
{
instance.onImportStarted(time);
}
}
}
#endregion
[Serializable]
public class CompilationEvent
{
public string name;
public string path;
// seconds
public double startTime;
public double endTime;
public double duration
{
get { return endTime - startTime; }
}
// milliseconds
public double startTimeMs
{
get { return startTime * 1000; }
}
public double endTimeMs
{
get { return endTime * 1000; }
}
public double durationMs
{
get { return duration * 1000; }
}
// microseconds
public long startTimeUs
{
get { return (long) (startTime * 1000000); }
}
public long endTimeUs
{
get { return (long) (endTime * 1000000); }
}
public long durationUs
{
get { return (long) (duration * 1000000); }
}
public ChromeTrace.Event toChromeEvent()
{
return new ChromeTrace.Event
{
name = name,
ph = "X", // 'Complete' event
ts = startTimeUs,
dur = durationUs,
args = new ChromeTrace.Event.Args
{
ms = durationMs,
}
};
}
}
public CompilationEvent import;
public List<CompilationEvent> assemblies;
public CompilationEvent reload;
void init()
{
import = new CompilationEvent { name = "import" };
assemblies = new List<CompilationEvent>();
reload = new CompilationEvent { name = "reload" };
}
void onImportStarted( double time )
{
if (import.startTime <= 0)
{
import.startTime = time;
}
}
void onImportFinished( double time )
{
if (import.endTime <= 0)
{
import.endTime = time;
if (logLevel == LogLevel.Verbose)
{
Debug.LogFormat("script import took {0:n2} s", import.duration);
}
}
}
void onAssemblyCompilationStarted( string assemblyPath )
{
double time = EditorApplication.timeSinceStartup;
onImportFinished(time); // first time a compilation starts means import is done
assemblies.Add(new CompilationEvent
{
name = assemblyPath.Replace("Library/ScriptAssemblies/", ""),
path = assemblyPath,
startTime = time,
});
}
void onAssemblyCompilationFinished( string assemblyPath )
{
double time = EditorApplication.timeSinceStartup;
var assembly = assemblies.Find(a => a.path == assemblyPath);
if (assembly != null)
{
assembly.endTime = time;
if (logLevel == LogLevel.Verbose)
{
Debug.LogFormat("compilation of {0} took {1:n2} s", assembly.name, assembly.duration);
}
}
}
void onBeforeAssemblyReload()
{
double time = EditorApplication.timeSinceStartup;
reload.startTime = time;
}
void onAfterAssemblyReload()
{
double time = EditorApplication.timeSinceStartup;
reload.endTime = time;
int assemblyCount = assemblies.Count;
if (reload.startTime <= 0 && assemblyCount <= 0)
{
return;
}
if (logLevel >= LogLevel.Low)
{
StringBuilder msg = new StringBuilder();
var startTime = import.startTime > 0 ? import.startTime
: assemblyCount > 0 ? assemblies[0].startTime
: reload.startTime;
msg.AppendFormat("completed reimport {0:n2} s\n", time - startTime);
msg.AppendFormat(" import {0:n2} s\n", import.duration);
msg.Append(" compilation ");
if (assemblyCount > 0)
{
msg.AppendFormat("{0:n2} s ({1} assembl{2})",
assemblies[assemblyCount - 1].endTime - assemblies[0].startTime,
assemblyCount, assemblyCount > 1 ? "ies" : "y");
}
else
{
msg.Append("no assembly was recompiled");
}
msg.AppendLine();
msg.AppendFormat(" domain reload {0:n2} s\n", reload.duration);
Debug.Log(msg);
}
if (assemblyCount > 0 && shouldDumpTrace)
{
dumpChromeTrace();
}
init(); // clear
}
void dumpChromeTrace()
{
// dump the compilation times to a json chrome trace to get a profiler timeline
// https://aras-p.info/blog/2017/01/23/Chrome-Tracing-as-Profiler-Frontend/
int assemblyCount = assemblies.Count;
ChromeTrace trace;
trace.meta_user = Environment.UserName;
trace.meta_cpu_count = SystemInfo.processorCount.ToString();
var events = trace.traceEvents = new ChromeTrace.Event[assemblyCount + 2];
events[0] = import.toChromeEvent();
events[assemblyCount + 1] = reload.toChromeEvent();
List<double> threads = new List<double>();
for (int i = 0; i < assemblyCount; i++)
{
var evt = assemblies[i].toChromeEvent();
// assign each event to a timeline lane:
// Unity can fire off several mono compilers in parallel,
// but the actual thread id can't be inferred from the assemblyCompilation callbacks
// -> compare the start/end time to guess which thread each event comes from.
bool found = false;
for (int iT = 0; iT < threads.Count; iT++)
{
if (threads[iT] < assemblies[i].startTime)
{
evt.tid = iT;
threads[iT] = assemblies[i].endTime;
found = true;
break;
}
}
if (!found)
{
evt.tid = threads.Count;
threads.Add(assemblies[i].endTime);
}
events[i + 1] = evt;
}
//Debug.Log(JsonUtility.ToJson(trace, true));
File.WriteAllText("compilationTrace.json", JsonUtility.ToJson(trace, true));
}
[Serializable]
public struct ChromeTrace
{
[Serializable]
public struct Event
{
public int pid;
public int tid;
public long ts;
public long dur;
public string ph;
public string name;
[Serializable]
public struct Args
{
public double ms;
}
public Args args;
}
public Event[] traceEvents;
public string meta_user;
public string meta_cpu_count;
}
}
}
@plucked
Copy link

plucked commented Feb 11, 2019

awesome! Thank you

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment