public void AddEventStopCallback(TraceSourceManager source, DynamicTraceEventParser dynamicParser, string provider)
{
// For some crossgen2 events (ex: jitting), there could be multiple start&stop pairs within one process, thus we sum up
// time elapsed between each pair as the interval of this event.
dynamicParser.AddCallbackForProviderEvent(provider, $"{EventName}/Stop", evt =>
{
if (Pid.HasValue && ParserUtility.MatchSingleProcessID(evt, source, (int)Pid))
{
// Get time elapsed for this pair of start&stop events
double interval = evt.TimeStampRelativeMSec - Start;
// If previous pid exists, this is the same process and time elapsed is added to the last value in the stack.
if (PrevPid.HasValue && ParserUtility.MatchSingleProcessID(evt, source, (int)PrevPid))
{
double lastValue = Intervals.Pop();
Intervals.Push(lastValue + interval);
}
// If previous pid doesn't exist, this is the next process and time elapsed is a new value pushed to the stack.
else
{
Intervals.Push(interval);
}
Start = 0;
PrevPid = Pid;
Pid = null;
}
});
}
public IEnumerable <Counter> Parse(string mergeTraceFile, string processName, IList <int> pids, string commandLine)
{
var results = new List <double>();
var reloadResults = new List <double>();
var ins = new Dictionary <int, double>();
double start = -1;
int? pid = null;
using (var source = new TraceSourceManager(mergeTraceFile))
{
source.Kernel.ProcessStart += evt =>
{
if (!pid.HasValue && ParserUtility.MatchProcessStart(evt, source, processName, pids, commandLine))
{
Console.WriteLine("Process Start");
pid = evt.ProcessID;
start = evt.TimeStampRelativeMSec;
}
};
source.Source.Dynamic.AddCallbackForProviderEvent("HotReload", "HotReload/Start", evt =>
{
if (evt.PayloadStringByName("handlerType").ToLower() == "main")
{
if (pid.HasValue)
{
results.Add(evt.TimeStampRelativeMSec - start);
start = evt.TimeStampRelativeMSec;
}
}
});
source.Source.Dynamic.AddCallbackForProviderEvent("HotReload", "HotReloadEnd", evt =>
{
if (evt.PayloadStringByName("handlerType").ToLower() == "main")
{
if (pid.HasValue)
{
reloadResults.Add(evt.TimeStampRelativeMSec - start);
start = 0;
pid = null;
}
}
});
source.Process();
}
return(new[] {
new Counter()
{
Name = "Time to Hot Reload Start", MetricName = "ms", TopCounter = true, Results = results.ToArray()
},
new Counter()
{
Name = "Hot Reload Time", MetricName = "ms", TopCounter = true, DefaultCounter = true, Results = reloadResults.ToArray()
},
});
}
public IEnumerable <Counter> Parse(string mergeTraceFile, string processName, IList <int> pids, string commandLine)
{
var loadingParser = new EventParser("Loading", (1, 2));
var emittingParser = new EventParser("Emitting", (3, 4));
var compilationParser = new EventParser("Compilation", (5, 6));
var jittingParser = new EventParser("Jit", (7, 8));
using (var source = new TraceSourceManager(mergeTraceFile))
{
var dynamicParser = new DynamicTraceEventParser(source.Source);
var clrParser = new ClrTraceEventParser(source.Source);
loadingParser.AddStartStopCallbacks(source, dynamicParser, clrParser, ProviderName, pids);
emittingParser.AddStartStopCallbacks(source, dynamicParser, clrParser, ProviderName, pids);
compilationParser.AddStartStopCallbacks(source, dynamicParser, clrParser, ProviderName, pids);
jittingParser.AddStartStopCallbacks(source, dynamicParser, clrParser, ProviderName, pids);
source.Process();
}
var processTimeParser = new ProcessTimeParser();
Counter processTimeCounter = null;
if (!Util.IsWindows())
{
processName = "corerun";
}
foreach (var counter in processTimeParser.Parse(mergeTraceFile, processName, pids, commandLine))
{
if (counter.Name == "Process Time")
{
processTimeCounter = counter;
}
}
return(new[] {
processTimeCounter,
new Counter()
{
Name = "Loading Interval", MetricName = "ms", DefaultCounter = false, TopCounter = true, Results = loadingParser.Intervals.ToArray()
},
new Counter()
{
Name = "Emitting Interval", MetricName = "ms", DefaultCounter = false, TopCounter = true, Results = emittingParser.Intervals.ToArray()
},
new Counter()
{
Name = "Jit Interval", MetricName = "ms", DefaultCounter = false, TopCounter = true, Results = jittingParser.Intervals.ToArray()
},
new Counter()
{
Name = "Compilation Interval", MetricName = "ms", DefaultCounter = false, TopCounter = true, Results = compilationParser.Intervals.ToArray()
}
});
}
public void AddEventStartCallback(TraceSourceManager source, DynamicTraceEventParser dynamicParser, string provider, IList <int> pids)
{
dynamicParser.AddCallbackForProviderEvent(provider, $"{EventName}/Start", evt =>
{
if (!Pid.HasValue && ParserUtility.MatchProcessID(evt, source, pids))
{
Pid = evt.ProcessID;
Start = evt.TimeStampRelativeMSec;
}
});
}
public static bool MatchProcessID(TraceEvent evt, TraceSourceManager source, IList <int> pids)
{
if (!pids.Contains(evt.ProcessID))
{
return(CompareResult.Mismatch);
}
if (!source.IsWindows)
{
// For Linux both pid and tid should match
if (!pids.Contains((int)GetPayloadValue(evt, "PayloadThreadID")))
{
return(CompareResult.Mismatch);
}
}
return(CompareResult.Match);
}
public static bool MatchCommandLine(TraceEvent evt, TraceSourceManager source, string commandLine)
{
if (source.IsWindows)
{
if (!commandLine.Equals(((string)GetPayloadValue(evt, "CommandLine")).Trim()))
{
return(CompareResult.Mismatch);
}
}
else
{
return(CompareResult.NotApplicable);
}
// Match the command line as well because pids might be reused during the session
return(CompareResult.Match);
}
public static bool MatchProcessName(TraceEvent evt, TraceSourceManager source, string processName)
{
if (source.IsWindows)
{
if (!processName.Equals(evt.ProcessName, StringComparison.OrdinalIgnoreCase))
{
return(CompareResult.Mismatch);
}
}
else
{
// 15 characters is the maximum length of a process name in Linux kernel event payload
if (processName.Length < 15)
{
if (!processName.Equals(evt.ProcessName, StringComparison.OrdinalIgnoreCase))
{
return(CompareResult.Mismatch);
}
}
else
{
if (evt.PayloadByName("FileName") == null)
{
// match the first 15 characters only if FileName field is not present in the payload
if (!processName.Substring(0, 15).Equals(evt.ProcessName, StringComparison.OrdinalIgnoreCase))
{
return(CompareResult.Mismatch);
}
}
else
{
// match the full process name by extracting the file name
string filename = (string)GetPayloadValue(evt, "FileName");
if (!processName.Equals(Path.GetFileName(filename)))
{
return(CompareResult.Mismatch);
}
}
}
}
return(CompareResult.Match);
}
public static bool MatchCommandLine(TraceEvent evt, TraceSourceManager source, string commandLine)
{
if (source.IsWindows)
{
int bufferMax = 512;
string payloadCommandLine = (string)GetPayloadValue(evt, "CommandLine");
if (payloadCommandLine.Length >= bufferMax && commandLine.Length >= bufferMax)
{
commandLine = commandLine.Substring(0, bufferMax);
payloadCommandLine = payloadCommandLine.Substring(0, bufferMax);
}
if (!commandLine.Trim().Equals(payloadCommandLine.Trim()))
{
return(CompareResult.Mismatch);
}
}
else
{
return(CompareResult.NotApplicable);
}
// Match the command line as well because pids might be reused during the session
return(CompareResult.Match);
}
public IEnumerable <Counter> Parse(string mergeTraceFile, string processName, IList <int> pids, string commandLine)
{
var results = new List <double>();
var threadTimes = new List <double>();
var buildEvalTime = new List <double>();
double threadTime = 0;
var ins = new Dictionary <int, double>();
double start = -1;
double buildEvalStart = -1;
int? pid = null;
Dictionary <string, List <double> > firstRun = new Dictionary <string, List <double> >();
Dictionary <string, List <double> > secondRun = new Dictionary <string, List <double> >();
Dictionary <string, List <double> > currentRun = firstRun;
using (var source = new TraceSourceManager(mergeTraceFile))
{
source.Kernel.ProcessStart += evt =>
{
if (!pid.HasValue && ParserUtility.MatchProcessStart(evt, source, processName, pids, commandLine))
{
pid = evt.ProcessID;
start = evt.TimeStampRelativeMSec;
}
};
if (source.IsWindows)
{
((ETWTraceEventSource)source.Source).Kernel.ThreadCSwitch += evt =>
{
if (!pid.HasValue) // we're currently in a measurement interval
{
return;
}
if (evt.NewProcessID != pid && evt.OldProcessID != pid)
{
return; // but this isn't our process
}
if (evt.OldProcessID == pid) // this is a switch out from our process
{
if (ins.TryGetValue(evt.OldThreadID, out var value)) // had we ever recorded a switch in for this thread?
{
threadTime += evt.TimeStampRelativeMSec - value;
ins.Remove(evt.OldThreadID);
}
}
else // this is a switch in to our process
{
ins[evt.NewThreadID] = evt.TimeStampRelativeMSec;
}
};
}
source.Kernel.ProcessStop += evt =>
{
if (pid.HasValue && ParserUtility.MatchSingleProcessID(evt, source, (int)pid))
{
if (!currentRun.ContainsKey(evt.EventName))
{
currentRun.Add(evt.EventName, new List <double>());
currentRun[evt.EventName].Add(evt.TimeStampRelativeMSec - start);
}
else
{
currentRun[evt.EventName].Add(evt.TimeStampRelativeMSec - start);
}
results.Add(evt.TimeStampRelativeMSec - start);
pid = null;
start = 0;
if (source.IsWindows)
{
if (!currentRun.ContainsKey("ThreadCSwitch"))
{
currentRun.Add("ThreadCSwitch", new List <double>());
currentRun["ThreadCSwitch"].Add(threadTime);
}
else
{
currentRun["ThreadCSwitch"].Add(threadTime);
}
threadTimes.Add(threadTime);
threadTime = 0;
}
}
};
source.Source.Dynamic.AddCallbackForProviderEvent("Microsoft-Build", "Evaluate/Start", evt =>
{
if (pid.HasValue && evt.ProcessID == pid.Value)
{
buildEvalStart = evt.TimeStampRelativeMSec;
}
});
source.Source.Dynamic.AddCallbackForProviderEvent("Microsoft-Build", "Evaluate/Stop", evt =>
{
if (pid.HasValue && evt.ProcessID == pid.Value)
{
if (!currentRun.ContainsKey(evt.EventName))
{
currentRun.Add(evt.EventName, new List <double>());
currentRun[evt.EventName].Add(evt.TimeStampRelativeMSec - buildEvalStart);
}
else
{
currentRun[evt.EventName].Add(evt.TimeStampRelativeMSec - buildEvalStart);
}
}
});
source.Source.Dynamic.AddCallbackForProviderEvent("InnerLoopMarkerEventSource", "Split", evt =>
{
currentRun = secondRun;
});
source.Source.Dynamic.AddCallbackForProviderEvent("InnerLoopMarkerEventSource", "EndIteration", evt =>
{
currentRun = firstRun;
});
source.Process();
}
List <double> diffGS = new List <double>();
List <double> diffTOT = new List <double>();
List <double> diffEBT = new List <double>();
for (int i = 0; i < firstRun["Process/Stop"].Count; i++)
{
diffGS.Add(firstRun["Process/Stop"][i] - secondRun["Process/Stop"][i]);
}
for (int i = 0; i < firstRun["ThreadCSwitch"].Count; i++)
{
diffTOT.Add(firstRun["ThreadCSwitch"][i] - secondRun["ThreadCSwitch"][i]);
}
for (int i = 0; i < firstRun["Evaluate/Stop"].Count; i++)
{
diffEBT.Add(firstRun["Evaluate/Stop"][i] - secondRun["Evaluate/Stop"][i]);
}
return(new[] {
new Counter()
{
Name = "Generic Startup First Run", MetricName = "ms", TopCounter = true, Results = firstRun["Process/Stop"].ToArray()
},
new Counter()
{
Name = "Generic Startup Second Run", MetricName = "ms", TopCounter = true, Results = secondRun["Process/Stop"].ToArray()
},
new Counter()
{
Name = "Generic Startup Diff", MetricName = "ms", DefaultCounter = true, TopCounter = true, Results = diffGS.ToArray()
},
new Counter()
{
Name = "Time on Thread Diff", MetricName = "ms", TopCounter = true, Results = diffTOT.ToArray()
},
new Counter()
{
Name = "Build Evaluate Time First Run", MetricName = "ms", TopCounter = true, Results = firstRun["Evaluate/Stop"].ToArray()
},
new Counter()
{
Name = "Build Evaluate Time Second Run", MetricName = "ms", TopCounter = true, Results = secondRun["Evaluate/Stop"].ToArray()
},
new Counter()
{
Name = "Build Evaluate Time Diff", MetricName = "ms", TopCounter = true, Results = diffEBT.ToArray()
}
});
}
public IEnumerable <Counter> Parse(string mergeTraceFile, string processName, IList <int> pids, string commandLine)
{
var results = new List <double>();
double threadTime = 0;
var threadTimes = new List <double>();
var ins = new Dictionary <int, double>();
double start = -1;
int? pid = null;
using (var source = new TraceSourceManager(mergeTraceFile))
{
source.Kernel.ProcessStart += evt =>
{
if (!pid.HasValue && ParserUtility.MatchProcessStart(evt, source, processName, pids, commandLine))
{
pid = evt.ProcessID;
start = evt.TimeStampRelativeMSec;
}
};
if (source.IsWindows)
{
((ETWTraceEventSource)source.Source).Kernel.ThreadCSwitch += evt =>
{
if (!pid.HasValue) // we're currently in a measurement interval
{
return;
}
if (evt.NewProcessID != pid && evt.OldProcessID != pid)
{
return; // but this isn't our process
}
if (evt.OldProcessID == pid) // this is a switch out from our process
{
if (ins.TryGetValue(evt.OldThreadID, out var value)) // had we ever recorded a switch in for this thread?
{
threadTime += evt.TimeStampRelativeMSec - value;
ins.Remove(evt.OldThreadID);
}
}
else // this is a switch in to our process
{
ins[evt.NewThreadID] = evt.TimeStampRelativeMSec;
}
};
}
ClrPrivateTraceEventParser clrpriv = new ClrPrivateTraceEventParser(source.Source);
clrpriv.StartupMainStart += evt =>
{
if (pid.HasValue && ParserUtility.MatchSingleProcessID(evt, source, (int)pid))
{
results.Add(evt.TimeStampRelativeMSec - start);
pid = null;
start = 0;
if (source.IsWindows)
{
threadTimes.Add(threadTime);
threadTime = 0;
}
}
};
source.Process();
}
var ret = new List <Counter> {
new Counter()
{
Name = "Time To Main", Results = results.ToArray(), TopCounter = true, DefaultCounter = true, HigherIsBetter = false, MetricName = "ms"
}
};
if (threadTimes.Count != 0)
{
ret.Add(new Counter()
{
Name = "Time on Thread", Results = threadTimes.ToArray(), TopCounter = true, DefaultCounter = false, HigherIsBetter = false, MetricName = "ms"
});
}
return(ret);
}
public static bool MatchSingleProcessID(TraceEvent evt, TraceSourceManager source, int pid)
{
return(MatchProcessID(evt, source, new List <int> {
pid
}));
}
public static bool MatchProcessStart(TraceEvent evt, TraceSourceManager source, string processName, IList <int> pids, string commandLine)
{
return(MatchCommandLine(evt, source, commandLine) &&
MatchProcessName(evt, source, processName) &&
MatchProcessID(evt, source, pids));
}
public IEnumerable <Counter> Parse(string mergeTraceFile, string processName, IList <int> pids, string commandLine)
{
var results = new List <double>();
var threadTimes = new List <double>();
double threadTime = 0;
var ins = new Dictionary <int, double>();
double start = -1;
int? pid = null;
List <List <double> > firstRun = new List <List <double> >();
List <List <double> > secondRun = new List <List <double> >();
using (var source = new TraceSourceManager(mergeTraceFile))
{
source.Kernel.ProcessStart += evt =>
{
if (!pid.HasValue && ParserUtility.MatchProcessStart(evt, source, processName, pids, commandLine))
{
pid = evt.ProcessID;
start = evt.TimeStampRelativeMSec;
}
};
if (source.IsWindows)
{
((ETWTraceEventSource)source.Source).Kernel.ThreadCSwitch += evt =>
{
if (!pid.HasValue) // we're currently in a measurement interval
{
return;
}
if (evt.NewProcessID != pid && evt.OldProcessID != pid)
{
return; // but this isn't our process
}
if (evt.OldProcessID == pid) // this is a switch out from our process
{
if (ins.TryGetValue(evt.OldThreadID, out var value)) // had we ever recorded a switch in for this thread?
{
threadTime += evt.TimeStampRelativeMSec - value;
ins.Remove(evt.OldThreadID);
}
}
else // this is a switch in to our process
{
ins[evt.NewThreadID] = evt.TimeStampRelativeMSec;
}
};
}
if (useLoggingExtension)
{
source.Source.Dynamic.AddCallbackForProviderEvent("Microsoft-Extensions-Logging", "FormattedMessage", evt =>
{
if (evt.PayloadString(5).ToLower() == "hosting started")
{
if (pid.HasValue)
{
results.Add(evt.TimeStampRelativeMSec - start);
pid = null;
start = 0;
if (source.IsWindows)
{
threadTimes.Add(threadTime);
threadTime = 0;
}
}
}
});
}
else
{
source.Kernel.ProcessStop += evt =>
{
if (pid.HasValue && ParserUtility.MatchSingleProcessID(evt, source, (int)pid))
{
results.Add(evt.TimeStampRelativeMSec - start);
pid = null;
start = 0;
if (source.IsWindows)
{
threadTimes.Add(threadTime);
threadTime = 0;
}
}
};
}
source.Source.Dynamic.AddCallbackForProviderEvent("InnerLoopMarkerEventSource", "Split", evt =>
{
if (firstRun.Count == 0)
{
firstRun.Add(new List <double>());
firstRun.Add(new List <double>());
}
firstRun[0].AddRange(results);
firstRun[1].AddRange(threadTimes);
results = new List <double>();
threadTimes = new List <double>();
});
source.Source.Dynamic.AddCallbackForProviderEvent("InnerLoopMarkerEventSource", "EndIteration", evt =>
{
if (secondRun.Count == 0)
{
secondRun.Add(new List <double>());
secondRun.Add(new List <double>());
}
secondRun[0].AddRange(results);
secondRun[1].AddRange(threadTimes);
results = new List <double>();
threadTimes = new List <double>();
});
source.Process();
}
List <double> diffGS = new List <double>();
List <double> diffTOT = new List <double>();
for (int i = 0; i < firstRun[0].Count; i++)
{
diffGS.Add(firstRun[0][i] - secondRun[0][i]);
}
for (int i = 0; i < firstRun[1].Count; i++)
{
diffTOT.Add(firstRun[1][i] - secondRun[1][i]);
}
return(new[] {
new Counter()
{
Name = "Generic Startup First Run", MetricName = "ms", TopCounter = true, Results = firstRun[0].ToArray()
},
new Counter()
{
Name = "Generic Startup Second Run", MetricName = "ms", TopCounter = true, Results = secondRun[0].ToArray()
},
new Counter()
{
Name = "Generic Startup Diff", MetricName = "ms", DefaultCounter = true, TopCounter = true, Results = diffGS.ToArray()
},
new Counter()
{
Name = "Time on Thread Diff", MetricName = "ms", TopCounter = true, Results = diffTOT.ToArray()
}
});
}
public void AddStartStopCallbacks(TraceSourceManager source, DynamicTraceEventParser dynamicParser, string provider, IList <int> pids)
{
AddEventStartCallback(source, dynamicParser, provider, pids);
AddEventStopCallback(source, dynamicParser, provider);
}