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