Created
February 11, 2019 11:47
-
-
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.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
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; | |
} | |
} | |
} |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
awesome! Thank you