// Compile with: csc CRefTest.cs -doc:Results.xml using System; using UnityEngine; using System.Collections.Generic; using System.IO; using UnityEngine.Profiling; using System.Runtime.Serialization; using System.Runtime.Serialization.Json; namespace MLAgents { [DataContract] public class TimerNode { static string s_Separator = "."; static double s_TicksToSeconds = 1e-7; // 100 ns per tick /// /// Full name of the node. This is the node's parents full name concatenated with this node's name /// string m_FullName; /// /// Child nodes, indexed by name. /// [DataMember(Name = "children", Order = 999)] Dictionary m_Children; /// /// Gauge Nodes to measure arbitrary values. /// [DataMember(Name = "gauges", EmitDefaultValue = false)] Dictionary m_Gauges; /// /// Custom sampler used to add timings to the profiler. /// CustomSampler m_Sampler; /// /// Number of total ticks elapsed for this node. /// long m_TotalTicks; /// /// If the node is currently running, the time (in ticks) when the node was started. /// If the node is not running, is set to 0. /// long m_TickStart; /// /// Number of times the corresponding code block has been called. /// [DataMember(Name = "count")] int m_NumCalls; /// /// The total recorded ticks for the timer node, plus the currently elapsed ticks /// if the timer is still running (i.e. if m_TickStart is non-zero). /// public long CurrentTicks { get { var currentTicks = m_TotalTicks; if (m_TickStart != 0) { currentTicks += (DateTime.Now.Ticks - m_TickStart); } return currentTicks; } } /// /// Total elapsed seconds. /// [DataMember(Name = "total")] public double TotalSeconds { get { return CurrentTicks * s_TicksToSeconds; } set {} // Serialization needs this, but unused. } public Dictionary Gauges { get { return m_Gauges; } } /// /// Total seconds spent in this block, excluding it's children. /// [DataMember(Name = "self")] public double SelfSeconds { get { long totalChildTicks = 0; if (m_Children != null) { foreach (var child in m_Children.Values) { totalChildTicks += child.m_TotalTicks; } } var selfTicks = Mathf.Max(0, CurrentTicks - totalChildTicks); return selfTicks * s_TicksToSeconds; } set {} // Serialization needs this, but unused. } public IReadOnlyDictionary Children { get { return m_Children; } } public int NumCalls { get { return m_NumCalls; } } public TimerNode(string name, bool isRoot = false) { m_FullName = name; if (isRoot) { // The root node is considered always running. This means that when we output stats, it'll // have a sensible value for total time (the running time since reset). // The root node doesn't have a sampler since that could interfere with the profiler. m_NumCalls = 1; m_TickStart = DateTime.Now.Ticks; m_Gauges = new Dictionary(); } else { m_Sampler = CustomSampler.Create(m_FullName); } } /// /// Start timing a block of code. /// public void Begin() { m_Sampler?.Begin(); m_TickStart = DateTime.Now.Ticks; } /// /// Stop timing a block of code, and increment internal counts. /// public void End() { var elapsed = DateTime.Now.Ticks - m_TickStart; m_TotalTicks += elapsed; m_TickStart = 0; m_NumCalls++; m_Sampler?.End(); } /// /// Return a child node for the given name. /// The children dictionary will be created if it does not already exist, and /// a new Node will be created if it's not already in the dictionary. /// Note that these allocations only happen once for a given timed block. /// /// /// public TimerNode GetChild(string name) { // Lazily create the children dictionary. if (m_Children == null) { m_Children = new Dictionary(); } if (!m_Children.ContainsKey(name)) { var childFullName = m_FullName + s_Separator + name; var newChild = new TimerNode(childFullName); m_Children[name] = newChild; return newChild; } return m_Children[name]; } /// /// Recursively form a string representing the current timer information. /// /// /// /// public string DebugGetTimerString(string parentName = "", int level = 0) { var indent = new string(' ', 2 * level); // TODO generalize var shortName = (level == 0) ? m_FullName : m_FullName.Replace(parentName + s_Separator, ""); string timerString; if (level == 0) { timerString = $"{shortName}(root)\n"; } else { timerString = $"{indent}{shortName}\t\traw={TotalSeconds} rawCount={m_NumCalls}\n"; } // TODO use StringBuilder? might be overkill since this is only debugging code? if (m_Children != null) { foreach (var c in m_Children.Values) { timerString += c.DebugGetTimerString(m_FullName, level + 1); } } return timerString; } } /// /// Tracks the most recent value of a metric. This is analogous to gauges in statsd. /// [DataContract] public class GaugeNode { [DataMember] public float value; [DataMember( Name = "min")] public float minValue; [DataMember( Name = "max")] public float maxValue; [DataMember] public uint count; public GaugeNode(float value) { this.value = value; minValue = value; maxValue = value; count = 1; } public void Update(float newValue) { minValue = Mathf.Min(minValue, newValue); maxValue = Mathf.Max(maxValue, newValue); value = newValue; ++count; } } /// /// A "stack" of timers that allows for lightweight hierarchical profiling of long-running processes. /// /// Example usage: /// /// using(TimerStack.Instance.Scoped("foo")) /// { /// doSomeWork(); /// for (int i=0; i<5; i++) /// { /// using(myTimer.Scoped("bar")) /// { /// doSomeMoreWork(); /// } /// } /// } /// /// /// /// /// This implements the Singleton pattern (solution 4) as described in /// https://csharpindepth.com/articles/singleton /// public class TimerStack : IDisposable { static readonly TimerStack k_Instance = new TimerStack(); Stack m_Stack; TimerNode m_RootNode; // Explicit static constructor to tell C# compiler // not to mark type as beforefieldinit static TimerStack() { } TimerStack() { Reset(); } public void Reset(string name = "root") { m_Stack = new Stack(); m_RootNode = new TimerNode(name, true); m_Stack.Push(m_RootNode); } public static TimerStack Instance { get { return k_Instance; } } public TimerNode RootNode { get { return m_RootNode; } } public void SetGauge(string name, float value) { if (!float.IsNaN(value)) { GaugeNode gauge; if (m_RootNode.Gauges.TryGetValue(name, out gauge)) { gauge.Update(value); } else { m_RootNode.Gauges[name] = new GaugeNode(value); } } } void Push(string name) { var current = m_Stack.Peek(); var next = current.GetChild(name); m_Stack.Push(next); next.Begin(); } void Pop() { var node = m_Stack.Pop(); node.End(); } /// /// Start a scoped timer. This should be used with the "using" statement. /// /// /// public TimerStack Scoped(string name) { Push(name); return this; } /// /// Closes the current scoped timer. This should never be called directly, only /// at the end of a "using" statement. /// Note that the instance is not actually disposed of; this is just to allow it to be used /// conveniently with "using". /// public void Dispose() { Pop(); } /// /// Get a string representation of the timers. /// Potentially slow so call sparingly. /// /// public string DebugGetTimerString() { return m_RootNode.DebugGetTimerString(); } /// /// Save the timers in JSON format to the provided filename. /// If the filename is null, a default one will be used. /// /// public void SaveJsonTimers(string filename = null) { if (filename == null) { var fullpath = Path.GetFullPath("."); filename = $"{fullpath}/csharp_timers.json"; } var fs = new FileStream(filename, FileMode.Create, FileAccess.Write); SaveJsonTimers(fs); fs.Close(); } /// /// Write the timers in JSON format to the provided stream. /// /// public void SaveJsonTimers(Stream stream) { var jsonSettings = new DataContractJsonSerializerSettings(); jsonSettings.UseSimpleDictionaryFormat = true; var ser = new DataContractJsonSerializer(typeof(TimerNode), jsonSettings); ser.WriteObject(stream, m_RootNode); } } }