List <ResultTableRowModel> BuildRowModels(Func <Benchmark, Metric, bool> primaryMetricSelector)
{
List <ResultTableRowModel> rows = new List <ResultTableRowModel>();
foreach (Benchmark benchmark in Benchmarks)
{
BenchmarkRunResult canonResult = BenchmarkRunResults.Where(r => r.Benchmark == benchmark).FirstOrDefault();
if (canonResult == null || canonResult.IterationResults == null || canonResult.IterationResults.Count == 0)
{
continue;
}
IterationResult canonIteration = canonResult.IterationResults[0];
foreach (Metric metric in canonIteration.Measurements.Keys)
{
if (primaryMetricSelector(benchmark, metric))
{
rows.Add(new ResultTableRowModel()
{
Benchmark = benchmark, Metric = metric
});
}
}
}
return(rows);
}
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);
}
/// <summary>
/// Converts IterationResult into Benchview's IterationModel, remaping and filtering the metrics reported
/// </summary>
static IterationModel ConvertIterationResult(IterationResult iterationResult, Func <Metric, Metric> metricMapping)
{
IterationModel iterationModel = new IterationModel();
iterationModel.Iteration = new Dictionary <string, double>();
foreach (KeyValuePair <Metric, double> measurement in iterationResult.Measurements)
{
Metric finalMetric = metricMapping(measurement.Key);
if (!finalMetric.Equals(default(Metric)))
{
iterationModel.Iteration.Add(finalMetric.Name, measurement.Value);
}
}
return(iterationModel);
}
void AddConsoleMetrics(IterationResult result, string stdout, ITestOutputHelper output)
{
output.WriteLine("Processing iteration results.");
double?trainingTime = null;
double?firstSearchTime = null;
double?steadyStateMedianTime = null;
var currentDecimalSeparator = CultureInfo.CurrentCulture.NumberFormat.NumberDecimalSeparator;
using (var reader = new StringReader(stdout))
{
string line;
while ((line = reader.ReadLine()) != null)
{
Match match = Regex.Match(line, @"^Training took \s*(\d+)ms$");
if (match.Success && match.Groups.Count == 2)
{
trainingTime = Convert.ToDouble(match.Groups[1].Value);
continue;
}
match = Regex.Match(line, @"^Search took \s*(\d+)ms$");
if (match.Success && match.Groups.Count == 2)
{
firstSearchTime = Convert.ToDouble(match.Groups[1].Value);
continue;
}
match = Regex.Match(line, $@"^Steadystate median search time: \s*(\d+\{currentDecimalSeparator}\d+)ms$");
if (match.Success && match.Groups.Count == 2)
{
//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
steadyStateMedianTime = Convert.ToDouble(match.Groups[1].Value);
continue;
}
}
}
if (!trainingTime.HasValue)
{
throw new FormatException("Training time was not found.");
}
if (!firstSearchTime.HasValue)
{
throw new FormatException("First Search time was not found.");
}
if (!steadyStateMedianTime.HasValue)
{
throw new FormatException("Steady state median response time not found.");
}
result.Measurements.Add(TrainingMetric, trainingTime.Value);
result.Measurements.Add(FirstSearchMetric, firstSearchTime.Value);
result.Measurements.Add(MedianSearchMetric, steadyStateMedianTime.Value);
output.WriteLine($"Training took {trainingTime}ms");
output.WriteLine($"Search took {firstSearchTime}ms");
output.WriteLine($"Median steady state search {steadyStateMedianTime.Value}ms");
}
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());
}
}
