// 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;
using UnityEngine.SceneManagement;
namespace Unity.MLAgents
{
[DataContract]
internal 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;
///
/// 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.
}
///
/// 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;
}
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;
}
}
[DataContract]
internal class RootNode : TimerNode
{
// Timer output format version
internal const string k_TimerFormatVersion = "0.1.0";
[DataMember(Name = "metadata", Order = 0)]
Dictionary m_Metadata = new Dictionary();
///
/// Gauge Nodes to measure arbitrary values.
///
[DataMember(Name = "gauges", EmitDefaultValue = false)]
Dictionary m_Gauges = new Dictionary();
public RootNode(string name="root") : base(name, true)
{
m_Metadata.Add("timer_format_version", k_TimerFormatVersion);
m_Metadata.Add("start_time_seconds", $"{DateTimeOffset.Now.ToUnixTimeSeconds()}");
m_Metadata.Add("unity_version", Application.unityVersion);
m_Metadata.Add("command_line_arguments", String.Join(" ", Environment.GetCommandLineArgs()));
}
public void AddMetadata(string key, string value)
{
m_Metadata[key] = value;
}
public Dictionary Gauges
{
get { return m_Gauges; }
}
public Dictionary Metadata
{
get { return m_Metadata; }
}
}
///
/// Tracks the most recent value of a metric. This is analogous to gauges in statsd and Prometheus.
///
[DataContract]
internal class GaugeNode
{
const float k_SmoothingFactor = .25f; // weight for exponential moving average.
///
/// The most recent value that the gauge was set to.
///
[DataMember]
public float value;
///
/// The smallest value that has been seen for the gauge since it was created.
///
[DataMember(Name = "min")]
public float minValue;
///
/// The largest value that has been seen for the gauge since it was created.
///
[DataMember(Name = "max")]
public float maxValue;
///
/// The exponential moving average of the gauge value. This will take all values into account,
/// but weights older values less as more values are added.
///
[DataMember(Name = "weightedAverage")]
public float weightedAverage;
///
/// The running average of all gauge values.
///
[DataMember]
public float runningAverage;
///
/// The number of times the gauge has been updated.
///
[DataMember]
public uint count;
public GaugeNode(float value)
{
this.value = value;
weightedAverage = value;
runningAverage = value;
minValue = value;
maxValue = value;
count = 1;
}
public void Update(float newValue)
{
++count;
minValue = Mathf.Min(minValue, newValue);
maxValue = Mathf.Max(maxValue, newValue);
// update exponential moving average
weightedAverage = (k_SmoothingFactor * newValue) + ((1f - k_SmoothingFactor) * weightedAverage);
value = newValue;
// Update running average - see https://www.johndcook.com/blog/standard_deviation/ for formula.
runningAverage = runningAverage + (newValue - runningAverage) / 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
///
internal class TimerStack : IDisposable
{
static readonly TimerStack k_Instance = new TimerStack();
Stack m_Stack;
RootNode m_RootNode;
Dictionary m_Metadata;
// Explicit static constructor to tell C# compiler
// not to mark type as beforefieldinit
static TimerStack()
{
}
TimerStack()
{
Reset();
}
///
/// Resets the timer stack and the root node.
///
/// Name of the root node.
public void Reset(string name = "root")
{
m_Stack = new Stack();
m_RootNode = new RootNode(name);
m_Stack.Push(m_RootNode);
}
///
/// The singleton instance.
///
public static TimerStack Instance
{
get { return k_Instance; }
}
internal RootNode RootNode
{
get { return m_RootNode; }
}
///
/// Updates the referenced gauge in the root node with the provided value.
///
/// The name of the Gauge to modify.
/// The value to update the Gauge with.
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);
}
}
}
public void AddMetadata(string key, string value)
{
m_RootNode.AddMetadata(key, 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.
///
///
internal 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 UNITY_EDITOR || UNITY_STANDALONE_WIN || UNITY_STANDALONE_OSX || UNITY_STANDALONE_LINUX
try
{
if (filename == null)
{
var activeScene = SceneManager.GetActiveScene();
var timerDir = Path.Combine(Application.dataPath, "ML-Agents", "Timers");
Directory.CreateDirectory(timerDir);
filename = Path.Combine(timerDir, $"{activeScene.name}_timers.json");
}
var fs = new FileStream(filename, FileMode.Create, FileAccess.Write);
SaveJsonTimers(fs);
fs.Close();
}
catch (IOException)
{
// It's possible we don't have write access to the directory.
Debug.LogWarning($"Unable to save timers to file {filename}");
}
#endif
}
///
/// Write the timers in JSON format to the provided stream.
///
///
public void SaveJsonTimers(Stream stream)
{
// Add some final metadata info
AddMetadata("scene_name", SceneManager.GetActiveScene().name);
AddMetadata("end_time_seconds", $"{DateTimeOffset.Now.ToUnixTimeSeconds()}");
var jsonSettings = new DataContractJsonSerializerSettings();
jsonSettings.UseSimpleDictionaryFormat = true;
var ser = new DataContractJsonSerializer(typeof(RootNode), jsonSettings);
ser.WriteObject(stream, m_RootNode);
}
}
}