protected override IterationResult RecordIterationMetrics(ScenarioExecutionResult scenarioIteration, string stdout, string stderr, ITestOutputHelper output)
{
IterationResult result = base.RecordIterationMetrics(scenarioIteration, stdout, stderr, output);
AddConsoleMetrics(result, stdout, output);
return(result);
}
protected virtual IterationResult RecordIterationMetrics(ScenarioExecutionResult scenarioIteration, string stdout, string stderr, ITestOutputHelper output)
{
IterationResult iterationResult = new IterationResult();
int elapsedMs = (int)(scenarioIteration.ProcessExitInfo.ExitTime - scenarioIteration.ProcessExitInfo.StartTime).TotalMilliseconds;
iterationResult.Measurements.Add(Metric.ElapsedTimeMilliseconds, elapsedMs);
if (!string.IsNullOrWhiteSpace(scenarioIteration.EventLogFileName) && File.Exists(scenarioIteration.EventLogFileName))
{
AddEtwData(iterationResult, scenarioIteration, output);
}
return(iterationResult);
}
private static ScenarioBenchmark AddEtwData(
ScenarioBenchmark scenarioBenchmark,
ScenarioExecutionResult scenarioExecutionResult,
IReadOnlyCollection <string> processesOfInterest,
IReadOnlyCollection <string> modulesOfInterest)
{
var metricModels = scenarioExecutionResult.PerformanceMonitorCounters
.Select(pmc => new MetricModel {
DisplayName = pmc.DisplayName,
Name = pmc.Name,
Unit = pmc.Unit,
});
// Get the list of processes of interest.
Console.WriteLine($"Parsing: {scenarioExecutionResult.EventLogFileName}");
var processes = new SimpleTraceEventParser().GetProfileData(scenarioExecutionResult);
// Extract the Pmc data for each one of the processes.
foreach (var process in processes)
{
if (!processesOfInterest.Any(p => p.Equals(process.Name, StringComparison.OrdinalIgnoreCase)))
{
continue;
}
var processTest = scenarioBenchmark.Tests
.SingleOrDefault(t => t.Name == process.Name && t.Namespace == "");
if (processTest == null)
{
processTest = new ScenarioTestModel(process.Name)
{
Namespace = "",
};
scenarioBenchmark.Tests.Add(processTest);
// Add metrics definitions.
processTest.Performance.Metrics.Add(ElapsedTimeMilliseconds);
processTest.Performance.Metrics.AddRange(metricModels);
}
var processIterationModel = new IterationModel {
Iteration = new Dictionary <string, double>()
};
processTest.Performance.IterationModels.Add(processIterationModel);
processIterationModel.Iteration.Add(
ElapsedTimeMilliseconds.Name, process.LifeSpan.Duration.TotalMilliseconds);
// Add process metrics values.
foreach (var pmcData in process.PerformanceMonitorCounterData)
{
processIterationModel.Iteration.Add(pmcData.Key.Name, pmcData.Value);
}
foreach (var module in process.Modules)
{
var moduleName = Path.GetFileName(module.FullName);
if (modulesOfInterest.Any(m => m.Equals(moduleName, StringComparison.OrdinalIgnoreCase)))
{
var moduleTestName = $"{moduleName}";
var moduleTest = scenarioBenchmark.Tests
.SingleOrDefault(t => t.Name == moduleTestName && t.Namespace == process.Name);
if (moduleTest == null)
{
moduleTest = new ScenarioTestModel(moduleTestName)
{
Namespace = process.Name,
Separator = "!",
};
scenarioBenchmark.Tests.Add(moduleTest);
// Add metrics definitions.
moduleTest.Performance.Metrics.AddRange(metricModels);
}
var moduleIterationModel = new IterationModel {
Iteration = new Dictionary <string, double>()
};
moduleTest.Performance.IterationModels.Add(moduleIterationModel);
// 5. Add module metrics values.
foreach (var pmcData in module.PerformanceMonitorCounterData)
{
moduleIterationModel.Iteration.Add(pmcData.Key.Name, pmcData.Value);
}
}
}
}
return(scenarioBenchmark);
}
private void PostIteration(ScenarioExecutionResult scenarioExecutionResult)
{
PrintHeader("Processing iteration results.");
double?startupTime = null;
double?firstRequestTime = null;
double?steadyStateAverageTime = null;
using (var reader = new StringReader(_stdout.ToString()))
{
string line;
while ((line = reader.ReadLine()) != null)
{
Match match = Regex.Match(line, @"^Server started in (\d+)ms$");
if (match.Success && match.Groups.Count == 2)
{
startupTime = Convert.ToDouble(match.Groups[1].Value);
continue;
}
match = Regex.Match(line, @"^Request took (\d+)ms$");
if (match.Success && match.Groups.Count == 2)
{
firstRequestTime = Convert.ToDouble(match.Groups[1].Value);
continue;
}
match = Regex.Match(line, @"^Steadystate average response time: (\d+)ms$");
if (match.Success && match.Groups.Count == 2)
{
steadyStateAverageTime = Convert.ToDouble(match.Groups[1].Value);
break;
}
}
}
if (!startupTime.HasValue)
{
throw new Exception("Startup time was not found.");
}
if (!firstRequestTime.HasValue)
{
throw new Exception("First Request time was not found.");
}
if (!steadyStateAverageTime.HasValue)
{
throw new Exception("Steady state average response time not found.");
}
IterationsData.Add(new IterationData {
ScenarioExecutionResult = scenarioExecutionResult,
StandardOutput = _stdout.ToString(),
StartupTime = startupTime.Value,
FirstRequestTime = firstRequestTime.Value,
SteadystateTime = steadyStateAverageTime.Value,
});
PrintRunningStepInformation($"({IterationsData.Count}) Server started in {IterationsData.Last().StartupTime}ms");
PrintRunningStepInformation($"({IterationsData.Count}) Request took {IterationsData.Last().FirstRequestTime}ms");
PrintRunningStepInformation($"({IterationsData.Count}) Cold start time (server start + first request time): {IterationsData.Last().StartupTime + IterationsData.Last().FirstRequestTime}ms");
PrintRunningStepInformation($"({IterationsData.Count}) Average steady state response {IterationsData.Last().SteadystateTime}ms");
_stdout.Clear();
_stderr.Clear();
}
protected static void AddEtwData(
IterationResult iteration,
ScenarioExecutionResult scenarioExecutionResult,
ITestOutputHelper output)
{
string[] modulesOfInterest = new string[] {
"Anonymously Hosted DynamicMethods Assembly",
"clrjit.dll",
"coreclr.dll",
"dotnet.exe",
"MusicStore.dll",
"AllReady.dll",
"Word2VecScenario.dll",
"ntoskrnl.exe",
"System.Private.CoreLib.dll",
"Unknown",
};
// Get the list of processes of interest.
try
{
var processes = new SimpleTraceEventParser().GetProfileData(scenarioExecutionResult);
// Extract the Pmc data for each one of the processes.
foreach (var process in processes)
{
if (process.Id != scenarioExecutionResult.ProcessExitInfo.ProcessId)
{
continue;
}
iteration.Measurements.Add(new Metric($"PMC/{process.Name}/Duration", "ms"),
process.LifeSpan.Duration.TotalMilliseconds);
// Add process metrics values.
foreach (var pmcData in process.PerformanceMonitorCounterData)
{
iteration.Measurements.Add(new Metric($"PMC/{process.Name}/{pmcData.Key.Name}", pmcData.Key.Unit), pmcData.Value);
}
foreach (var module in process.Modules)
{
var moduleName = Path.GetFileName(module.FullName);
if (modulesOfInterest.Any(m => m.Equals(moduleName, StringComparison.OrdinalIgnoreCase)))
{
foreach (var pmcData in module.PerformanceMonitorCounterData)
{
Metric m = new Metric($"PMC/{process.Name}!{moduleName}/{pmcData.Key.Name}", pmcData.Key.Unit);
// Sometimes the etw parser gives duplicate module entries which leads to duplicate keys
// but I haven't hunted down the reason. For now it is first one wins.
if (!iteration.Measurements.ContainsKey(m))
{
iteration.Measurements.Add(m, pmcData.Value);
}
}
}
}
}
}
catch (InvalidOperationException e)
{
output.WriteLine("Error while processing ETW log: " + scenarioExecutionResult.EventLogFileName);
output.WriteLine(e.ToString());
}
}
private void PostIteration(ScenarioExecutionResult scenarioExecutionResult)
{
PrintHeader("Processing iteration results.");
double?startupTime = null;
double?firstRequestTime = null;
double?steadyStateAverageTime = null;
double?steadyStateMedianTime = null;
using (var reader = new StringReader(_stdout.ToString()))
{
string line;
while ((line = reader.ReadLine()) != null)
{
Match match = Regex.Match(line, @"^Server start \(ms\): \s*(\d+)\s*$");
if (match.Success && match.Groups.Count == 2)
{
startupTime = Convert.ToDouble(match.Groups[1].Value);
continue;
}
match = Regex.Match(line, @"^1st Request \(ms\): \s*(\d+)\s*$");
if (match.Success && match.Groups.Count == 2)
{
firstRequestTime = Convert.ToDouble(match.Groups[1].Value);
continue;
}
//the steady state output chart looks like:
// Requests Aggregate Time(ms) Req/s Req Min(ms) Req Mean(ms) Req Median(ms) Req Max(ms) SEM(%)
// ---------- ------------------ ----- ----------- ------------ -------------- ----------- ------
// 2- 100 5729 252.60 3.01 3.96 3.79 9.81 1.86
// 101- 250 6321 253.76 3.40 3.94 3.84 5.25 0.85
// ... many more rows ...
// Requests Agg req/s min mean median max SEM
match = Regex.Match(line, @"^\s*\d+-\s*\d+ \s* \d+ \s* \d+\.\d+ \s* \d+\.\d+ \s* (\d+\.\d+) \s* (\d+\.\d+) \s* \d+\.\d+ \s* \d+\.\d+$");
if (match.Success && match.Groups.Count == 3)
{
//many lines will match, but the final values of these variables will be from the last batch which is presumably the
//best measurement of steady state performance
steadyStateAverageTime = Convert.ToDouble(match.Groups[1].Value);
steadyStateMedianTime = Convert.ToDouble(match.Groups[2].Value);
continue;
}
}
}
if (!startupTime.HasValue)
{
throw new Exception("Startup time was not found.");
}
if (!firstRequestTime.HasValue)
{
throw new Exception("First Request time was not found.");
}
if (!steadyStateAverageTime.HasValue)
{
throw new Exception("Steady state average response time not found.");
}
if (!steadyStateMedianTime.HasValue)
{
throw new Exception("Steady state median response time not found.");
}
IterationsData.Add(new IterationData
{
ScenarioExecutionResult = scenarioExecutionResult,
StandardOutput = _stdout.ToString(),
StartupTime = startupTime.Value,
FirstRequestTime = firstRequestTime.Value,
SteadystateTime = steadyStateAverageTime.Value,
SteadystateMedianTime = steadyStateMedianTime.Value,
});
PrintRunningStepInformation($"({IterationsData.Count}) Server started in {IterationsData.Last().StartupTime}ms");
PrintRunningStepInformation($"({IterationsData.Count}) Request took {IterationsData.Last().FirstRequestTime}ms");
PrintRunningStepInformation($"({IterationsData.Count}) Cold start time (server start + first request time): {IterationsData.Last().StartupTime + IterationsData.Last().FirstRequestTime}ms");
PrintRunningStepInformation($"({IterationsData.Count}) Average steady state response {IterationsData.Last().SteadystateTime}ms");
PrintRunningStepInformation($"({IterationsData.Count}) Median steady state response {IterationsData.Last().SteadystateMedianTime}ms");
_stdout.Clear();
_stderr.Clear();
}
/// <summary>
/// Gets profile data from the provided <see cref="ScenarioExecutionResult"/> object
/// </summary>
/// <param name="scenarioExecutionResult"></param>
/// <returns>A collection of the profiled processes for the given scenario.</returns>
/// <remarks>
/// Some assumptions:
/// 1. The scenario launches a single process, but itself can launch child processes.
/// 2. Process started/stopped within the ETW session.
/// </remarks>
public IReadOnlyCollection <Process> GetProfileData(ScenarioExecutionResult scenarioExecutionResult)
{
if (!RuntimeInformation.IsOSPlatform(OSPlatform.Windows))
{
throw new PlatformNotSupportedException();
}
var processes = new List <Process>();
Module defaultNtoskrnlModule = null;
var pmcSamplingIntervals = new Dictionary <int, long>();
bool IsOurProcess(ProcessTraceData obj)
{
return(obj.ProcessID == scenarioExecutionResult.ProcessExitInfo.ProcessId ||
processes.Any(process => process.Id == obj.ProcessID || process.Id == obj.ParentID));
}
using (var source = new ETWTraceEventSource(scenarioExecutionResult.EventLogFileName))
{
if (source.EventsLost > 0)
{
throw new Exception($"Events lost in trace '{scenarioExecutionResult.EventLogFileName}'");
}
const int DefaultModuleChecksum = 0;
////////////////////////////////////////////////////////////////
// Process data
var parser = new KernelTraceEventParser(source);
parser.ProcessStart += (ProcessTraceData obj) => {
if (IsOurProcess(obj))
{
var process = new Process(obj.ImageFileName, obj.ProcessID, obj.ParentID, scenarioExecutionResult.PerformanceMonitorCounters);
process.LifeSpan.Start = obj.TimeStamp;
processes.Add(process);
}
};
parser.ProcessStop += (ProcessTraceData obj) => {
if (IsOurProcess(obj))
{
processes.Single(process => process.Id == obj.ProcessID).LifeSpan.End = obj.TimeStamp;
}
};
////////////////////////////////////////////////////////////////
// Image/Module data
parser.ImageLoad += (ImageLoadTraceData obj) => {
var process = processes.SingleOrDefault(p => p.Id == obj.ProcessID);
if (process == null)
{
return;
}
var module = process.Modules
.SingleOrDefault(m => m.Checksum == obj.ImageChecksum && m.FullName == obj.FileName);
if (module == null)
{
module = new Module(obj.FileName, obj.ImageChecksum, scenarioExecutionResult.PerformanceMonitorCounters);
process.Modules.Add(module);
}
module.RuntimeInstances.Add(
new RuntimeInstance(new AddressSpace(obj.ImageBase, (uint)obj.ImageSize), obj.TimeStamp));
};
parser.ImageUnload += (ImageLoadTraceData obj) => {
var process = processes.SingleOrDefault(p => p.Id == obj.ProcessID);
if (process == null)
{
return;
}
var module = process.Modules
.SingleOrDefault(m => m.Checksum == obj.ImageChecksum && m.FullName == obj.FileName);
if (module == null)
{
return;
}
var info = module.RuntimeInstances.SingleOrDefault(i => {
return(i.AddressSpace.Start == obj.ImageBase &&
i.AddressSpace.Size == obj.ImageSize &&
i.LifeSpan.End > obj.TimeStamp);
});
if (info == null)
{
return; // Managed methods already unloaded.
}
info.LifeSpan.End = obj.TimeStamp;
};
////////////////////////////////////////////////////////////////
// "ntoskrnl.exe" data
parser.ImageDCStart += (ImageLoadTraceData obj) => {
if (obj.ProcessID == 0 && obj.FileName.EndsWith("ntoskrnl.exe"))
{
if (defaultNtoskrnlModule == null)
{
defaultNtoskrnlModule = new Module(obj.FileName, obj.ImageChecksum, scenarioExecutionResult.PerformanceMonitorCounters);
defaultNtoskrnlModule.RuntimeInstances.Add(
new RuntimeInstance(new AddressSpace(obj.ImageBase, (uint)obj.ImageSize), obj.TimeStamp));
}
}
};
////////////////////////////////////////////////////////////////
// PMC data
var pmcSamples = new List <PmcSample>();
parser.PerfInfoCollectionStart += (SampledProfileIntervalTraceData obj) => {
// Update the Pmc intervals.
if (scenarioExecutionResult.PerformanceMonitorCounters.Any(pmc => pmc.Id == obj.SampleSource))
{
if (!pmcSamplingIntervals.ContainsKey(obj.SampleSource))
{
pmcSamplingIntervals.Add(obj.SampleSource, obj.NewInterval);
}
else
{
pmcSamplingIntervals[obj.SampleSource] = obj.NewInterval;
}
}
};
parser.PerfInfoPMCSample += (PMCCounterProfTraceData obj) => {
var performanceMonitorCounter = scenarioExecutionResult.PerformanceMonitorCounters
.SingleOrDefault(pmc => pmc.Id == obj.ProfileSource);
if (performanceMonitorCounter == null)
{
return;
}
var process = processes.SingleOrDefault(p => p.Id == obj.ProcessID);
if (process == null)
{
return;
}
process.PerformanceMonitorCounterData[performanceMonitorCounter] += pmcSamplingIntervals[obj.ProfileSource];
// Is the IP in the kernel (Under this process)?
if (defaultNtoskrnlModule != null && obj.IsInTimeAndAddressIntervals(defaultNtoskrnlModule))
{
var krnlModule = process.Modules
.SingleOrDefault(m => m.Checksum == defaultNtoskrnlModule.Checksum && m.FullName == defaultNtoskrnlModule.FullName);
if (krnlModule == null)
{
krnlModule = new Module(defaultNtoskrnlModule);
process.Modules.Add(krnlModule);
}
}
var modules = process.Modules
.Where(m => {
return(obj.IsInTimeAndAddressIntervals(m));
})
.Select(m => m);
if (modules.Count() == 0)
{
// This might fall in managed code. We need to buffer and test it afterwards.
pmcSamples.Add(new PmcSample {
InstructionPointer = obj.InstructionPointer,
ProcessId = obj.ProcessID,
ProfileSourceId = obj.ProfileSource,
TimeStamp = obj.TimeStamp,
SamplingInterval = pmcSamplingIntervals[obj.ProfileSource],
});
return;
}
modules.ForEach(module => {
module.PerformanceMonitorCounterData[performanceMonitorCounter] += pmcSamplingIntervals[obj.ProfileSource];
});
};
////////////////////////////////////////////////////////////////
// .NET modules
parser.Source.Clr.LoaderModuleLoad += (ModuleLoadUnloadTraceData obj) => {
var process = processes.SingleOrDefault(p => p.Id == obj.ProcessID);
if (process == null)
{
return;
}
var modulePath = string.IsNullOrEmpty(obj.ModuleNativePath) ? obj.ModuleILPath : obj.ModuleNativePath;
var module = process.Modules
.SingleOrDefault(m => m.FullName == modulePath && m.RuntimeInstances.Any(i => i.LifeSpan.IsInInterval(obj.TimeStamp) == 0));
if (module == null)
{
// Not previously loaded (For example, 'Anonymously Hosted DynamicMethods Assembly')
module = new DotNetModule(modulePath, DefaultModuleChecksum, scenarioExecutionResult.PerformanceMonitorCounters, obj.ModuleID);
process.Modules.Add(module);
}
else
{
// Update/Swap the module. It is a .NET module.
var dotnetModule = new DotNetModule(module, obj.ModuleID);
process.Modules.Remove(module); // Remove existing
process.Modules.Add(dotnetModule); // Add it back as managed
}
};
parser.Source.Clr.LoaderModuleUnload += (ModuleLoadUnloadTraceData obj) => {
var process = processes
.SingleOrDefault(p => p.Id == obj.ProcessID);
if (process == null)
{
return;
}
var module = process.Modules
.OfType <DotNetModule>()
.SingleOrDefault(m => m.Id == obj.ModuleID && m.RuntimeInstances.Count > 0);
if (module == null)
{
return;
}
var info = module.RuntimeInstances
.SingleOrDefault(i => i.LifeSpan.IsInInterval(obj.TimeStamp) == 0);
if (info == null)
{
throw new InvalidOperationException($"Unloading non-loaded .NET module: {(string.IsNullOrEmpty(obj.ModuleNativePath) ? obj.ModuleILPath : obj.ModuleNativePath)}");
}
info.LifeSpan.End = obj.TimeStamp;
};
////////////////////////////////////////////////////////////////
// .NET methods
parser.Source.Clr.MethodLoadVerbose += (MethodLoadUnloadVerboseTraceData obj) => {
var process = processes
.SingleOrDefault(p => p.Id == obj.ProcessID);
if (process == null)
{
return;
}
var module = process.Modules
.OfType <DotNetModule>()
.SingleOrDefault(m => m.Id == obj.ModuleID);
if (module == null)
{
var clrHelpersModule = new DotNetModule("$CLRHelpers$", DefaultModuleChecksum, scenarioExecutionResult.PerformanceMonitorCounters, 0);
process.Modules.Add(clrHelpersModule);
module = clrHelpersModule;
}
var method = module.Methods
.SingleOrDefault(m => m.Id == obj.MethodID);
if (method == null)
{
method = new DotNetMethod(
obj.MethodID,
obj.MethodName,
obj.MethodNamespace,
obj.IsDynamic,
obj.IsGeneric,
obj.IsJitted
);
module.Methods.Add(method);
}
method.RuntimeInstances.Add(
new RuntimeInstance(new AddressSpace(obj.MethodStartAddress, (uint)obj.MethodSize), obj.TimeStamp));
};
parser.Source.Clr.MethodUnloadVerbose += (MethodLoadUnloadVerboseTraceData obj) => {
var process = processes.SingleOrDefault(p => p.Id == obj.ProcessID);
if (process == null)
{
return;
}
var module = process.Modules
.OfType <DotNetModule>()
.SingleOrDefault(m => m.Id == obj.ModuleID);
if (module == null)
{
return;
}
var method = module.Methods
.SingleOrDefault(m => m.Id == obj.MethodID);
if (method == null)
{
return;
}
var info = method.RuntimeInstances.SingleOrDefault(i => {
return(i.AddressSpace.Start == obj.MethodStartAddress &&
i.AddressSpace.Size == obj.MethodSize &&
i.LifeSpan.End > obj.TimeStamp);
});
if (info == null)
{
throw new InvalidOperationException($"Unloading non-loaded .NET method: {obj.MethodName}");
}
info.LifeSpan.End = obj.TimeStamp;
};
source.Process();
// TODO: We could order modules/methods by timestamp, then by address?
// Map PMC to managed modules.
for (int i = pmcSamples.Count - 1; i >= 0; i--)
{
var pmc = pmcSamples[i];
var performanceMonitorCounter = scenarioExecutionResult.PerformanceMonitorCounters
.SingleOrDefault(p => p.Id == pmc.ProfileSourceId);
if (performanceMonitorCounter == null)
{
continue;
}
processes
.Single(p => p.Id == pmc.ProcessId).Modules
.OfType <DotNetModule>()
.ForEach(module => {
var methodsCount = module.Methods
.Where(m => {
return(m.RuntimeInstances.Any(info => info.LifeSpan.IsInInterval(pmc.TimeStamp) == 0 &&
info.AddressSpace.IsInInterval(pmc.InstructionPointer) == 0));
})
.Count();
if (methodsCount != 0)
{
module.PerformanceMonitorCounterData[performanceMonitorCounter] += pmc.SamplingInterval;
pmcSamples.RemoveAt(i);
}
});
}
// Map PMC to Unknown module.
const string UnknownModuleName = "Unknown";
pmcSamples
.GroupBy(pmc => pmc.ProcessId)
.Select(g1 => {
return(new {
ProcessId = g1.Key,
PerformanceMonitorCounters = g1
.GroupBy(pmc => pmc.ProfileSourceId)
.ToDictionary(
g2 => scenarioExecutionResult.PerformanceMonitorCounters.Single(pmc => pmc.Id == g2.Key),
g2 => g2.Aggregate(0, (long count, PmcSample pmcSample) => count + pmcSample.SamplingInterval)),
});
})
.ForEach(pmcRollover => {
var process = processes.Single(p => p.Id == pmcRollover.ProcessId);
var newModule = new Module(UnknownModuleName, DefaultModuleChecksum, scenarioExecutionResult.PerformanceMonitorCounters);
pmcRollover.PerformanceMonitorCounters.ForEach(pair => {
newModule.PerformanceMonitorCounterData[pair.Key] = pair.Value;
});
process.Modules.Add(newModule);
});
return(processes);
}
}
