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); }