private static BenchmarkReport Run(Benchmark benchmark, ILogger logger, IConfig config)
{
var toolchain = Toolchain.GetToolchain(benchmark.Job.Runtime);
logger.WriteLineHeader("// **************************");
logger.WriteLineHeader("// Benchmark: " + benchmark.ShortInfo);
var generateResult = Generate(logger, toolchain, benchmark);
if (!generateResult.IsGenerateSuccess)
{
return(new BenchmarkReport(benchmark, generateResult, null, null, null));
}
var buildResult = Build(logger, toolchain, generateResult, benchmark);
if (!buildResult.IsBuildSuccess)
{
return(new BenchmarkReport(benchmark, generateResult, buildResult, null, null));
}
var executeResults = Execute(logger, benchmark, toolchain, buildResult, config);
var runs = new List <Measurement>();
for (int index = 0; index < executeResults.Count; index++)
{
var executeResult = executeResults[index];
runs.AddRange(executeResult.Data.Select(line => Measurement.Parse(logger, line, index + 1)).Where(r => r != null));
}
return(new BenchmarkReport(benchmark, generateResult, buildResult, executeResults, runs));
}
private static BenchmarkReport RunCore(Benchmark benchmark, ILogger logger, ReadOnlyConfig config, string rootArtifactsFolderPath, Func <Job, IToolchain> toolchainProvider, IResolver resolver, List <string> artifactsToCleanup)
{
var toolchain = toolchainProvider(benchmark.Job);
logger.WriteLineHeader("// **************************");
logger.WriteLineHeader("// Benchmark: " + benchmark.DisplayInfo);
var assemblyResolveHelper = GetAssemblyResolveHelper(toolchain, logger);
var generateResult = Generate(logger, toolchain, benchmark, rootArtifactsFolderPath, config, resolver);
try
{
if (!generateResult.IsGenerateSuccess)
{
return(new BenchmarkReport(benchmark, generateResult, null, null, null, default(GcStats)));
}
var buildResult = Build(logger, toolchain, generateResult, benchmark, resolver);
if (!buildResult.IsBuildSuccess)
{
return(new BenchmarkReport(benchmark, generateResult, buildResult, null, null, default(GcStats)));
}
var(executeResults, gcStats) = Execute(logger, benchmark, toolchain, buildResult, config, resolver);
var runs = new List <Measurement>();
for (int index = 0; index < executeResults.Count; index++)
{
var executeResult = executeResults[index];
runs.AddRange(executeResult.Data.Select(line => Measurement.Parse(logger, line, index + 1)).Where(r => r.IterationMode != IterationMode.Unknown));
}
return(new BenchmarkReport(benchmark, generateResult, buildResult, executeResults, runs, gcStats));
}
catch (Exception e)
{
logger.WriteLineError("// Exception: " + e);
return(new BenchmarkReport(benchmark, generateResult, BuildResult.Failure(generateResult, e), Array.Empty <ExecuteResult>(), Array.Empty <Measurement>(), GcStats.Empty));
}
finally
{
if (!config.KeepBenchmarkFiles)
{
artifactsToCleanup.AddRange(generateResult.ArtifactsToCleanup);
}
assemblyResolveHelper?.Dispose();
}
}
public void PrintOptions(ILogger logger)
{
logger.WriteLineHeader($"{BenchmarkDotNetInfo.FullTitle}");
logger.WriteLine();
logger.WriteLineHeader("Options:");
foreach (var option in configuration)
{
// TODO also consider allowing short version (i.e. '-d' and '--diagnosers')
var optionText = $"--{option.Key} <{option.Key.ToUpperInvariant()}>";
var parameters = string.Join(", ", option.Value.GetAllOptions.Value);
var explanation = $"Allowed values: {parameters}";
logger.WriteLineInfo($" {optionText,-30} {explanation}");
}
}
private static Dictionary <Benchmark, BuildResult> BuildInParallel(ILogger logger, string rootArtifactsFolderPath, Func <Job, IToolchain> toolchainProvider, IResolver resolver, Benchmark[] benchmarks, ReadOnlyConfig config, ref StartedClock globalChronometer)
{
using (benchmarks.Select(benchmark => GetAssemblyResolveHelper(toolchainProvider(benchmark.Job), logger)).FirstOrDefault(helper => helper != null))
{
logger.WriteLineHeader($"// ***** Building {benchmarks.Length} benchmark(s) in Parallel: Start *****");
var buildResults = benchmarks
.AsParallel()
.Select(benchmark => { return(benchmark, buildResult: Build(benchmark, config, rootArtifactsFolderPath, toolchainProvider, resolver)); })
.ToDictionary(result => result.benchmark, result => result.buildResult);
logger.WriteLineHeader($"// ***** Done, took {globalChronometer.GetElapsed().GetTimeSpan().ToFormattedTotalTime()} *****");
return(buildResults);
}
}
public void DisplayResults(ILogger outputLogger)
{
if (logger.CapturedOutput.Count > 0)
outputLogger.WriteLineHeader(new string('-', 20));
foreach (var line in logger.CapturedOutput)
outputLogger.Write(line.Kind, line.Text);
}
public override void ExportToLog(Summary summary, ILogger logger)
{
foreach (var report in summary.Reports.Values)
{
var runs = report.AllMeasurements;
var modes = runs.Select(it => it.IterationMode).Distinct();
logger.WriteLineHeader($"*** {report.Benchmark.ShortInfo} ***");
logger.WriteLineHeader("* Raw *");
foreach (var run in runs)
logger.WriteLineResult(run.ToStr());
foreach (var mode in modes)
{
logger.NewLine();
logger.WriteLineHeader($"* Statistics for {mode}");
logger.WriteLineStatistic(runs.Where(it => it.IterationMode == mode).GetStatistics().ToTimeStr());
}
}
}
private static BenchmarkReport RunCore(Benchmark benchmark, ILogger logger, ReadOnlyConfig config, string rootArtifactsFolderPath, Func <Job, IToolchain> toolchainProvider, IResolver resolver, BuildResult buildResult)
{
var toolchain = toolchainProvider(benchmark.Job);
logger.WriteLineHeader("// **************************");
logger.WriteLineHeader("// Benchmark: " + benchmark.DisplayInfo);
var(executeResults, gcStats) = Execute(logger, benchmark, toolchain, buildResult, config, resolver);
var runs = new List <Measurement>();
for (int index = 0; index < executeResults.Count; index++)
{
var executeResult = executeResults[index];
runs.AddRange(executeResult.Data.Select(line => Measurement.Parse(logger, line, index + 1)).Where(r => r.IterationMode != IterationMode.Unknown));
}
return(new BenchmarkReport(benchmark, buildResult, buildResult, executeResults, runs, gcStats));
}
public static BenchmarkReport Run(Benchmark benchmark, ILogger logger, IConfig config, string rootArtifactsFolderPath, Func <Job, IToolchain> toolchainProvider, IResolver resolver)
{
var toolchain = toolchainProvider(benchmark.Job);
logger.WriteLineHeader("// **************************");
logger.WriteLineHeader("// Benchmark: " + benchmark.DisplayInfo);
var generateResult = Generate(logger, toolchain, benchmark, rootArtifactsFolderPath, config, resolver);
try
{
if (!generateResult.IsGenerateSuccess)
{
return(new BenchmarkReport(benchmark, generateResult, null, null, null, default(GcStats)));
}
var buildResult = Build(logger, toolchain, generateResult, benchmark, resolver);
if (!buildResult.IsBuildSuccess)
{
return(new BenchmarkReport(benchmark, generateResult, buildResult, null, null, default(GcStats)));
}
var gcStats = default(GcStats);
var executeResults = Execute(logger, benchmark, toolchain, buildResult, config, resolver, out gcStats);
var runs = new List <Measurement>();
for (int index = 0; index < executeResults.Count; index++)
{
var executeResult = executeResults[index];
runs.AddRange(executeResult.Data.Select(line => Measurement.Parse(logger, line, index + 1)).Where(r => r.IterationMode != IterationMode.Unknown));
}
return(new BenchmarkReport(benchmark, generateResult, buildResult, executeResults, runs, gcStats));
}
finally
{
if (!config.KeepBenchmarkFiles)
{
generateResult.ArtifactsPaths?.RemoveBenchmarkFiles();
}
}
}
public override void ExportToLog(Summary summary, ILogger logger)
{
foreach (var report in summary.Reports.Values)
{
var runs = report.AllMeasurements;
var modes = runs.Select(it => it.IterationMode).Distinct();
logger.WriteLineHeader($"*** {report.Benchmark.ShortInfo} ***");
logger.WriteLineHeader("* Raw *");
foreach (var run in runs)
{
logger.WriteLineResult(run.ToStr());
}
foreach (var mode in modes)
{
logger.WriteLine();
logger.WriteLineHeader($"* Statistics for {mode}");
logger.WriteLineStatistic(runs.Where(it => it.IterationMode == mode).GetStatistics().ToTimeStr());
}
}
}
public void DisplayResults(ILogger outputLogger)
{
if (logger.CapturedOutput.Count > 0)
{
outputLogger.WriteLineHeader(new string('-', 20));
}
foreach (var line in logger.CapturedOutput)
{
outputLogger.Write(line.Kind, line.Text);
}
}
public void DisplayResults(ILogger logger)
{
foreach (var diagnoser in diagnosers)
{
// TODO when Diagnosers/Diagnostis are wired up properly, instead of the Type name,
// print the name used on the cmd line, i.e. -d=<NAME>
logger.WriteLineHeader($"// * Diagnostic Output - {diagnoser.GetType().Name} *");
diagnoser.DisplayResults(logger);
logger.WriteLine();
}
}
public void DisplayResults(ILogger logger)
{
foreach (var diagnoser in diagnosers)
{
// TODO when Diagnosers/Diagnostis are wired up properly, instead of the Type name,
// print the name used on the cmd line, i.e. -d=<NAME>
logger.WriteLineHeader($"// * Diagnostic Output - {diagnoser.GetType().Name} *");
diagnoser.DisplayResults(logger);
logger.WriteLine();
}
}
public override void ExportToLog(Summary summary, ILogger logger)
{
foreach (var report in summary.Reports)
{
var runs = report.AllMeasurements;
var modeStages = runs.Select(it => (it.IterationMode, it.IterationStage)).Distinct();
logger.WriteLineHeader($"*** {report.BenchmarkCase.DisplayInfo} ***");
logger.WriteLineHeader("* Raw *");
foreach (var run in runs)
{
logger.WriteLineResult(run.ToStr(report.BenchmarkCase.Config.Encoding));
}
foreach (var(mode, stage) in modeStages)
{
logger.WriteLine();
logger.WriteLineHeader($"* Statistics for {mode}{stage}");
logger.WriteLineStatistic(runs.Where(it => it.Is(mode, stage)).GetStatistics().ToTimeStr(report.BenchmarkCase.Config.Encoding, calcHistogram: true));
}
}
}
public override void ExportToLog(Summary summary, ILogger logger)
{
var cultureInfo = summary.GetCultureInfo();
foreach (var report in summary.Reports)
{
var measurements = report.AllMeasurements;
var modeStages = measurements.Select(it => (it.IterationMode, it.IterationStage)).Distinct();
logger.WriteLineHeader($"*** {report.BenchmarkCase.DisplayInfo} ***");
logger.WriteLineHeader("* Raw *");
foreach (var measurement in measurements)
{
logger.WriteLineResult(measurement.ToString());
}
foreach (var(mode, stage) in modeStages)
{
logger.WriteLine();
logger.WriteLineHeader($"* Statistics for {mode}{stage}");
var statistics = measurements.Where(it => it.Is(mode, stage)).GetStatistics();
var formatter = statistics.CreateNanosecondFormatter(cultureInfo);
logger.WriteLineStatistic(statistics.ToString(cultureInfo, formatter, calcHistogram: true));
}
}
}
private static Summary Run(IList <Benchmark> benchmarks, ILogger logger, string title, IConfig config)
{
var currentDirectory = Directory.GetCurrentDirectory();
logger.WriteLineHeader("// ***** BenchmarkRunner: Start *****");
logger.WriteLineInfo("// Found benchmarks:");
foreach (var benchmark in benchmarks)
{
logger.WriteLineInfo($"// {benchmark.ShortInfo}");
}
logger.WriteLine();
var globalChronometer = Chronometer.Start();
var reports = new List <BenchmarkReport>();
foreach (var benchmark in benchmarks)
{
var report = Run(benchmark, logger, config);
reports.Add(report);
if (report.GetResultRuns().Any())
{
logger.WriteLineStatistic(report.GetResultRuns().GetStatistics().ToTimeStr());
}
logger.WriteLine();
}
var clockSpan = globalChronometer.Stop();
var summary = new Summary(title, reports, EnvironmentHelper.GetCurrentInfo(), config, currentDirectory, clockSpan.GetTimeSpan());
logger.WriteLineHeader("// ***** BenchmarkRunner: Finish *****");
logger.WriteLine();
logger.WriteLineHeader("// * Export *");
foreach (var file in config.GetCompositeExporter().ExportToFiles(summary))
{
var printedFile = file.StartsWith(currentDirectory) ? file.Substring(currentDirectory.Length).Trim('/', '\\') : file;
logger.WriteLineInfo($" {printedFile}");
}
logger.WriteLine();
logger.WriteLineHeader("// * Detailed results *");
// TODO: make exporter
foreach (var report in reports)
{
logger.WriteLineInfo(report.Benchmark.ShortInfo);
logger.WriteLineStatistic(report.GetResultRuns().GetStatistics().ToTimeStr());
logger.WriteLine();
}
LogTotalTime(logger, clockSpan.GetTimeSpan());
logger.WriteLine();
logger.WriteLineHeader("// * Summary *");
MarkdownExporter.Console.ExportToLog(summary, logger);
// TODO: make exporter
var warnings = config.GetCompositeAnalyser().Analyze(summary).ToList();
if (warnings.Count > 0)
{
logger.WriteLine();
logger.WriteLineError("// * Warnings * ");
foreach (var warning in warnings)
{
logger.WriteLineError($"{warning.Message}");
}
}
if (config.GetDiagnosers().Count() > 0)
{
logger.WriteLine();
config.GetCompositeDiagnoser().DisplayResults(logger);
}
logger.WriteLine();
logger.WriteLineHeader("// ***** BenchmarkRunner: End *****");
return(summary);
}
private static Summary Run(Benchmark[] benchmarks, ILogger logger, string title, IConfig config, string rootArtifactsFolderPath, Func<IJob, IToolchain> toolchainProvider)
{
logger.WriteLineHeader("// ***** BenchmarkRunner: Start *****");
logger.WriteLineInfo("// Found benchmarks:");
foreach (var benchmark in benchmarks)
logger.WriteLineInfo($"// {benchmark.ShortInfo}");
logger.WriteLine();
var validationErrors = Validate(benchmarks, logger, config);
if (validationErrors.Any(validationError => validationError.IsCritical))
{
return Summary.CreateFailed(benchmarks, title, HostEnvironmentInfo.GetCurrent(), config, GetResultsFolderPath(rootArtifactsFolderPath), validationErrors);
}
var globalChronometer = Chronometer.Start();
var reports = new List<BenchmarkReport>();
foreach (var benchmark in benchmarks)
{
var report = Run(benchmark, logger, config, rootArtifactsFolderPath, toolchainProvider);
reports.Add(report);
if (report.GetResultRuns().Any())
logger.WriteLineStatistic(report.GetResultRuns().GetStatistics().ToTimeStr());
logger.WriteLine();
}
var clockSpan = globalChronometer.Stop();
var summary = new Summary(title, reports, HostEnvironmentInfo.GetCurrent(), config, GetResultsFolderPath(rootArtifactsFolderPath), clockSpan.GetTimeSpan(), validationErrors);
logger.WriteLineHeader("// ***** BenchmarkRunner: Finish *****");
logger.WriteLine();
logger.WriteLineHeader("// * Export *");
var currentDirectory = Directory.GetCurrentDirectory();
foreach (var file in config.GetCompositeExporter().ExportToFiles(summary))
{
logger.WriteLineInfo($" {file.Replace(currentDirectory, string.Empty).Trim('/', '\\')}");
}
logger.WriteLine();
logger.WriteLineHeader("// * Detailed results *");
// TODO: make exporter
foreach (var report in reports)
{
logger.WriteLineInfo(report.Benchmark.ShortInfo);
logger.WriteLineStatistic(report.GetResultRuns().GetStatistics().ToTimeStr());
logger.WriteLine();
}
LogTotalTime(logger, clockSpan.GetTimeSpan());
logger.WriteLine();
logger.WriteLineHeader("// * Summary *");
MarkdownExporter.Console.ExportToLog(summary, logger);
// TODO: make exporter
var warnings = config.GetCompositeAnalyser().Analyse(summary).ToList();
if (warnings.Count > 0)
{
logger.WriteLine();
logger.WriteLineError("// * Warnings * ");
foreach (var warning in warnings)
logger.WriteLineError($"{warning.Message}");
}
if (config.GetDiagnosers().Count() > 0)
{
logger.WriteLine();
config.GetCompositeDiagnoser().DisplayResults(logger);
}
logger.WriteLine();
logger.WriteLineHeader("// ***** BenchmarkRunner: End *****");
return summary;
}
private static BenchmarkReport Run(Benchmark benchmark, ILogger logger, IConfig config, string rootArtifactsFolderPath, Func<IJob, IToolchain> toolchainProvider)
{
var toolchain = toolchainProvider(benchmark.Job);
logger.WriteLineHeader("// **************************");
logger.WriteLineHeader("// Benchmark: " + benchmark.ShortInfo);
var generateResult = Generate(logger, toolchain, benchmark, rootArtifactsFolderPath, config);
try
{
if (!generateResult.IsGenerateSuccess)
return new BenchmarkReport(benchmark, generateResult, null, null, null);
var buildResult = Build(logger, toolchain, generateResult, benchmark);
if (!buildResult.IsBuildSuccess)
return new BenchmarkReport(benchmark, generateResult, buildResult, null, null);
List<ExecuteResult> executeResults = Execute(logger, benchmark, toolchain, buildResult, config);
var runs = new List<Measurement>();
for (int index = 0; index < executeResults.Count; index++)
{
var executeResult = executeResults[index];
runs.AddRange(executeResult.Data.Select(line => Measurement.Parse(logger, line, index + 1)).Where(r => r.IterationMode != IterationMode.Unknown));
}
return new BenchmarkReport(benchmark, generateResult, buildResult, executeResults, runs);
}
finally
{
if (!config.KeepBenchmarkFiles)
{
generateResult.ArtifactsPaths?.RemoveBenchmarkFiles();
}
}
}
public static Summary Run(Benchmark[] benchmarks, ILogger logger, string title, IConfig config, string rootArtifactsFolderPath, Func <Job, IToolchain> toolchainProvider, IResolver resolver)
{
logger.WriteLineHeader("// ***** BenchmarkRunner: Start *****");
logger.WriteLineInfo("// Found benchmarks:");
foreach (var benchmark in benchmarks)
{
logger.WriteLineInfo($"// {benchmark.DisplayInfo}");
}
logger.WriteLine();
var validationErrors = Validate(benchmarks, logger, config);
if (validationErrors.Any(validationError => validationError.IsCritical))
{
return(Summary.CreateFailed(benchmarks, title, HostEnvironmentInfo.GetCurrent(), config, GetResultsFolderPath(rootArtifactsFolderPath), validationErrors));
}
var globalChronometer = Chronometer.Start();
var reports = new List <BenchmarkReport>();
foreach (var benchmark in benchmarks)
{
var report = Run(benchmark, logger, config, rootArtifactsFolderPath, toolchainProvider, resolver);
reports.Add(report);
if (report.GetResultRuns().Any())
{
logger.WriteLineStatistic(report.GetResultRuns().GetStatistics().ToTimeStr());
}
logger.WriteLine();
}
var clockSpan = globalChronometer.Stop();
var summary = new Summary(title, reports, HostEnvironmentInfo.GetCurrent(), config, GetResultsFolderPath(rootArtifactsFolderPath), clockSpan.GetTimeSpan(), validationErrors);
logger.WriteLineHeader("// ***** BenchmarkRunner: Finish *****");
logger.WriteLine();
logger.WriteLineHeader("// * Export *");
var currentDirectory = Directory.GetCurrentDirectory();
foreach (var file in config.GetCompositeExporter().ExportToFiles(summary))
{
logger.WriteLineInfo($" {file.Replace(currentDirectory, string.Empty).Trim('/', '\\')}");
}
logger.WriteLine();
logger.WriteLineHeader("// * Detailed results *");
// TODO: make exporter
foreach (var report in reports)
{
logger.WriteLineInfo(report.Benchmark.DisplayInfo);
var resultRuns = report.GetResultRuns();
if (resultRuns.IsEmpty())
{
logger.WriteLineError("There are no any results runs");
}
else
{
logger.WriteLineStatistic(resultRuns.GetStatistics().ToTimeStr());
}
logger.WriteLine();
}
LogTotalTime(logger, clockSpan.GetTimeSpan());
logger.WriteLine();
logger.WriteLineHeader("// * Summary *");
MarkdownExporter.Console.ExportToLog(summary, logger);
// TODO: make exporter
ConclusionHelper.Print(logger, config.GetCompositeAnalyser().Analyse(summary).ToList());
if (config.GetDiagnosers().Any())
{
logger.WriteLine();
config.GetCompositeDiagnoser().DisplayResults(logger);
}
logger.WriteLine();
logger.WriteLineHeader("// ***** BenchmarkRunner: End *****");
return(summary);
}
//Code is inspired by https://github.com/Microsoft/perfview/blob/master/src/PerfView/PerfViewData.cs#L5719-L5944
public IEnumerable <Metric> Parse()
{
using (var traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(etlFilePath)))
{
var eventSource = traceLog.Events.GetSource();
var bdnEventsParser = new EngineEventLogParser(eventSource);
var start = false;
var isFirstActualStartEnd = false;
long totalOperation = 0;
long countOfAllocatedObject = 0;
bdnEventsParser.WorkloadActualStart += data =>
{
if (!isFirstActualStartEnd)
{
start = true;
}
totalOperation = data.TotalOperations;
};
bdnEventsParser.WorkloadActualStop += data =>
{
start = false;
isFirstActualStartEnd = true;
};
var heapParser = new HeapTraceProviderTraceEventParser(eventSource);
// We index by heap address and then within the heap we remember the allocation stack
var heaps = new Dictionary <Address, Dictionary <Address, long> >();
Dictionary <Address, long> lastHeapAllocs = null;
Address lastHeapHandle = 0;
long nativeLeakSize = 0;
long totalAllocation = 0;
heapParser.HeapTraceAlloc += delegate(HeapAllocTraceData data)
{
if (!start)
{
return;
}
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
allocs[data.AllocAddress] = data.AllocSize;
checked
{
countOfAllocatedObject++;
nativeLeakSize += data.AllocSize;
totalAllocation += data.AllocSize;
}
};
heapParser.HeapTraceFree += delegate(HeapFreeTraceData data)
{
if (!start)
{
return;
}
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
if (allocs.TryGetValue(data.FreeAddress, out long alloc))
{
nativeLeakSize -= alloc;
allocs.Remove(data.FreeAddress);
}
};
heapParser.HeapTraceReAlloc += delegate(HeapReallocTraceData data)
{
if (!start)
{
return;
}
// Reallocs that actually move stuff will cause a Alloc and delete event
// so there is nothing to do for those events. But when the address is
// the same we need to resize.
if (data.OldAllocAddress != data.NewAllocAddress)
{
return;
}
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
// This is a clone of the Free code
if (allocs.TryGetValue(data.OldAllocAddress, out long alloc))
{
nativeLeakSize -= alloc;
allocs.Remove(data.OldAllocAddress);
}
// This is a clone of the Alloc code (sigh don't clone code)
allocs[data.NewAllocAddress] = data.NewAllocSize;
checked
{
nativeLeakSize += data.NewAllocSize;
}
};
heapParser.HeapTraceDestroy += delegate(HeapTraceData data)
{
if (!start)
{
return;
}
// Heap is dieing, kill all objects in it.
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
foreach (var alloc in allocs.Values)
{
nativeLeakSize -= alloc;
}
};
eventSource.Process();
logger.WriteLine();
logger.WriteLineHeader(LogSeparator);
logger.WriteLineInfo($"{benchmarkCase.DisplayInfo}");
logger.WriteLineHeader(LogSeparator);
if (totalOperation == 0)
{
logger.WriteLine($"Something went wrong. The trace file {etlFilePath} does not contain BenchmarkDotNet engine events.");
yield break;
}
var memoryAllocatedPerOperation = totalAllocation / totalOperation;
var memoryLeakPerOperation = nativeLeakSize / totalOperation;
logger.WriteLine($"Native memory allocated per single operation: {SizeValue.FromBytes(memoryAllocatedPerOperation).ToString(SizeUnit.B, benchmarkCase.Config.CultureInfo)}");
logger.WriteLine($"Count of allocated object: {countOfAllocatedObject / totalOperation}");
if (nativeLeakSize != 0)
{
logger.WriteLine($"Native memory leak per single operation: {SizeValue.FromBytes(memoryLeakPerOperation).ToString(SizeUnit.B, benchmarkCase.Config.CultureInfo)}");
}
var heapInfoList = heaps.Select(h => new { Address = h.Key, h.Value.Count, types = h.Value.Values });
foreach (var item in heapInfoList.Where(p => p.Count > 0))
{
logger.WriteLine($"Count of not deallocated object: {item.Count / totalOperation}");
}
yield return(new Metric(new AllocatedNativeMemoryDescriptor(), memoryAllocatedPerOperation));
yield return(new Metric(new NativeMemoryLeakDescriptor(), memoryLeakPerOperation));
}
}
public static Summary Run(BenchmarkRunInfo benchmarkRunInfo, ILogger logger, string title, string rootArtifactsFolderPath, Func <Job, IToolchain> toolchainProvider, IResolver resolver, List <string> artifactsToCleanup)
{
var benchmarks = benchmarkRunInfo.Benchmarks;
var config = benchmarkRunInfo.Config;
logger.WriteLineHeader("// ***** BenchmarkRunner: Start *****");
logger.WriteLineInfo("// Found benchmarks:");
foreach (var benchmark in benchmarks)
{
logger.WriteLineInfo($"// {benchmark.DisplayInfo}");
}
logger.WriteLine();
var validationErrors = Validate(benchmarks, logger, config);
if (validationErrors.Any(validationError => validationError.IsCritical))
{
return(Summary.CreateFailed(benchmarks, title, HostEnvironmentInfo.GetCurrent(), config, GetResultsFolderPath(rootArtifactsFolderPath), validationErrors));
}
var globalChronometer = Chronometer.Start();
var reports = new List <BenchmarkReport>();
var buildResults = BuildInParallel(logger, rootArtifactsFolderPath, toolchainProvider, resolver, benchmarks, config, ref globalChronometer);
foreach (var benchmark in benchmarks)
{
var buildResult = buildResults[benchmark];
if (!config.KeepBenchmarkFiles)
{
artifactsToCleanup.AddRange(buildResult.ArtifactsToCleanup);
}
if (buildResult.IsBuildSuccess)
{
var report = RunCore(benchmark, logger, config, rootArtifactsFolderPath, toolchainProvider, resolver, buildResult);
reports.Add(report);
if (report.GetResultRuns().Any())
{
logger.WriteLineStatistic(report.GetResultRuns().GetStatistics().ToTimeStr());
}
}
else
{
reports.Add(new BenchmarkReport(benchmark, buildResult, buildResult, null, null, default));
if (buildResult.GenerateException != null)
{
logger.WriteLineError($"// Generate Exception: {buildResult.GenerateException.Message}");
}
if (buildResult.BuildException != null)
{
logger.WriteLineError($"// Build Exception: {buildResult.BuildException.Message}");
}
}
logger.WriteLine();
}
var clockSpan = globalChronometer.GetElapsed();
var summary = new Summary(title, reports, HostEnvironmentInfo.GetCurrent(), config, GetResultsFolderPath(rootArtifactsFolderPath), clockSpan.GetTimeSpan(), validationErrors);
logger.WriteLineHeader("// ***** BenchmarkRunner: Finish *****");
logger.WriteLine();
logger.WriteLineHeader("// * Export *");
var currentDirectory = Directory.GetCurrentDirectory();
foreach (var file in config.GetCompositeExporter().ExportToFiles(summary, logger))
{
logger.WriteLineInfo($" {file.Replace(currentDirectory, string.Empty).Trim('/', '\\')}");
}
logger.WriteLine();
logger.WriteLineHeader("// * Detailed results *");
// TODO: make exporter
foreach (var report in reports)
{
logger.WriteLineInfo(report.Benchmark.DisplayInfo);
logger.WriteLineStatistic($"Runtime = {report.GetRuntimeInfo()}; GC = {report.GetGcInfo()}");
var resultRuns = report.GetResultRuns();
if (resultRuns.IsEmpty())
{
logger.WriteLineError("There are not any results runs");
}
else
{
logger.WriteLineStatistic(resultRuns.GetStatistics().ToTimeStr());
}
logger.WriteLine();
}
LogTotalTime(logger, clockSpan.GetTimeSpan());
logger.WriteLine();
logger.WriteLineHeader("// * Summary *");
MarkdownExporter.Console.ExportToLog(summary, logger);
// TODO: make exporter
ConclusionHelper.Print(logger, config.GetCompositeAnalyser().Analyse(summary).ToList());
// TODO: move to conclusions
var columnWithLegends = summary.Table.Columns.Select(c => c.OriginalColumn).Where(c => !string.IsNullOrEmpty(c.Legend)).ToList();
var effectiveTimeUnit = summary.Table.EffectiveSummaryStyle.TimeUnit;
if (columnWithLegends.Any() || effectiveTimeUnit != null)
{
logger.WriteLine();
logger.WriteLineHeader("// * Legends *");
int maxNameWidth = 0;
if (columnWithLegends.Any())
{
maxNameWidth = Math.Max(maxNameWidth, columnWithLegends.Select(c => c.ColumnName.Length).Max());
}
if (effectiveTimeUnit != null)
{
maxNameWidth = Math.Max(maxNameWidth, effectiveTimeUnit.Name.Length + 2);
}
foreach (var column in columnWithLegends)
{
logger.WriteLineHint($" {column.ColumnName.PadRight(maxNameWidth, ' ')} : {column.Legend}");
}
if (effectiveTimeUnit != null)
{
logger.WriteLineHint($" {("1 " + effectiveTimeUnit.Name).PadRight(maxNameWidth, ' ')} :" +
$" 1 {effectiveTimeUnit.Description} ({TimeUnit.Convert(1, effectiveTimeUnit, TimeUnit.Second).ToStr("0.#########")} sec)");
}
}
if (config.GetDiagnosers().Any())
{
logger.WriteLine();
config.GetCompositeDiagnoser().DisplayResults(logger);
}
logger.WriteLine();
logger.WriteLineHeader("// ***** BenchmarkRunner: End *****");
return(summary);
}
private static Summary Run(Benchmark[] benchmarks, ILogger logger, string title, IConfig config, string rootArtifactsFolderPath)
{
logger.WriteLineHeader("// ***** BenchmarkRunner: Start *****");
logger.WriteLineInfo("// Found benchmarks:");
foreach (var benchmark in benchmarks)
{
logger.WriteLineInfo($"// {benchmark.ShortInfo}");
}
logger.WriteLine();
var validationErrors = Validate(benchmarks, logger, config);
if (validationErrors.Any(validationError => validationError.IsCritical))
{
return(Summary.CreateFailed(benchmarks, title, EnvironmentInfo.GetCurrent(), config, GetResultsFolderPath(rootArtifactsFolderPath), validationErrors));
}
var globalChronometer = Chronometer.Start();
var reports = new List <BenchmarkReport>();
foreach (var benchmark in benchmarks)
{
var report = Run(benchmark, logger, config, rootArtifactsFolderPath);
reports.Add(report);
if (report.GetResultRuns().Any())
{
logger.WriteLineStatistic(report.GetResultRuns().GetStatistics().ToTimeStr());
}
logger.WriteLine();
}
var clockSpan = globalChronometer.Stop();
var summary = new Summary(title, reports, EnvironmentInfo.GetCurrent(), config, GetResultsFolderPath(rootArtifactsFolderPath), clockSpan.GetTimeSpan(), validationErrors);
logger.WriteLineHeader("// ***** BenchmarkRunner: Finish *****");
logger.WriteLine();
logger.WriteLineHeader("// * Export *");
var currentDirectory = Directory.GetCurrentDirectory();
foreach (var file in config.GetCompositeExporter().ExportToFiles(summary))
{
logger.WriteLineInfo($" {file.Replace(currentDirectory, string.Empty).Trim('/', '\\')}");
}
logger.WriteLine();
logger.WriteLineHeader("// * Detailed results *");
// TODO: make exporter
foreach (var report in reports)
{
logger.WriteLineInfo(report.Benchmark.ShortInfo);
logger.WriteLineStatistic(report.GetResultRuns().GetStatistics().ToTimeStr());
logger.WriteLine();
}
LogTotalTime(logger, clockSpan.GetTimeSpan());
logger.WriteLine();
logger.WriteLineHeader("// * Summary *");
MarkdownExporter.Console.ExportToLog(summary, logger);
// TODO: make exporter
var warnings = config.GetCompositeAnalyser().Analyse(summary).ToList();
if (warnings.Count > 0)
{
logger.WriteLine();
logger.WriteLineError("// * Warnings * ");
foreach (var warning in warnings)
{
logger.WriteLineError($"{warning.Message}");
}
}
if (config.GetDiagnosers().Count() > 0)
{
logger.WriteLine();
config.GetCompositeDiagnoser().DisplayResults(logger);
}
logger.WriteLine();
logger.WriteLineHeader("// ***** BenchmarkRunner: End *****");
return(summary);
}
//Code is inspired by https://github.com/Microsoft/perfview/blob/master/src/PerfView/PerfViewData.cs#L5719-L5944
private IEnumerable <Metric> Parse(TraceLog traceLog)
{
var stackSource = new MutableTraceEventStackSource(traceLog);
var eventSource = traceLog.Events.GetSource();
var bdnEventsParser = new EngineEventLogParser(eventSource);
var start = false;
var isFirstActualStartEnd = false;
long totalOperation = 0;
long countOfAllocatedObject = 0;
bdnEventsParser.WorkloadActualStart += data =>
{
if (!isFirstActualStartEnd)
{
start = true;
}
totalOperation = data.TotalOperations;
};
bdnEventsParser.WorkloadActualStop += data =>
{
start = false;
isFirstActualStartEnd = true;
};
var heapParser = new HeapTraceProviderTraceEventParser(eventSource);
// We index by heap address and then within the heap we remember the allocation stack
var heaps = new Dictionary <Address, Dictionary <Address, long> >();
Dictionary <Address, long> lastHeapAllocs = null;
Address lastHeapHandle = 0;
long nativeLeakSize = 0;
long totalAllocation = 0;
heapParser.HeapTraceAlloc += delegate(HeapAllocTraceData data)
{
if (!start)
{
return;
}
var call = data.CallStackIndex();
var frameIndex = stackSource.GetCallStack(call, data);
if (!IsCallStackIn(frameIndex))
{
return;
}
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
allocs[data.AllocAddress] = data.AllocSize;
checked
{
countOfAllocatedObject++;
nativeLeakSize += data.AllocSize;
totalAllocation += data.AllocSize;
}
bool IsCallStackIn(StackSourceCallStackIndex index)
{
while (index != StackSourceCallStackIndex.Invalid)
{
var frame = stackSource.GetFrameIndex(index);
var name = stackSource.GetFrameName(frame, false);
if (name.StartsWith(moduleName, StringComparison.Ordinal) &&
name.IndexOf(functionName, StringComparison.Ordinal) > 0)
{
return(true);
}
index = stackSource.GetCallerIndex(index);
}
return(false);
}
};
heapParser.HeapTraceFree += delegate(HeapFreeTraceData data)
{
if (!start)
{
return;
}
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
if (allocs.TryGetValue(data.FreeAddress, out long alloc))
{
nativeLeakSize -= alloc;
allocs.Remove(data.FreeAddress);
}
};
heapParser.HeapTraceReAlloc += delegate(HeapReallocTraceData data)
{
if (!start)
{
return;
}
// Reallocs that actually move stuff will cause a Alloc and delete event
// so there is nothing to do for those events. But when the address is
// the same we need to resize.
if (data.OldAllocAddress != data.NewAllocAddress)
{
return;
}
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
if (allocs.TryGetValue(data.OldAllocAddress, out long alloc))
{
// Free
nativeLeakSize -= alloc;
allocs.Remove(data.OldAllocAddress);
// Alloc
allocs[data.NewAllocAddress] = data.NewAllocSize;
checked
{
nativeLeakSize += data.NewAllocSize;
}
}
};
heapParser.HeapTraceDestroy += delegate(HeapTraceData data)
{
if (!start)
{
return;
}
// Heap is dieing, kill all objects in it.
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
foreach (var alloc in allocs.Values)
{
nativeLeakSize -= alloc;
}
};
eventSource.Process();
logger.WriteLine();
logger.WriteLineHeader(LogSeparator);
logger.WriteLineInfo($"{benchmarkCase.DisplayInfo}");
logger.WriteLineHeader(LogSeparator);
if (totalOperation == 0)
{
logger.WriteLine($"Something went wrong. The trace file {etlFilePath} does not contain BenchmarkDotNet engine events.");
return(Enumerable.Empty <Metric>());
}
var memoryAllocatedPerOperation = totalAllocation / totalOperation;
var memoryLeakPerOperation = nativeLeakSize / totalOperation;
logger.WriteLine($"Native memory allocated per single operation: {SizeValue.FromBytes(memoryAllocatedPerOperation).ToString(SizeUnit.B, benchmarkCase.Config.CultureInfo)}");
logger.WriteLine($"Count of allocated object: {countOfAllocatedObject / totalOperation}");
if (nativeLeakSize != 0)
{
logger.WriteLine($"Native memory leak per single operation: {SizeValue.FromBytes(memoryLeakPerOperation).ToString(SizeUnit.B, benchmarkCase.Config.CultureInfo)}");
}
var heapInfoList = heaps.Select(h => new { Address = h.Key, h.Value.Count, types = h.Value.Values });
foreach (var item in heapInfoList.Where(p => p.Count > 0))
{
logger.WriteLine($"Count of not deallocated object: {item.Count / totalOperation}");
}
return(new[]
{
new Metric(new AllocatedNativeMemoryDescriptor(), memoryAllocatedPerOperation),
new Metric(new NativeMemoryLeakDescriptor(), memoryLeakPerOperation)
});
}
