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