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