using System;
using System.Diagnostics;
using System.Collections.Generic;
using System.Text;
using System.Linq;
namespace Ink.Runtime
{
/// <summary>
/// Simple ink profiler that logs every instruction in the story and counts frequency and timing.
/// To use:
///
/// var profiler = story.StartProfiling(),
///
/// (play your story for a bit)
///
/// var reportStr = profiler.Report();
///
/// story.EndProfiling();
///
/// </summary>
public class Profiler
{
/// <summary>
/// The root node in the hierarchical tree of recorded ink timings.
/// </summary>
public ProfileNode rootNode {
get {
return _rootNode;
}
}
public Profiler() {
_rootNode = new ProfileNode();
}
/// <summary>
/// Generate a printable report based on the data recording during profiling.
/// </summary>
public string Report() {
var sb = new StringBuilder();
sb.AppendFormat("{0} CONTINUES / LINES:\n", _numContinues);
sb.AppendFormat("TOTAL TIME: {0}\n", FormatMillisecs(_continueTotal));
sb.AppendFormat("SNAPSHOTTING: {0}\n", FormatMillisecs(_snapTotal));
sb.AppendFormat("OTHER: {0}\n", FormatMillisecs(_continueTotal - (_stepTotal + _snapTotal)));
sb.Append(_rootNode.ToString());
return sb.ToString();
}
public void PreContinue() {
_continueWatch.Reset();
_continueWatch.Start();
}
public void PostContinue() {
_continueWatch.Stop();
_continueTotal += Millisecs(_continueWatch);
_numContinues++;
}
public void PreStep() {
_currStepStack = null;
_stepWatch.Reset();
_stepWatch.Start();
}
public void Step(CallStack callstack)
{
_stepWatch.Stop();
var stack = new string[callstack.elements.Count];
for(int i=0; i<stack.Length; i++) {
string stackElementName = "";
if(!callstack.elements[i].currentPointer.isNull) {
var objPath = callstack.elements[i].currentPointer.path;
for(int c=0; c<objPath.length; c++) {
var comp = objPath.GetComponent(c);
if( !comp.isIndex ) {
stackElementName = comp.name;
break;
}
}
}
stack[i] = stackElementName;
}
_currStepStack = stack;
var currObj = callstack.currentElement.currentPointer.Resolve();
string stepType = null;
var controlCommandStep = currObj as ControlCommand;
if( controlCommandStep )
stepType = controlCommandStep.commandType.ToString() + " CC";
else
stepType = currObj.GetType().Name;
_currStepDetails = new StepDetails {
type = stepType,
obj = currObj
};
_stepWatch.Start();
}
public void PostStep() {
_stepWatch.Stop();
var duration = Millisecs(_stepWatch);
_stepTotal += duration;
_rootNode.AddSample(_currStepStack, duration);
_currStepDetails.time = duration;
_stepDetails.Add(_currStepDetails);
}
/// <summary>
/// Generate a printable report specifying the average and maximum times spent
/// stepping over different internal ink instruction types.
/// This report type is primarily used to profile the ink engine itself rather
/// than your own specific ink.
/// </summary>
public string StepLengthReport()
{
var sb = new StringBuilder();
sb.AppendLine("TOTAL: "+_rootNode.totalMillisecs+"ms");
var averageStepTimes = _stepDetails
.GroupBy(s => s.type)
.Select(typeToDetails => new KeyValuePair<string, double>(typeToDetails.Key, typeToDetails.Average(d => d.time)))
.OrderByDescending(stepTypeToAverage => stepTypeToAverage.Value)
.Select(stepTypeToAverage => {
var typeName = stepTypeToAverage.Key;
var time = stepTypeToAverage.Value;
return typeName + ": " + time + "ms";
})
.ToArray();
sb.AppendLine("AVERAGE STEP TIMES: "+string.Join(", ", averageStepTimes));
var accumStepTimes = _stepDetails
.GroupBy(s => s.type)
.Select(typeToDetails => new KeyValuePair<string, double>(typeToDetails.Key + " (x"+typeToDetails.Count()+")", typeToDetails.Sum(d => d.time)))
.OrderByDescending(stepTypeToAccum => stepTypeToAccum.Value)
.Select(stepTypeToAccum => {
var typeName = stepTypeToAccum.Key;
var time = stepTypeToAccum.Value;
return typeName + ": " + time;
})
.ToArray();
sb.AppendLine("ACCUMULATED STEP TIMES: "+string.Join(", ", accumStepTimes));
return sb.ToString();
}
/// <summary>
/// Create a large log of all the internal instructions that were evaluated while profiling was active.
/// Log is in a tab-separated format, for easy loading into a spreadsheet application.
/// </summary>
public string Megalog()
{
var sb = new StringBuilder();
sb.AppendLine("Step type\tDescription\tPath\tTime");
foreach(var step in _stepDetails) {
sb.Append(step.type);
sb.Append("\t");
sb.Append(step.obj.ToString());
sb.Append("\t");
sb.Append(step.obj.path);
sb.Append("\t");
sb.AppendLine(step.time.ToString("F8"));
}
return sb.ToString();
}
public void PreSnapshot() {
_snapWatch.Reset();
_snapWatch.Start();
}
public void PostSnapshot() {
_snapWatch.Stop();
_snapTotal += Millisecs(_snapWatch);
}
double Millisecs(Stopwatch watch)
{
var ticks = watch.ElapsedTicks;
return ticks * _millisecsPerTick;
}
public static string FormatMillisecs(double num) {
if( num > 5000 ) {
return string.Format("{0:N1} secs", num / 1000.0);
} if( num > 1000 ) {
return string.Format("{0:N2} secs", num / 1000.0);
} else if( num > 100 ) {
return string.Format("{0:N0} ms", num);
} else if( num > 1 ) {
return string.Format("{0:N1} ms", num);
} else if( num > 0.01 ) {
return string.Format("{0:N3} ms", num);
} else {
return string.Format("{0:N} ms", num);
}
}
Stopwatch _continueWatch = new Stopwatch();
Stopwatch _stepWatch = new Stopwatch();
Stopwatch _snapWatch = new Stopwatch();
double _continueTotal;
double _snapTotal;
double _stepTotal;
string[] _currStepStack;
StepDetails _currStepDetails;
ProfileNode _rootNode;
int _numContinues;
struct StepDetails {
public string type;
public Runtime.Object obj;
public double time;
}
List<StepDetails> _stepDetails = new List<StepDetails>();
static double _millisecsPerTick = 1000.0 / Stopwatch.Frequency;
}
/// <summary>
/// Node used in the hierarchical tree of timings used by the Profiler.
/// Each node corresponds to a single line viewable in a UI-based representation.
/// </summary>
public class ProfileNode {
/// <summary>
/// The key for the node corresponds to the printable name of the callstack element.
/// </summary>
public readonly string key;
#pragma warning disable 0649
/// <summary>
/// Horribly hacky field only used by ink unity integration,
/// but saves constructing an entire data structure that mirrors
/// the one in here purely to store the state of whether each
/// node in the UI has been opened or not /// </summary>
public bool openInUI;
#pragma warning restore 0649
/// <summary>
/// Whether this node contains any sub-nodes - i.e. does it call anything else
/// that has been recorded?
/// </summary>
/// <value><c>true</c> if has children; otherwise, <c>false</c>.</value>
public bool hasChildren {
get {
return _nodes != null && _nodes.Count > 0;
}
}
/// <summary>
/// Total number of milliseconds this node has been active for.
/// </summary>
public int totalMillisecs {
get {
return (int)_totalMillisecs;
}
}
public ProfileNode() {
}
public ProfileNode(string key) {
this.key = key;
}
public void AddSample(string[] stack, double duration) {
AddSample(stack, -1, duration);
}
void AddSample(string[] stack, int stackIdx, double duration) {
_totalSampleCount++;
_totalMillisecs += duration;
if( stackIdx == stack.Length-1 ) {
_selfSampleCount++;
_selfMillisecs += duration;
}
if( stackIdx+1 < stack.Length )
AddSampleToNode(stack, stackIdx+1, duration);
}
void AddSampleToNode(string[] stack, int stackIdx, double duration)
{
var nodeKey = stack[stackIdx];
if( _nodes == null ) _nodes = new Dictionary<string, ProfileNode>();
ProfileNode node;
if( !_nodes.TryGetValue(nodeKey, out node) ) {
node = new ProfileNode(nodeKey);
_nodes[nodeKey] = node;
}
node.AddSample(stack, stackIdx, duration);
}
/// <summary>
/// Returns a sorted enumerable of the nodes in descending order of
/// how long they took to run.
/// </summary>
public IEnumerable<KeyValuePair<string, ProfileNode>> descendingOrderedNodes {
get {
if( _nodes == null ) return null;
return _nodes.OrderByDescending(keyNode => keyNode.Value._totalMillisecs);
}
}
void PrintHierarchy(StringBuilder sb, int indent)
{
Pad(sb, indent);
sb.Append(key);
sb.Append(": ");
sb.AppendLine(ownReport);
if( _nodes == null ) return;
foreach(var keyNode in descendingOrderedNodes) {
keyNode.Value.PrintHierarchy(sb, indent+1);
}
}
/// <summary>
/// Generates a string giving timing information for this single node, including
/// total milliseconds spent on the piece of ink, the time spent within itself
/// (v.s. spent in children), as well as the number of samples (instruction steps)
/// recorded for both too.
/// </summary>
/// <value>The own report.</value>
public string ownReport {
get {
var sb = new StringBuilder();
sb.Append("total ");
sb.Append(Profiler.FormatMillisecs(_totalMillisecs));
sb.Append(", self ");
sb.Append(Profiler.FormatMillisecs(_selfMillisecs));
sb.Append(" (");
sb.Append(_selfSampleCount);
sb.Append(" self samples, ");
sb.Append(_totalSampleCount);
sb.Append(" total)");
return sb.ToString();
}
}
void Pad(StringBuilder sb, int spaces)
{
for(int i=0; i<spaces; i++) sb.Append(" ");
}
/// <summary>
/// String is a report of the sub-tree from this node, but without any of the header information
/// that's prepended by the Profiler in its Report() method.
/// </summary>
public override string ToString ()
{
var sb = new StringBuilder();
PrintHierarchy(sb, 0);
return sb.ToString();
}
Dictionary<string, ProfileNode> _nodes;
double _selfMillisecs;
double _totalMillisecs;
int _selfSampleCount;
int _totalSampleCount;
}
}
