using System; using System.Collections.Generic; using System.Diagnostics; using System.Globalization; using System.Text; using System.Threading; using UnityEditor.Build.Pipeline.Interfaces; namespace UnityEditor.Build.Pipeline.Utilities { /// /// Basic implementation of IBuildLogger. Stores events in memory and can dump them to the trace event format. /// /// [Serializable] public class BuildLog : IBuildLogger, IDeferredBuildLogger { [Serializable] internal struct LogEntry { public int ThreadId { get; set; } public double Time { get; set; } public LogLevel Level { get; set; } public string Message { get; set; } } [Serializable] internal class LogStep { List m_Children; List m_Entries; public string Name { get; set; } public LogLevel Level { get; set; } public List Children { get { if (m_Children == null) m_Children = new List(); return m_Children; } } public List Entries { get { if (m_Entries == null) m_Entries = new List(); return m_Entries; } } public double DurationMS { get; private set; } public int ThreadId { get; set; } public double StartTime { get; set; } internal bool isThreaded; public bool HasChildren { get { return Children != null && Children.Count > 0; } } public bool HasEntries { get { return Entries != null && Entries.Count > 0; } } internal void Complete(double time) { DurationMS = time - StartTime; } } LogStep m_Root; [NonSerialized] Stack m_Stack; [NonSerialized] ThreadLocal m_ThreadedLogs; [NonSerialized] Stopwatch m_WallTimer; bool m_ShouldOverrideWallTimer; double m_WallTimerOverride; double GetWallTime() { return m_ShouldOverrideWallTimer ? m_WallTimerOverride : m_WallTimer.Elapsed.TotalMilliseconds; } void Init(bool onThread) { m_WallTimer = Stopwatch.StartNew(); m_Root = new LogStep(); m_Stack = new Stack(); m_Stack.Push(m_Root); AddMetaData("Date", DateTime.Now.ToString()); if (!onThread) { AddMetaData("UnityVersion", UnityEngine.Application.unityVersion); #if UNITY_2019_2_OR_NEWER // PackageManager package inspection APIs didn't exist until 2019.2 PackageManager.PackageInfo info = PackageManager.PackageInfo.FindForAssembly(typeof(BuildLog).Assembly); if (info != null) AddMetaData(info.name, info.version); #endif } } /// /// Creates a new build log object. /// public BuildLog() { Init(false); } internal BuildLog(bool onThread) { Init(onThread); } private BuildLog GetThreadSafeLog() { if (m_ThreadedLogs != null) { if (!m_ThreadedLogs.IsValueCreated) m_ThreadedLogs.Value = new BuildLog(true); return m_ThreadedLogs.Value; } return this; } /// public void BeginBuildStep(LogLevel level, string stepName, bool multiThreaded) { BuildLog log = GetThreadSafeLog(); BeginBuildStepInternal(log, level, stepName, multiThreaded); } private static void BeginBuildStepInternal(BuildLog log, LogLevel level, string stepName, bool multiThreaded) { LogStep node = new LogStep(); node.Level = level; node.Name = stepName; node.StartTime = log.GetWallTime(); node.ThreadId = Thread.CurrentThread.ManagedThreadId; log.m_Stack.Peek().Children.Add(node); log.m_Stack.Push(node); if (multiThreaded) { Debug.Assert(log.m_ThreadedLogs == null); log.m_ThreadedLogs = new ThreadLocal(true); log.m_ThreadedLogs.Value = log; node.isThreaded = true; } } /// public void EndBuildStep() { EndBuildStepInternal(GetThreadSafeLog()); } private static void OffsetTimesR(LogStep step, double offset) { step.StartTime += offset; if (step.HasEntries) { for (int i = 0; i < step.Entries.Count; i++) { LogEntry e = step.Entries[i]; e.Time = e.Time + offset; step.Entries[i] = e; } } if (step.HasChildren) foreach (LogStep subStep in step.Children) OffsetTimesR(subStep, offset); } private static void EndBuildStepInternal(BuildLog log) { Debug.Assert(log.m_Stack.Count > 1); LogStep node = log.m_Stack.Pop(); node.Complete(log.GetWallTime()); if (node.isThreaded) { foreach (BuildLog subLog in log.m_ThreadedLogs.Values) { if (subLog != log) { OffsetTimesR(subLog.Root, node.StartTime); if (subLog.Root.HasChildren) node.Children.AddRange(subLog.Root.Children); if (subLog.Root.HasEntries) node.Entries.AddRange(subLog.Root.Entries); } } log.m_ThreadedLogs.Dispose(); log.m_ThreadedLogs = null; } } internal LogStep Root { get { return m_Root; } } /// public void AddEntry(LogLevel level, string msg) { BuildLog log = GetThreadSafeLog(); log.m_Stack.Peek().Entries.Add(new LogEntry() { Level = level, Message = msg, Time = log.GetWallTime(), ThreadId = Thread.CurrentThread.ManagedThreadId }); } /// /// Internal use only. /// /// /// Event collection to handle void IDeferredBuildLogger.HandleDeferredEventStream(IEnumerable events) { HandleDeferredEventStreamInternal(events); } internal void HandleDeferredEventStreamInternal(IEnumerable events) { // now make all those times relative to the active event LogStep startStep = m_Stack.Peek(); m_ShouldOverrideWallTimer = true; foreach (DeferredEvent e in events) { m_WallTimerOverride = e.Time + startStep.StartTime; if (e.Type == DeferredEventType.Begin) { BeginBuildStep(e.Level, e.Name, false); if (!string.IsNullOrEmpty(e.Context)) AddEntry(e.Level, e.Context); } else if (e.Type == DeferredEventType.End) EndBuildStep(); else AddEntry(e.Level, e.Name); } m_ShouldOverrideWallTimer = false; LogStep stopStep = m_Stack.Peek(); if (stopStep != startStep) throw new Exception("Deferred events did not line up as expected"); } static void AppendLineIndented(StringBuilder builder, int indentCount, string text) { for (int i = 0; i < indentCount; i++) builder.Append(" "); builder.AppendLine(text); } static void PrintNodeR(bool includeSelf, StringBuilder builder, int indentCount, BuildLog.LogStep node) { if (includeSelf) AppendLineIndented(builder, indentCount, $"[{node.Name}] {node.DurationMS * 1000}us"); foreach (var msg in node.Entries) { string line = (msg.Level == LogLevel.Warning || msg.Level == LogLevel.Error) ? $"{msg.Level}: {msg.Message}" : msg.Message; AppendLineIndented(builder, indentCount + 1, line); } foreach (var child in node.Children) PrintNodeR(true, builder, indentCount + 1, child); } internal string FormatAsText() { using (new CultureScope()) { StringBuilder builder = new StringBuilder(); PrintNodeR(false, builder, -1, Root); return builder.ToString(); } } static string CleanJSONText(string message) { return message.Replace("\\", "\\\\"); } static IEnumerable IterateTEPLines(bool includeSelf, BuildLog.LogStep node) { ulong us = (ulong)(node.StartTime * 1000); string argText = string.Empty; if (node.Entries.Count > 0) { StringBuilder builder = new StringBuilder(); builder.Append(", \"args\": {"); for (int i = 0; i < node.Entries.Count; i++) { string line = (node.Entries[i].Level == LogLevel.Warning || node.Entries[i].Level == LogLevel.Error) ? $"{node.Entries[i].Level}: {node.Entries[i].Message}" : node.Entries[i].Message; builder.Append($"\"{i}\":\"{CleanJSONText(line)}\""); if (i < (node.Entries.Count - 1)) builder.Append(", "); } builder.Append("}"); argText = builder.ToString(); } if (includeSelf) yield return "{" + $"\"name\": \"{CleanJSONText(node.Name)}\", \"ph\": \"X\", \"dur\": {node.DurationMS * 1000}, \"tid\": {node.ThreadId}, \"ts\": {us}, \"pid\": 1" + argText + "}"; foreach (var child in node.Children) foreach (var r in IterateTEPLines(true, child)) yield return r; } class CultureScope : IDisposable { CultureInfo m_Prev; public CultureScope() { m_Prev = Thread.CurrentThread.CurrentCulture; Thread.CurrentThread.CurrentCulture = CultureInfo.InvariantCulture; } public void Dispose() { Thread.CurrentThread.CurrentCulture = m_Prev; } } private List> m_MetaData = new List>(); /// /// Adds a key value pair to the MetaData list. This can be used to store things like package version numbers. /// /// The key for the MetaData. /// The value of the MetaData. public void AddMetaData(string key, string value) { m_MetaData.Add(new Tuple(key, value)); } /// /// Converts the captured build log events into the text Trace Event Profiler format /// /// Profile data. public string FormatForTraceEventProfiler() { using (new CultureScope()) { StringBuilder builder = new StringBuilder(); builder.AppendLine("{"); foreach (Tuple tuple in m_MetaData) builder.AppendLine($"\"{tuple.Item1}\": \"{tuple.Item2}\","); builder.AppendLine("\"traceEvents\": ["); int i = 0; foreach (string line in IterateTEPLines(false, Root)) { if (i != 0) builder.Append(","); builder.AppendLine(line); i++; } builder.AppendLine("]"); builder.AppendLine("}"); return builder.ToString(); } } } }