From 608066db7c7de8ded4c38a6e436e6f84324b4298 Mon Sep 17 00:00:00 2001 From: Alois Kraus <101576413+AloisKraus@users.noreply.github.com> Date: Mon, 29 Jan 2024 17:01:19 +0100 Subject: [PATCH] Readymetrics (#81) * Added new ProcessKey extension to resolve ETWProcessIndex from ProcessKey * Fix .NET 4.8 app.config binding to System.Runtime.CompilerServices.Unsafe * Suppress windows platfrom warnings. * - Extract average process priority from CPU sampling data. * Fix GetProcessIndexByPidAtTime which would not return the index when process start or end time was given. * - Dump Process Priority to CSV and print besides exe - Added -NoPriority flag to get old output * -Extend Percentile to decimal and long * - Collect for Ready Times idle and non idle times - Print idle and non-idle ready times - Fixed column algnment * For .NET 8.0 use 1 to use server GC with a dynamic number of GC Heaps instead of the currently hard coded 4. This shows significant memory savings in high memory pressure scenarios. * - Fix BuildProcessIndexCache during extraction. Process name can be null for processes which are still existing as ID but no name can be retrieved. * - Fix Priority alignment when -NoPriority is used in CPU Total mode - Reordered CSV columns and added NonIdle Ready Times The idle and non idle cswitch counts can be off by the total context switch count because for each method we only calculate percentiles if at least 50 CSwitch events were found. - Fix output regressions due to new column in tests * Add extended CPU Ready Metric integrationt tests * - Fix bug slice.PreviousActivityOnProcessor.Process.Id does not return the idle process (it is always 0) instead slice?.Wait?.ReadyThreadEvent?.ReadyingProcess?.Id is the correct one to get the extracted data to match with WPA. - Adapted test data to match with values displayed in WPA * Fix unit tests * ETWAnalyzer 3.0.0.1 Renamed properties to reflect that we measure C1 states from idle and own process which we call DeeSleep Read Times. All others are non deep sleep states. * Renamed detailed output and made output more compact. Added sum of all values which are >99% of all events to make it easy to check if some mount everest outliers are responsible for the majority of delays * - Added to Ready data >99% sum to get total sum and sum of mount everest outliers to be able to judge the overal distribution shape. - Fixed formatting when only stacktags are visible - Added to CSV data Sum and 99% sum columns * - Extract P/E core consumption when CPU has E-Cores present regardless if we have collected Frequency data. * - Dump CPU print frequency data only when we did collect frqeuency data. - Renamed ReadyTimes to stay consistent with file naming * -Added to -Dump CPU -SortOrder Priority which only sorts in CPU total mode. * - Extract Power Parse events not exposed by TraceProcessing on our own: Autonomous Mode BaseProfile HeteroPolicy HeteroThread HeteroThreadShort - Dump Power print newly exposed properties - Dump Power fixed issue where too many files were supressed in diff mode * -Dump Power fix file name width formatting. * -dump Power optimize single file name case output. * Added to -dump Power -extract Power currently active power profile to extract and displayed data. * -Dump Power add to CSV newly added columns. * Revert change to use slice?.Wait?.ReadyThreadEvent?.ReadyingProcess?.Id == WindowsConstants.IdleProcessId and use slice.PreviousActivityOnProcessor.Process.Id == WindowsConstants.IdleProcessId && slice?.SwitchIn?.ContextSwitch?.PreviousCState == 1 again which is the correct way. When PreviousCState is 1 it must have been switched by the dile thread. * -Dump Stats print CPU Topology for P and E Cores in NumberOfProcessors and SpeedMHz * Fix: Spurious Frequency data even when not explicitely recorded. * Error messge spelling * Simplify Code * Fix issue when CPU topology returns wrong core count * -Dump Power fix issue if multiple files contain the same power setting but in the end 0 files are printed. Now we print the skipped files and keep of each group the first file so we print one file of an identical power settings group. * -Dump Power fix skip message. * Fix: Do not crash when CPU topology data is not present. * -Extract - Added -NoCSwitch and -NoSampling to ignore CPU sampling or context switch data when extracing CPU or stacktag data. - Added extraction of process pirorities via Context Switch events in addition to CPU sampling data. --- ETWAnalyzer/Analyzers/ProcessExtensions.cs | 18 +- ETWAnalyzer/App.config | 6 +- ETWAnalyzer/Commands/DumpCommand.cs | 13 +- ETWAnalyzer/Commands/ExtractCommand.cs | 28 +- ETWAnalyzer/ETWAnalyzer.csproj | 4 +- ETWAnalyzer/EventDump/DumpBase_T.cs | 1 + ETWAnalyzer/EventDump/DumpCPUMethod.cs | 362 +++++++++++----- ETWAnalyzer/EventDump/DumpFileDirBase.cs | 4 + ETWAnalyzer/EventDump/DumpPower.cs | 177 +++++++- ETWAnalyzer/EventDump/DumpStats.cs | 58 ++- ETWAnalyzer/Extract/CPU/CPUStats.cs | 26 +- .../Extract/CPU/Extended/CPUExtended.cs | 11 + .../Extract/CPU/Extended/FrequencySource.cs | 2 +- .../Extract/CPU/Extended/IReadyTimes.cs | 142 ------- .../Extract/CPU/Extended/ReadyTimes.cs | 400 ++++++++++++++++++ ETWAnalyzer/Extract/CPU/ICPUStats.cs | 5 + ETWAnalyzer/Extract/ETWExtract.cs | 2 +- ETWAnalyzer/Extract/Power/BasePowerProfile.cs | 36 ++ .../Power/HeteroThreadSchedulingPolicy.cs | 42 ++ .../Extract/Power/IPowerConfiguration.cs | 38 +- .../Extract/Power/PowerConfiguration.cs | 74 +++- ETWAnalyzer/Extractors/CPU/CPUExtractor.cs | 180 +++++++- ETWAnalyzer/Extractors/CPU/CPUMethodData.cs | 145 +++++-- .../Extractors/CPU/CpuFrequencyExtractor.cs | 25 +- .../Extractors/CPU/StackTagExtractor.cs | 65 ++- ETWAnalyzer/Extractors/ExtractSerializer.cs | 4 +- .../Extractors/MachineDetailsExtractor.cs | 2 +- .../Extractors/Power/PowerExtractor.cs | 138 ++++++ ETWAnalyzer/Infrastructure/Numeric.cs | 91 ++++ ETWAnalyzer/Properties/AssemblyInfo.cs | 2 +- .../KernelPowerConstants.cs | 24 ++ ETWAnalyzer/runtimeconfig.template.json | 1 - ETWAnalyzer_iTest/ProgramTestsLong.cs | 52 ++- .../CPUPerProcessMethodListTests.cs | 2 +- .../EventDump/DumpCPUMethodTests.cs | 134 +++++- .../Extract/TimelineExtractorTests.cs | 2 +- ETWAnalyzer_uTest/GlobalSuppressions.cs | 1 + 37 files changed, 1927 insertions(+), 390 deletions(-) delete mode 100644 ETWAnalyzer/Extract/CPU/Extended/IReadyTimes.cs create mode 100644 ETWAnalyzer/Extract/CPU/Extended/ReadyTimes.cs create mode 100644 ETWAnalyzer/Extract/Power/BasePowerProfile.cs create mode 100644 ETWAnalyzer/Extract/Power/HeteroThreadSchedulingPolicy.cs create mode 100644 ETWAnalyzer/TraceProcessorHelpers/KernelPowerConstants.cs diff --git a/ETWAnalyzer/Analyzers/ProcessExtensions.cs b/ETWAnalyzer/Analyzers/ProcessExtensions.cs index 955dd2ac..299caf79 100644 --- a/ETWAnalyzer/Analyzers/ProcessExtensions.cs +++ b/ETWAnalyzer/Analyzers/ProcessExtensions.cs @@ -168,18 +168,30 @@ public static ETWProcess FindSingleProcessByName(TestDataFile file, string exeNa } /// - /// Find a process by its process key from a TestDataFile + /// Find a process by its process key from a TestDataFile. You should cache the results since it involves an array lookup! /// /// /// ProcessKey /// Found process or null if it was not found. public static ETWProcess FindProcessByKey(this TestDataFile file, ProcessKey key) { - if( key == null ) + return key.FindProcessByKey(file.Extract); + } + + /// + /// Find process by key in extracted data. You should cache the results since it involves an array lookup! + /// + /// + /// + /// Process or null if process was not found. + public static ETWProcess FindProcessByKey(this ProcessKey key, IETWExtract extract) + { + if (key == null) { return null; } - return file.Extract.Processes.Where(x => x.ProcessName != null && (x.ProcessID == key.Pid && key.Name == x.ProcessName) && ( x.StartTime == key.StartTime ) ).FirstOrDefault(); + + return extract.Processes.Where(x => x.ProcessName != null && (x.ProcessID == key.Pid && key.Name == x.ProcessName) && (x.StartTime == key.StartTime)).FirstOrDefault(); } /// diff --git a/ETWAnalyzer/App.config b/ETWAnalyzer/App.config index e2ba286c..b1ba87ab 100644 --- a/ETWAnalyzer/App.config +++ b/ETWAnalyzer/App.config @@ -12,8 +12,12 @@ + + + + - + C:\Symbols diff --git a/ETWAnalyzer/Commands/DumpCommand.cs b/ETWAnalyzer/Commands/DumpCommand.cs index 2489ba4e..8eaa2f1d 100644 --- a/ETWAnalyzer/Commands/DumpCommand.cs +++ b/ETWAnalyzer/Commands/DumpCommand.cs @@ -168,10 +168,11 @@ class DumpCommand : ArgParser " -topNMethods dd nn Include dd most expensive methods/stacktags which consume most CPU in trace. Optional nn skips the first nn lines." + Environment.NewLine + " -ThreadCount Show # of unique threads that did execute that method." + Environment.NewLine + " -ProcessFmt timefmt Add besides process name start/stop time and duration. See -TimeFmt for available options." + Environment.NewLine + - " -SortBy [CPU/Wait/CPUWait/CPUWaitReady/ReadyAvg/CSwitchCount/StackDepth/First/Last/TestTime/StartTime] Default method sort order is CPU consumption. Wait sorts by wait time, First/Last sorts by first/last occurrence of method/stacktags." + Environment.NewLine + + " -SortBy [CPU/Wait/CPUWait/CPUWaitReady/ReadyAvg/CSwitchCount/StackDepth/First/Last/Priority/TestTime/StartTime] Default method sort order is CPU consumption. Wait sorts by wait time, First/Last sorts by first/last occurrence of method/stacktags." + Environment.NewLine + " StackDepth shows hottest methods which consume most CPU but are deepest in the call stack." + Environment.NewLine + " StartTime sorts by process start time to correlate things in the order the processes were started." + Environment.NewLine + " TestTime can be used to force sort order of files by test time when -ShowTotal is used. When totals are enabled the files are sorted by highest totals." + Environment.NewLine + + " Sorting by process Priority is only applicable when you sort CPU totals without methods. " + Environment.NewLine + " -MinMaxCSwitchCount xx-yy or xx Filter by context switch count." + Environment.NewLine + " -MinMaxReadyAvgus xx-yy Filter by Ready Average time in us." + Environment.NewLine + " -MinMaxReadyMs xx-yy or xx Only include methods (stacktags have no recorded ready times) with a minimum ready time of [xx, yy] ms." + Environment.NewLine + @@ -179,7 +180,8 @@ class DumpCommand : ArgParser " -MinMaxWaitMs xx-yy or xx Only include methods/stacktags with a minimum wait time of [xx,yy] ms." + Environment.NewLine + " -Details Show additionally Session Id, Ready Average time, Context Switch Count, average CPU frequency per CPU efficiency class and ready percentiles." + Environment.NewLine + " -Normalize Normalize CPU time to 100% of CPU frequency. Enables comparison of CPU time independant of the used power profile." + Environment.NewLine + - " -NoFrequency When -Details is present do not print average CPU frequency and CPU usage per processor efficiency class (e.g. P/E Cores)." + Environment.NewLine + + " -NoFrequency When -Details is present do not print P/E core CPU usage and average frequency." + Environment.NewLine + + " -NoPriority Omit process Priority in total cpu mode and when methods are printed in -Details mode." + Environment.NewLine + " -NoReady Do not print Ready time, average or percentiles (when -Details is used) per method." + Environment.NewLine + " -Session dd;yy Filter processes by Windows session id. Multiple filters are separated by ;" + Environment.NewLine + " E.g. dd;dd2 will filter for all dd instances and dd2. The wildcards * and ? are supported for all filter strings." + Environment.NewLine + @@ -653,6 +655,7 @@ internal enum SortOrders StartTime, ReadyAvg, CSwitchCount, + Priority, // Process sort order StopTime, @@ -831,6 +834,8 @@ internal enum ZeroTimeModes public MinMaxRange MinMaxCSwitch { get; private set; } = new(); public bool NoReadyDetails { get; private set; } public bool NoFrequencyDetails { get; private set; } + public bool NoPriorityDetails { get; private set; } + public bool Normalize { get; private set; } @@ -1450,6 +1455,9 @@ public override void Parse() case "-nofrequency": NoFrequencyDetails = true; break; + case "-nopriority": + NoPriorityDetails = true; + break; case "-normalize": Normalize = true; break; @@ -1811,6 +1819,7 @@ public override void Run() MinMaxReadyMs = MinMaxReadyMs, NoReadyDetails = NoReadyDetails, NoFrequencyDetails = NoFrequencyDetails, + NoPriorityDetails = NoPriorityDetails, Normalize = Normalize, MinMaxReadyAverageUs = MinMaxReadyAverageUs, MinMaxCSwitch = MinMaxCSwitch, diff --git a/ETWAnalyzer/Commands/ExtractCommand.cs b/ETWAnalyzer/Commands/ExtractCommand.cs index b164c44c..c271d3fc 100644 --- a/ETWAnalyzer/Commands/ExtractCommand.cs +++ b/ETWAnalyzer/Commands/ExtractCommand.cs @@ -90,6 +90,8 @@ class ExtractCommand : ArgParser " must have been successfully loaded during extraction. Otherwise a warning is printed due to symbol loading errors." + Environment.NewLine + " -keepTemp If you want to analyze the ETL files more than once from compressed files you can use this option to keep the uncompressed ETL files in the output folder. " + Environment.NewLine + " -allCPU By default only methods with CPU or Wait > 10 ms are extracted. Used together with -extract CPU." + Environment.NewLine + + " -NoSampling Do not process CPU sampling data. Sometimes VMWare VMs produce invalid CPU sampling data. In that case you can ignore it and process only the Context Switch data. " + Environment.NewLine + + " -NoCSwitch Do not process Context Switch data. Useful to reduce memory consumption if you do not need CPU Wait/Ready timings." + Environment.NewLine + " -NoReady By default when Context switch data is present an extra Json file with extended CPU data is created." + Environment.NewLine + " You will miss with -Dump CPU -Details Ready time percentiles." + Environment.NewLine + " -allExceptions By default exceptions are filtered away by the rules configured in Configuration\\ExceptionFilters.xml. To get all specify this flag." + Environment.NewLine + @@ -143,6 +145,8 @@ class ExtractCommand : ArgParser internal const string AllCPUArg = "-allcpu"; internal const string ConcurrencyArg = "-concurrency"; internal const string DryRunArg = "-dryrun"; + internal const string NoSampling = "-nosampling"; + internal const string NoCSwitch = "-nocswitch"; @@ -335,6 +339,16 @@ public enum ExtractionOptions /// public int? Concurrency { get; private set; } + /// + /// -NoSampling Ignore CPU sampling data + /// + public bool IgnoreCPUSampling { get; private set; } + + /// + /// -NoCSwitch Ignore Context Switch data + /// + public bool IgnoreCSwitchData { get; private set; } + /// /// Create an extract command with given command line switches @@ -418,6 +432,12 @@ public override void Parse() case ChildArg: // -child IsChildProcess = true; break; + case NoSampling: + IgnoreCPUSampling = true; + break; + case NoCSwitch: + IgnoreCSwitchData = true; + break; case AllCPUArg: // -allcpu ExtractAllCPUData = true; break; @@ -493,7 +513,7 @@ public override void Parse() } ConfigureExtractors(Extractors, myProcessingActionList); - SetExtractorFilters(Extractors, ExtractAllCPUData, DisableExceptionFilter, TimelineDataExtractionIntervalS, Concurrency, NoReady); + SetExtractorFilters(Extractors, ExtractAllCPUData, DisableExceptionFilter, TimelineDataExtractionIntervalS, Concurrency, NoReady, IgnoreCPUSampling, IgnoreCSwitchData); } @@ -568,7 +588,7 @@ private static void SortDependantExtractors(List extractors) } } - static void SetExtractorFilters(List extractors, bool extractAllCpuData, bool disableExceptionFilter, float? timelineExtractionInterval, int ?concurrency, bool noReady) + static void SetExtractorFilters(List extractors, bool extractAllCpuData, bool disableExceptionFilter, float? timelineExtractionInterval, int ?concurrency, bool noReady, bool noSampling, bool noCSwitch) { var cpu = extractors.OfType().SingleOrDefault(); if (cpu != null) @@ -576,6 +596,8 @@ static void SetExtractorFilters(List extractors, bool extractAllC cpu.ExtractAllCPUData = extractAllCpuData; cpu.Concurrency = concurrency; cpu.NoReady = noReady; + cpu.NoSampling = noSampling; + cpu.NoCSwitch = noCSwitch; cpu.TimelineDataExtractionIntervalS = timelineExtractionInterval; } @@ -583,6 +605,8 @@ static void SetExtractorFilters(List extractors, bool extractAllC if( stacktag != null) { stacktag.Concurrency = concurrency; + stacktag.NoSampling = noSampling; + stacktag.NoCSwitch = noCSwitch; } var exception = extractors.OfType().SingleOrDefault(); diff --git a/ETWAnalyzer/ETWAnalyzer.csproj b/ETWAnalyzer/ETWAnalyzer.csproj index fa21165d..adb9cec9 100644 --- a/ETWAnalyzer/ETWAnalyzer.csproj +++ b/ETWAnalyzer/ETWAnalyzer.csproj @@ -22,8 +22,10 @@ True https://github.com/Siemens-Healthineers/ETWAnalyzer ProgramaticAccess.md - 3.0.0.0 + 3.0.0.1 x64 + true + 1 false diff --git a/ETWAnalyzer/EventDump/DumpBase_T.cs b/ETWAnalyzer/EventDump/DumpBase_T.cs index 6b70258d..92cd104a 100644 --- a/ETWAnalyzer/EventDump/DumpBase_T.cs +++ b/ETWAnalyzer/EventDump/DumpBase_T.cs @@ -35,6 +35,7 @@ abstract class DumpBase : DumpBase protected string Col_StartTime = "Start Time"; protected string Col_Time = "Time"; protected string Col_Machine = "Machine"; + protected string Col_AveragePriority = "Average Priority"; public override void Execute() diff --git a/ETWAnalyzer/EventDump/DumpCPUMethod.cs b/ETWAnalyzer/EventDump/DumpCPUMethod.cs index 85c3574f..df316a1a 100644 --- a/ETWAnalyzer/EventDump/DumpCPUMethod.cs +++ b/ETWAnalyzer/EventDump/DumpCPUMethod.cs @@ -47,7 +47,7 @@ class DumpCPUMethod : DumpFileDirBase /// /// Key is filter string, value is filter method /// - public KeyValuePair> StackTagFilter { get; internal set; } + public KeyValuePair> StackTagFilter { get; internal set; } /// /// When true we print only process total CPU information @@ -70,7 +70,7 @@ internal bool IsProcessTotalMode /// /// Do not indent by process but show process name on same line as method /// - public bool ShowDetailsOnMethodLine { get; internal set; } + public bool ShowDetailsOnMethodLine { get; internal set; } /// /// Omit command line in console and if configured in CSV output to reduce CSV size which is one of the largest string per line @@ -174,6 +174,11 @@ internal bool IsProcessTotalMode /// public bool Normalize { get; internal set; } + /// + /// Omit priority in output + /// + public bool NoPriorityDetails { get; internal set; } + /// @@ -202,7 +207,13 @@ internal bool IsProcessTotalMode /// /// Total CPU Header CPU column width /// - const int CPUTotal_CPUColumnWidth = 9; + const int CPUTotal_CPUColumnWidth = 9; + + /// + /// Total CPU column width + /// + const int CPUtotal_PriorityColumnWidth = 8; + /// /// Total CPU Header Process Name column width @@ -251,6 +262,8 @@ public class MatchData public ICPUUsage[] CPUUsage { get; internal set; } public IReadOnlyDictionary Topology { get; internal set; } public IReadyTimes ReadyDetails { get; internal set; } + public float ProcessPriority { get; internal set; } + public bool HasFrequencyData { get; internal set; } public override string ToString() { @@ -265,7 +278,7 @@ public override List ExecuteInternal() List matches = new(); - foreach(var test in testsOrderedByTime) + foreach (var test in testsOrderedByTime) { using (test.Value) // Release deserialized ETWExtract to keep memory footprint in check { @@ -279,7 +292,7 @@ public override List ExecuteInternal() { double zeroS = GetZeroTimeInS(file.Extract); // by default print only methods - if( (MethodFilter.Key == null && StackTagFilter.Key == null) || MethodFilter.Key != null) + if ((MethodFilter.Key == null && StackTagFilter.Key == null) || MethodFilter.Key != null) { AddPerMethodStats(matches, file, zeroS); } @@ -325,7 +338,7 @@ private void AddStackTagStats(List matches, TestDataFile file, double private void AddMatchingStackTags(List matches, TestDataFile file, IProcessStackTags tags, double zeroTimeS) { - if( tags == null) + if (tags == null) { return; } @@ -366,8 +379,8 @@ private void AddMatchingStackTags(List matches, TestDataFile file, IP ProcessAndPid = process.GetProcessWithId(UsePrettyProcessName), ProcessKey = process.ToProcessKey(), SourceFile = file.JsonExtractFileWhenPresent, - FirstCallTime = stacktag.FirstOccurence.AddSeconds(-1.0d* zeroTimeS), - LastCallTime = stacktag.FirstOccurence.AddSeconds(-1.0d* zeroTimeS) + stacktag.FirstLastOccurenceDuration, + FirstCallTime = stacktag.FirstOccurence.AddSeconds(-1.0d * zeroTimeS), + LastCallTime = stacktag.FirstOccurence.AddSeconds(-1.0d * zeroTimeS) + stacktag.FirstLastOccurenceDuration, FirstLastCallDurationS = (float)stacktag.FirstLastOccurenceDuration.TotalSeconds, SessionStart = file.Extract.SessionStart, Process = process, @@ -382,7 +395,7 @@ private void AddMatchingStackTags(List matches, TestDataFile file, IP private void AddPerMethodStats(List matches, TestDataFile file, double zeroTimeS) { - if( file.Extract?.CPU?.PerProcessMethodCostsInclusive == null) + if (file.Extract?.CPU?.PerProcessMethodCostsInclusive == null) { ColorConsole.WriteWarning($"Warning: File {file.JsonExtractFileWhenPresent} contains no CPU data."); return; @@ -392,7 +405,7 @@ private void AddPerMethodStats(List matches, TestDataFile file, doubl foreach (var perProcess in file.Extract.CPU.PerProcessMethodCostsInclusive.MethodStatsPerProcess) { - if ( !IsMatchingProcessAndCmdLine(file, perProcess.Process)) + if (!IsMatchingProcessAndCmdLine(file, perProcess.Process)) { continue; } @@ -403,35 +416,40 @@ private void AddPerMethodStats(List matches, TestDataFile file, doubl if (process != null) { - - DateTimeOffset lastCallTime = file.Extract.ConvertTraceRelativeToAbsoluteTime (methodCost.LastOccurenceInSecond - (float) zeroTimeS ); - DateTimeOffset firstCallTime = file.Extract.ConvertTraceRelativeToAbsoluteTime(methodCost.FirstOccurenceInSecond - (float) zeroTimeS ); + + DateTimeOffset lastCallTime = file.Extract.ConvertTraceRelativeToAbsoluteTime(methodCost.LastOccurenceInSecond - (float)zeroTimeS); + DateTimeOffset firstCallTime = file.Extract.ConvertTraceRelativeToAbsoluteTime(methodCost.FirstOccurenceInSecond - (float)zeroTimeS); ModuleDefinition module = null; ModuleDefinition exeModule = null; Driver driver = null; - if (ShowModuleInfo && file.Extract.Modules != null ) + if (ShowModuleInfo && file.Extract.Modules != null) { driver = Drivers.Default.TryGetDriverForModule(methodCost.Module); module = file.Extract.Modules.FindModule(methodCost.Module, process); exeModule = file.Extract.Modules.FindModule(process.ProcessName, process); } - if( !IsMatchingModule(module) ) // filter by module string + if (!IsMatchingModule(module)) // filter by module string { continue; } ICPUUsage[] cpuUsage = null; IReadyTimes readyTimes = null; + float prio = 0.0f; + bool hasFrequencyData = false; - if ( perProcess.Process.Pid > WindowsConstants.IdleProcessId) + if (perProcess.Process.Pid > WindowsConstants.IdleProcessId) { ETWProcessIndex idx = file.Extract.GetProcessIndexByPID(perProcess.Process.Pid, perProcess.Process.StartTime); + file.Extract?.CPU?.PerProcessAvgCPUPriority?.TryGetValue(idx, out prio); // get process priority + ProcessMethodIdx procMethod = idx.Create(methodCost.MethodIdx); - if ( file.Extract.CPU?.ExtendedCPUMetrics?.MethodIndexToCPUMethodData?.ContainsKey(procMethod) == true ) + if (file.Extract.CPU?.ExtendedCPUMetrics?.MethodIndexToCPUMethodData?.ContainsKey(procMethod) == true) { cpuUsage = file.Extract.CPU.ExtendedCPUMetrics.MethodIndexToCPUMethodData[procMethod].CPUConsumption; + hasFrequencyData = file.Extract.CPU.ExtendedCPUMetrics.HasFrequencyData; } IReadOnlyDictionary extendedCPUMetrics = file?.Extract?.CPU?.ExtendedCPUMetrics?.MethodIndexToCPUMethodData; @@ -442,6 +460,9 @@ private void AddPerMethodStats(List matches, TestDataFile file, doubl } } + + + matches.Add(new MatchData { TestName = file.TestName, @@ -453,9 +474,11 @@ private void AddPerMethodStats(List matches, TestDataFile file, doubl WaitMs = methodCost.WaitMs, ReadyMs = methodCost.ReadyMs, ReadyAverageUs = methodCost.ReadyAverageUs, + ProcessPriority = prio, ContextSwitchCount = methodCost.ContextSwitchCount, Threads = methodCost.Threads, - CPUUsage = cpuUsage, + CPUUsage = cpuUsage, + HasFrequencyData = hasFrequencyData, Topology = file?.Extract?.CPU?.Topology, ReadyDetails = readyTimes, HasCPUSamplingData = file.Extract.CPU.PerProcessMethodCostsInclusive.HasCPUSamplingData, @@ -475,7 +498,7 @@ private void AddPerMethodStats(List matches, TestDataFile file, doubl ExeModule = exeModule, Driver = driver, ZeroTimeS = zeroTimeS, - }) ; + }); } } } @@ -498,7 +521,7 @@ internal void AddAndPrintTotalStats(List matches, TestDataFile file) bool ProcessFilter(KeyValuePair procCPU) { bool lret = true; - if( !IsMatchingProcessAndCmdLine(file, procCPU.Key)) + if (!IsMatchingProcessAndCmdLine(file, procCPU.Key)) { lret = false; } @@ -512,7 +535,7 @@ bool ProcessFilter(KeyValuePair procCPU) } else { - if( process.ProcessID == 0) // exclude idle process + if (process.ProcessID == 0) // exclude DeepSleep process { lret = false; } @@ -520,7 +543,7 @@ bool ProcessFilter(KeyValuePair procCPU) } - if( lret && !MinMaxCPUMs.IsWithin( (int) procCPU.Value) ) + if (lret && !MinMaxCPUMs.IsWithin((int)procCPU.Value)) { lret = false; } @@ -532,6 +555,7 @@ bool ProcessFilter(KeyValuePair procCPU) // Then we skip the first N entries to show only the last TopNSafe results which are the highest values Dictionary lookupCache = new(); + Dictionary indexCache = new(); ETWProcess Lookup(ProcessKey key) { @@ -544,15 +568,30 @@ ETWProcess Lookup(ProcessKey key) return process; } + ETWProcessIndex LookupIndex(ProcessKey key) + { + if (!indexCache.TryGetValue(key, out ETWProcessIndex processIndex)) + { + processIndex = file.Extract.GetProcessIndexByPidAtTime(key.Pid, key.StartTime); + indexCache[key] = processIndex; + } + return processIndex; + } + List filtered = file.Extract.CPU.PerProcessCPUConsumptionInMs.Where(ProcessFilter).Select(x => { ETWProcess process = Lookup(x.Key); - if (process == null) { return null; } + ETWProcessIndex index = LookupIndex(x.Key); + if (index == ETWProcessIndex.Invalid) + { + return null; + } + ModuleDefinition module = ShowModuleInfo ? file.Extract.Modules.Modules.Where(x => x.Processes.Contains(process)).Where(x => x.ModuleName.EndsWith(".exe", StringComparison.OrdinalIgnoreCase)).FirstOrDefault() : null; if (!IsMatchingModule(module)) // filter by module string @@ -560,12 +599,16 @@ ETWProcess Lookup(ProcessKey key) return null; } + float prio = 0.0f; + file.Extract?.CPU.PerProcessAvgCPUPriority?.TryGetValue(index, out prio); + return new MatchData { TestName = file.TestName, PerformedAt = file.PerformedAt, DurationInMs = file.DurationInMs, CPUMs = x.Value, + ProcessPriority = prio, BaseLine = file.Extract.MainModuleVersion != null ? file.Extract.MainModuleVersion.ToString() : "", Method = "", ProcessAndPid = process.GetProcessWithId(UsePrettyProcessName), @@ -576,7 +619,7 @@ ETWProcess Lookup(ProcessKey key) Module = module, }; - }).Where(x=> x!=null).SortAscendingGetTopNLast(SortBySortOrder, null, TopN).ToList(); + }).Where(x => x != null).SortAscendingGetTopNLast(SortBySortOrder, null, TopN).ToList(); PrintTotalCPUHeaderOnce(); @@ -584,21 +627,21 @@ ETWProcess Lookup(ProcessKey key) if (!Merge) { string CpuString = ""; - if( (ShowTotal != null && ShowTotal != TotalModes.None)) + if ((ShowTotal != null && ShowTotal != TotalModes.None)) { - long cpuTotal = filtered.Select(x => (long) x.CPUMs).Sum(); + long cpuTotal = filtered.Select(x => (long)x.CPUMs).Sum(); CpuString = $" [green]CPU {cpuTotal:N0} ms[/green] "; } PrintFileName(file.JsonExtractFileWhenPresent, CpuString, file.PerformedAt, file.Extract.MainModuleVersion?.ToString()); } - + foreach (var cpu in filtered) { matches.Add(cpu); - if (!IsCSVEnabled && !Merge && !(ShowTotal == TotalModes.Total) ) + if (!IsCSVEnabled && !Merge && !(ShowTotal == TotalModes.Total)) { - PrintCPUTotal(cpu.CPUMs, cpu.Process, Path.GetFileNameWithoutExtension(file.FileName), file.Extract.SessionStart, matches[matches.Count-1].Module); + PrintCPUTotal(cpu.CPUMs, cpu.ProcessPriority, cpu.Process, Path.GetFileNameWithoutExtension(file.FileName), file.Extract.SessionStart, matches[matches.Count - 1].Module); } } } @@ -608,38 +651,62 @@ void PrintTotalCPUHeaderOnce() if (!IsCSVEnabled) { string cpuHeaderName = "CPU"; + string priorityHeaderName = ShowTotal == TotalModes.Total || NoPriorityDetails ? "" : "Priority".WithWidth(CPUtotal_PriorityColumnWidth)+" "; string processHeaderName = "Process Name"; - string sessionHeaderName = ShowDetails ? "Session ": ""; + string sessionHeaderName = ShowDetails ? "Session " : ""; if (myCPUTotalHeaderShown == false) { - ColorConsole.WriteEmbeddedColorLine($"\t[Green]{cpuHeaderName.WithWidth(CPUTotal_CPUColumnWidth)} ms[/Green] [yellow]{sessionHeaderName}{processHeaderName.WithWidth(CPUTotal_ProcessNameWidth)}[/yellow]"); + ColorConsole.WriteEmbeddedColorLine($"\t[Green]{cpuHeaderName.WithWidth(CPUTotal_CPUColumnWidth)} ms[/Green] [red]{priorityHeaderName}[/red][yellow]{sessionHeaderName}{processHeaderName.WithWidth(CPUTotal_ProcessNameWidth)}[/yellow]"); myCPUTotalHeaderShown = true; } } } - void PrintCPUTotal(long cpu, ETWProcess process, string sourceFile, DateTimeOffset sessionStart, ModuleDefinition exeModule) + /// + /// Format priority with color when it is greater 8 which is normal, or in a different color when it is below normal + /// + /// + /// + /// + string FormatPriorityColor(float priority, int width) + { + if (NoPriorityDetails || priority == 0) + { + return ""; + } + return priority >= 8.0f ? $"[red]{"F1".WidthFormat(priority, width)}[/red]" : $"[green]{"F1".WidthFormat(priority, width)}[/green]"; + } + + void PrintCPUTotal(long cpu, float priority, ETWProcess process, string sourceFile, DateTimeOffset sessionStart, ModuleDefinition exeModule) { string fileName = this.Merge ? $" {sourceFile}" : ""; string cpuStr = cpu.ToString("N0"); - string sessionIdStr = ShowDetails ? $"{process.SessionId, 7} " : ""; + string sessionIdStr = ShowDetails ? $"{process.SessionId,7} " : ""; string moduleInfo = ""; - if(exeModule != null) + if (exeModule != null) { moduleInfo = GetModuleString(exeModule, true); } + string prio = ""; + if (NoPriorityDetails == false && priority > 0) + { + prio = FormatPriorityColor(priority, CPUtotal_PriorityColumnWidth) + " "; + } + + + if (NoCmdLine) { - ColorConsole.WriteEmbeddedColorLine($"\t[Green]{cpuStr,CPUTotal_CPUColumnWidth} ms[/Green] [yellow]{process.GetProcessWithId(UsePrettyProcessName),CPUTotal_ProcessNameWidth}{GetProcessTags(process, sessionStart)}[/yellow]{fileName} [red]{moduleInfo}[/red]"); + ColorConsole.WriteEmbeddedColorLine($"\t[Green]{cpuStr,CPUTotal_CPUColumnWidth} ms[/Green] {prio}[yellow]{process.GetProcessWithId(UsePrettyProcessName),CPUTotal_ProcessNameWidth}{GetProcessTags(process, sessionStart)}[/yellow]{fileName} [red]{moduleInfo}[/red]"); } else { - ColorConsole.WriteEmbeddedColorLine($"\t[Green]{cpuStr,CPUTotal_CPUColumnWidth} ms[/Green] [yellow]{sessionIdStr}{process.GetProcessWithId(UsePrettyProcessName),CPUTotal_ProcessNameWidth}{GetProcessTags(process, sessionStart)}[/yellow] {process.CommandLineNoExe}", ConsoleColor.DarkCyan, true); + ColorConsole.WriteEmbeddedColorLine($"\t[Green]{cpuStr,CPUTotal_CPUColumnWidth} ms[/Green] {prio}[yellow]{sessionIdStr}{process.GetProcessWithId(UsePrettyProcessName),CPUTotal_ProcessNameWidth}{GetProcessTags(process, sessionStart)}[/yellow] {process.CommandLineNoExe}", ConsoleColor.DarkCyan, true); ColorConsole.WriteEmbeddedColorLine($" {fileName} [red]{moduleInfo}[/red]"); } } @@ -648,7 +715,7 @@ internal List PrintMatches(List matches) { List printed = new(); - if(IsProcessTotalMode) + if (IsProcessTotalMode) { ProcessTotalMatches(matches); } @@ -681,11 +748,11 @@ internal void ProcessPerMethodMatches(List matches, List p decimal overallCPUTotal = 0; decimal overallWaitTotal = 0; - (Dictionary fileTotals, - Dictionary> fileProcessTotals ) = GetFileAndProcessTotals(matches); + (Dictionary fileTotals, + Dictionary> fileProcessTotals) = GetFileAndProcessTotals(matches); // order files by test time (default) or by totals if enabled - List> byFileOrdered = matches.GroupBy(GetFileGroupName) + List> byFileOrdered = matches.GroupBy(GetFileGroupName) .OrderBy(CreateFileSorter(fileTotals)).ToList(); foreach (var fileGroup in byFileOrdered) @@ -709,11 +776,11 @@ internal void ProcessPerMethodMatches(List matches, List p FileTotals total = fileTotals[GetFileGroupName(firstFileGroup)]; overallCPUTotal += total.CPUMs; overallWaitTotal += total.WaitMs; - + fileTotalString = $" [green]CPU {"N0".WidthFormat(total.CPUMs, totalWidth)} ms[/green] " + - (waitFormatter.Header == "" ? "" : $"[yellow]Wait {"N0".WidthFormat(total.WaitMs, totalWidth)} ms[/yellow] ")+ + (waitFormatter.Header == "" ? "" : $"[yellow]Wait {"N0".WidthFormat(total.WaitMs, totalWidth)} ms[/yellow] ") + (readyFormatter.Header == "" ? "" : $"[red]Ready: {"N0".WidthFormat(total.ReadyMs, totalWidth)} ms[/red] ") + - ( (waitFormatter.Header == "" && readyFormatter.Header == "") ? "" : $"[magenta]Total {"N0".WidthFormat(total.GetTotal(SortOrder), totalWidth)} ms[/magenta] "); + ((waitFormatter.Header == "" && readyFormatter.Header == "") ? "" : $"[magenta]Total {"N0".WidthFormat(total.GetTotal(SortOrder), totalWidth)} ms[/magenta] "); } PrintFileName(firstFileGroup.SourceFile, fileTotalString, firstFileGroup.PerformedAt, firstFileGroup.BaseLine); @@ -734,12 +801,12 @@ internal void ProcessPerMethodMatches(List matches, List p if (String.IsNullOrEmpty(CSVFile) && !ShowDetailsOnMethodLine) { string processTotalString = ""; - if(ShowTotal == TotalModes.Process || ShowTotal == TotalModes.Method) + if (ShowTotal == TotalModes.Process || ShowTotal == TotalModes.Method) { ProcessTotals processTotals = fileProcessTotals[GetFileGroupName(firstFileGroup)][firstProcessGroup.ProcessKey]; - processTotalString = $"[green]CPU {"N0".WidthFormat(processTotals.CPUMs, totalWidth)} ms[/green] "+ - (waitFormatter.Header == "" ? "" : $"[yellow]Wait: {"N0".WidthFormat(processTotals.WaitMs, totalWidth)} ms[/yellow] ")+ - (readyFormatter.Header == "" ? "" : $"[red]Ready: {"N0".WidthFormat(processTotals.ReadyMs, totalWidth)} ms[/red] ")+ + processTotalString = $"[green]CPU {"N0".WidthFormat(processTotals.CPUMs, totalWidth)} ms[/green] " + + (waitFormatter.Header == "" ? "" : $"[yellow]Wait: {"N0".WidthFormat(processTotals.WaitMs, totalWidth)} ms[/yellow] ") + + (readyFormatter.Header == "" ? "" : $"[red]Ready: {"N0".WidthFormat(processTotals.ReadyMs, totalWidth)} ms[/red] ") + ((waitFormatter.Header == "" && readyFormatter.Header == "") ? "" : $"[magenta]Total: {"N0".WidthFormat(processTotals.GetTotal(SortOrder), totalWidth)} ms[/magenta] "); } @@ -748,7 +815,12 @@ internal void ProcessPerMethodMatches(List matches, List p ETWProcess process = current.Process; string moduleString = current.ExeModule != null ? " " + GetModuleString(current.ExeModule, true) : ""; - ColorConsole.WriteEmbeddedColorLine($" {processTotalString}[grey]{process.GetProcessWithId(UsePrettyProcessName)}{GetProcessTags(process, current.SessionStart.AddSeconds(current.ZeroTimeS))}[/grey] {cmdLine}", ConsoleColor.DarkCyan, true); + string processPriority = ""; + if (!NoPriorityDetails && current.ProcessPriority > 0) + { + processPriority = ShowDetails ? $" Priority: {FormatPriorityColor(current.ProcessPriority, 0)}" : ""; + } + ColorConsole.WriteEmbeddedColorLine($" {processTotalString}[grey]{process.GetProcessWithId(UsePrettyProcessName)}{GetProcessTags(process, current.SessionStart.AddSeconds(current.ZeroTimeS))}[/grey]{processPriority} {cmdLine}", ConsoleColor.DarkCyan, true); ColorConsole.WriteEmbeddedColorLine($"[red]{moduleString}[/red]"); } @@ -784,10 +856,10 @@ internal void ProcessPerMethodMatches(List matches, List p ColorConsole.WriteEmbeddedColorLine($"{coreFrequencyFormatter.Print(match)}", ConsoleColor.Cyan, true); } - if ( readyDetailsFormatter.Header != "" && match.ReadyDetails != null) + if (readyDetailsFormatter.Header != "" && match.ReadyDetails != null) { - Console.WriteLine(); - ColorConsole.WriteEmbeddedColorLine($"[red] {readyDetailsFormatter.Print(match)}[/red]", null, true); + ColorConsole.WriteLine(""); + ColorConsole.WriteEmbeddedColorLine($"[red]{readyDetailsFormatter.Print(match)}[/red]", null, true); } @@ -820,7 +892,7 @@ internal void ProcessPerMethodMatches(List matches, List p if ((ShowTotal != null && ShowTotal != TotalModes.None) && !IsCSVEnabled) { - string crossFileTotal = (overallWaitTotal == 0 ? "Total " : $"[magenta]Total {overallCPUTotal + overallWaitTotal:N0} ms[/magenta] ") + + string crossFileTotal = (overallWaitTotal == 0 ? "Total " : $"[magenta]Total {overallCPUTotal + overallWaitTotal:N0} ms[/magenta] ") + $"[green]CPU {overallCPUTotal:N0} ms[/green] " + (overallWaitTotal == 0 ? "" : $"[yellow]Wait {overallWaitTotal:N0} ms[/yellow]"); ColorConsole.WriteEmbeddedColorLine(crossFileTotal); @@ -832,7 +904,7 @@ enum FormatterType Invalid = 0, CPU, FirstLast, - Wait, + Wait, Ready, ReadyAverage, CSwitchCount, @@ -841,6 +913,14 @@ enum FormatterType ReadyDetails, } + /// + /// true when only stacktags are printed. Some details like Ready, ThreadCount are not supported/implemented at stacktag level. + /// + bool IsOnlyStackTagActive + { + get => StackTagFilter.Key != null && (MethodFilter.Key == null || !TopNMethods.IsEmpty); + } + private Formatter GetHeaderFormatter(List matches, FormatterType type) { return type switch @@ -891,41 +971,41 @@ TimeFormats.UTC or }, FormatterType.Wait => new Formatter { - Header = matches.Any(x => x.HasCSwitchData.GetValueOrDefault() || x.WaitMs != 0) ? " Wait ms" : "", + Header = matches.Any(x => x.HasCSwitchData.GetValueOrDefault() || x.WaitMs != 0) ? " Wait ms " : "", Print = matches.Any(x => x.HasCSwitchData.GetValueOrDefault() || x.WaitMs != 0) ? (data) => " " + "N0".WidthFormat(data.WaitMs, 9) + " ms " : (data) => "", }, FormatterType.Ready => new Formatter { - // only data in enhanced format can contain ready data - Header = matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && !NoReadyDetails ? " Ready ms " : "", - Print = matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && !NoReadyDetails ? (data) => "N0".WidthFormat(data.ReadyMs, 6) + " ms " : (data) => "", + // only data in enhanced format can contain ready data and if not just stacktags are enabled + Header = !IsOnlyStackTagActive && matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && !NoReadyDetails ? " Ready ms " : "", + Print = !IsOnlyStackTagActive && matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && !NoReadyDetails ? (data) => "N0".WidthFormat(data.ReadyMs, 6) + " ms " : (data) => "", }, FormatterType.ReadyAverage => new Formatter { - Header = (matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && ShowDetails && !NoReadyDetails) ? "ReadyAvg " : "", - Print = (matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && ShowDetails && !NoReadyDetails) ? - (data) => (data.ReadyAverageUs > 0 ? $"{data.ReadyAverageUs,5} us " : "".WithWidth(5+4)) : + Header = (!IsOnlyStackTagActive && matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && ShowDetails && !NoReadyDetails) ? "ReadyAvg " : "", + Print = (!IsOnlyStackTagActive && matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && ShowDetails && !NoReadyDetails) ? + (data) => (data.ReadyAverageUs > 0 ? $"{data.ReadyAverageUs,5} us " : "".WithWidth(5 + 4)) : (data) => "", }, FormatterType.CSwitchCount => new Formatter { - Header = matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && ShowDetails ? " CSwitches " : "", - Print = matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && ShowDetails ? (data) => "N0".WidthFormat(data.ContextSwitchCount, 10) + " " : (data) => "", + Header = !IsOnlyStackTagActive && matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && ShowDetails ? " CSwitches " : "", + Print = !IsOnlyStackTagActive && matches.Any(x => x.HasCSwitchData.GetValueOrDefault()) && ShowDetails ? (data) => "N0".WidthFormat(data.ContextSwitchCount, 10) + " " : (data) => "", }, FormatterType.Frequency => new Formatter { Header = ShowDetails && !NoFrequencyDetails && matches.Any(x => x.CPUUsage != null) ? "CoreData" : "", - Print = ShowDetails && !NoFrequencyDetails && matches.Any(x => x.CPUUsage != null) ? FormatCoreData : (data) => "", + Print = ShowDetails && !NoFrequencyDetails && matches.Any(x => x.CPUUsage != null) ? FormatCoreData : (data) => "", }, FormatterType.ThreadCount => new Formatter { - Header = ThreadCount ? "#Threads " : "", - Print = (data) => ThreadCount ? "#" + "N0".WidthFormat(data.Threads, -9) : "", + Header = !IsOnlyStackTagActive && ThreadCount ? "#Threads " : "", + Print = (data) => !IsOnlyStackTagActive && ThreadCount ? "#" + "N0".WidthFormat(data.Threads, -9) : "", }, FormatterType.ReadyDetails => new Formatter { Header = ShowDetails && !NoReadyDetails && matches.Any(x => x.ReadyDetails != null) ? "ReadyDetails" : "", - Print = ShowDetails && !NoReadyDetails && matches.Any(x=> x.ReadyDetails != null ) ? FormatReadyData : (data) => "", + Print = ShowDetails && !NoReadyDetails && matches.Any(x => x.ReadyDetails != null) ? FormatReadyData : (data) => "", }, _ => throw new NotSupportedException($"Formatter {type} is not supported"), }; @@ -941,7 +1021,24 @@ private string FormatReadyData(MatchData data) string lret = ""; if (data.ReadyDetails != null) { - lret = "".WithWidth(3) + $"Min: {data.ReadyDetails.MinUs:F1} us 5% {data.ReadyDetails.Percentile5:F1} us 25% {data.ReadyDetails.Percentile25:F1} us 50% {data.ReadyDetails.Percentile50:F1} us 90%: {data.ReadyDetails.Percentile90:F1} us 95%: {data.ReadyDetails.Percentile95:F1} us Max: {data.ReadyDetails.MaxUs:F1} us"; + if (data.ReadyDetails.HasDeepSleepTimes) + { + lret = $" CPU Wakeup Ready Min/5%/25%/50%/90%/95%/99%/Max Percentiles in us: {"F1".WidthFormat(data.ReadyDetails.MinDeepSleepUs, 3)} {"F1".WidthFormat(data.ReadyDetails.Percentile5DeepSleepUs, 4)} {"F1".WidthFormat(data.ReadyDetails.Percentile25DeepSleepUs, 4)} {"F1".WidthFormat(data.ReadyDetails.Percentile50DeepSleepUs, 4)} " + + $"{"F0".WidthFormat(data.ReadyDetails.Percentile90DeepSleepUs, 5)} {"F0".WidthFormat(data.ReadyDetails.Percentile95DeepSleepUs, 5)} {"F0".WidthFormat(data.ReadyDetails.Percentile99DeepSleepUs, 5)} {"F0".WidthFormat(data.ReadyDetails.MaxDeepSleepUs, 7)} us >99% Sum: {"F4".WidthFormat(data.ReadyDetails.SumGreater99PercentDeepSleepUs/1_000_000.0,8)} s " + + $"Sum: {"F4".WidthFormat(data.ReadyDetails.SumDeepSleepUs / 1_000_000.0d, 8)} s Count: {"N0".WidthFormat(data.ReadyDetails.CSwitchCountDeepSleep, 10)}"; + } + if (lret != "" && data.ReadyDetails.HasNonDeepSleepTimes) + { + lret += Environment.NewLine; + } + + if (data.ReadyDetails.HasNonDeepSleepTimes) + { + int spaces = data.ReadyDetails.HasNonDeepSleepTimes ? 5 : 0; + lret += "".WithWidth(spaces) + $" Other Ready Min/5%/25%/50%/90%/95%/99%/Max Percentiles in us: {"F1".WidthFormat(data.ReadyDetails.MinNonDeepSleepUs, 3)} {"F1".WidthFormat(data.ReadyDetails.Percentile5NonDeepSleepUs, 4)} {"F1".WidthFormat(data.ReadyDetails.Percentile25NonDeepSleepUs, 4)} {"F1".WidthFormat(data.ReadyDetails.Percentile50NonDeepSleepUs, 4)} " + + $"{"F0".WidthFormat(data.ReadyDetails.Percentile90NonDeepSleepUs, 5)} {"F0".WidthFormat(data.ReadyDetails.Percentile95NonDeepSleepUs, 5)} {"F0".WidthFormat(data.ReadyDetails.Percentile99NonDeepSleepUs, 5)} {"F0".WidthFormat(data.ReadyDetails.MaxNonDeepSleepUs, 7)} us " + + $">99% Sum: {"F4".WidthFormat(data.ReadyDetails.SumGreater99PercentNonDeepSleepUs/1_000_000.0d, 8)} s Sum: {"F4".WidthFormat(data.ReadyDetails.SumNonDeepSleepUs / 1_000_000.0d, 8)} s Count: {"N0".WidthFormat(data.ReadyDetails.CSwitchCountNonDeepSleep, 10)}"; + } } return lret; } @@ -954,29 +1051,35 @@ private string FormatReadyData(MatchData data) string FormatCoreData(MatchData data) { string lret = ""; - if( data.CPUUsage!= null ) + if (data.CPUUsage != null) { int totalCPUMs = data.CPUUsage.Sum(x => x.CPUMs); int totalNormalizedCPUMs = 0; - foreach(var usage in data.CPUUsage.OrderByDescending(x=>x.EfficiencyClass)) + foreach (var usage in data.CPUUsage.OrderByDescending(x => x.EfficiencyClass)) { float percentAboveNominal = (100.0f * usage.AverageMHz / data.Topology.First(x => x.Value.EfficiencyClass == usage.EfficiencyClass).Value.NominalFrequencyMHz); - + string cpuPercent = $"{(100.0f * usage.CPUMs / totalCPUMs):F0}".WithWidth(3); string normalizedCPU = ""; - if( Normalize ) + if (Normalize) { float factor = (percentAboveNominal / 100.0f); - int normalizedCPUMs = (int) (usage.CPUMs * factor); // Scale CPU to 100% CPU Frequency + int normalizedCPUMs = (int)(usage.CPUMs * factor); // Scale CPU to 100% CPU Frequency totalNormalizedCPUMs += normalizedCPUMs; normalizedCPU = $"N0".WidthFormat(normalizedCPUMs, 10) + " ms "; } - lret += " [green]" + $"N0".WidthFormat(usage.CPUMs, 10) + $" ms {normalizedCPU}[/green]"+ $"Class: {usage.EfficiencyClass} " + $"({cpuPercent} % CPU) on {usage.UsedCores,2} Cores " + "N0".WidthFormat(usage.AverageMHz, 5) + $" MHz ({(int)percentAboveNominal,3}% Frequency) " + $"Enabled Cores: {usage.EnabledCPUsAvg,2} Duration: {usage.LastS- usage.FirstS:F3} s" + Environment.NewLine; + + string frequencyPart = ""; + if( data.HasFrequencyData) + { + frequencyPart = "N0".WidthFormat(usage.AverageMHz, 5) + $" MHz ({(int)percentAboveNominal,3}% Frequency) "; + } + lret += " [green]" + $"N0".WidthFormat(usage.CPUMs, 10) + $" ms {normalizedCPU}[/green]" + $"Class: {usage.EfficiencyClass} " + $"({cpuPercent} % CPU) on {usage.UsedCores,2} Cores " + frequencyPart + $"Enabled Cores: {usage.EnabledCPUsAvg,2} Duration: {usage.LastS - usage.FirstS:F3} s" + Environment.NewLine; } - if( Normalize && data.CPUUsage.Length > 1 ) + if (Normalize && data.CPUUsage.Length > 1) { - lret += "".WithWidth(4) + $"[green]Normalized: {"N0".WidthFormat(totalNormalizedCPUMs,10)} ms [/green]"; + lret += "".WithWidth(4) + $"[green]Normalized: {"N0".WidthFormat(totalNormalizedCPUMs, 10)} ms [/green]"; } } return lret.TrimEnd(StringFormatExtensions.NewLineChars); @@ -1013,7 +1116,7 @@ public decimal GetTotal(SortOrders order) internal class ProcessTotals : FileTotals { - + } /// @@ -1021,7 +1124,7 @@ internal class ProcessTotals : FileTotals /// /// /// Dictionary of file name as key and value is the total per file sum - internal (Dictionary, Dictionary>) GetFileAndProcessTotals(List matches) + internal (Dictionary, Dictionary>) GetFileAndProcessTotals(List matches) { Dictionary fileTotals = new(); Dictionary> fileProcessTotals = new(); @@ -1047,13 +1150,13 @@ internal class ProcessTotals : FileTotals foreach (MatchData data in filteredSubItems) { - if( !fileProcessTotals.TryGetValue(GetFileGroupName(data), out Dictionary processDict) ) + if (!fileProcessTotals.TryGetValue(GetFileGroupName(data), out Dictionary processDict)) { processDict = new(); fileProcessTotals.Add(GetFileGroupName(data), processDict); } - if ( !processDict.TryGetValue(data.ProcessKey, out ProcessTotals processTotals)) + if (!processDict.TryGetValue(data.ProcessKey, out ProcessTotals processTotals)) { processTotals = new(); processDict[data.ProcessKey] = processTotals; @@ -1126,15 +1229,6 @@ private void WritePerMethodCsvLine(MatchData match, float firstLastDurationS, st if (!myCSVHeaderPrinted) { OpenCSVWithHeader("CSVOptions", "Test Case", "Date", "Test Time in ms", "Module", "Method", "CPU ms", "Wait ms", "Ready ms", "Ready Average us", - "Ready Min us", - "Ready Max us", - "Ready 5% Percentile us", - "Ready 25% Percentile us", - "Ready 50% Percentile us (Median)", - "Ready 90% Percentile us", - "Ready 95% Percentile us", - "Ready 99% Percentile us", - "Context Switch Count", "CPU ms Efficiency Class 0", "Average Frequency Efficiency Class 0", "FrequencyRelativeToNominal % Efficiency Class 0", @@ -1144,22 +1238,39 @@ private void WritePerMethodCsvLine(MatchData match, float firstLastDurationS, st "FrequencyRelativeToNominal % Efficiency Class 1", "UsedCores Class 1", "Enabled Cores", - "# Threads", Col_Baseline, Col_Process, Col_ProcessName, Col_Session, "Start Time", "StackDepth", - "FirstLastCall Duration in s", $"First Call time in {GetAbbreviatedName(firstFormat)}", $"Last Call time in {GetAbbreviatedName(lastFormat)}", Col_CommandLine, "SourceFile", "IsNewProcess", "Module and Driver Info"); + "# Threads", + Col_AveragePriority, + Col_Baseline, Col_Process, Col_ProcessName, Col_Session, "Start Time", "StackDepth", + "FirstLastCall Duration in s", $"First Call time in {GetAbbreviatedName(firstFormat)}", $"Last Call time in {GetAbbreviatedName(lastFormat)}", Col_CommandLine, "SourceFile", "IsNewProcess", "Module and Driver Info", + "DeepSleep Ready Min us", + "NonDeepSleep Ready Min us", + "DeepSleep Ready Max us", + "NonDeepSleep Ready Max us", + "DeepSleep Ready 5% Percentile us", + "NonDeepSleep Ready 5% Percentile us", + "DeepSleep Ready 25% Percentile us", + "NonDeepSleep Ready 25% Percentile us", + "DeepSleep Ready 50% Percentile us (Median)", + "NonDeepSleep Ready 50% Percentile us (Median)", + "DeepSleep Ready 90% Percentile us", + "NonDeepSleep Ready 90% Percentile us", + "DeepSleep Ready 95% Percentile us", + "NonDeepSleep Ready 95% Percentile us", + "DeepSleep Ready 99% Percentile us", + "NonDeepSleep Ready 99% Percentile us", + "NonDeepSleep Sum for > 99% Percentile us", + "DeepSleep Sum for > 99% Percentile us", + "NonDeepSleep Sum us", + "DeepSleep Sum us", + "DeepSleep Ready Count", + "NonDeepSleep Ready Count", + "Context Switch Count" + ); myCSVHeaderPrinted = true; } WriteCSVLine(CSVOptions, match.TestName, match.PerformedAt, match.DurationInMs, match.ModuleName, match.Method, match.CPUMs, match.WaitMs, match.ReadyMs, match.ReadyAverageUs, - match?.ReadyDetails?.MinUs, - match?.ReadyDetails?.MaxUs, - match?.ReadyDetails?.Percentile5, - match?.ReadyDetails?.Percentile25, - match?.ReadyDetails?.Percentile50, - match?.ReadyDetails?.Percentile90, - match?.ReadyDetails?.Percentile95, - match?.ReadyDetails?.Percentile99, - match.ContextSwitchCount, cpuClass0Ms, frequencyClass0MHz, frequencyRelativeToNominalPercentClass0, @@ -1169,8 +1280,46 @@ private void WritePerMethodCsvLine(MatchData match, float firstLastDurationS, st frequencyRelativeToNominalPercentClass1, usedCoresClass1, enabledCores, - match.Threads, match.BaseLine, match.ProcessAndPid, match.Process.GetProcessName(UsePrettyProcessName), match.Process.SessionId, match.Process.StartTime, match.CPUMs / Math.Exp(match.StackDepth), - firstLastDurationS, GetDateTimeString(match.FirstCallTime, match.SessionStart, firstFormat), GetDateTimeString(match.LastCallTime, match.SessionStart, lastFormat), NoCmdLine ? "" : match.Process.CmdLine, match.SourceFile, (match.Process.IsNew ? 1 : 0), moduleDriverInfo); + match.Threads, + GetNullIfZero(match.ProcessPriority), + match.BaseLine, match.ProcessAndPid, match.Process.GetProcessName(UsePrettyProcessName), match.Process.SessionId, match.Process.StartTime, match.CPUMs / Math.Exp(match.StackDepth), + firstLastDurationS, GetDateTimeString(match.FirstCallTime, match.SessionStart, firstFormat), GetDateTimeString(match.LastCallTime, match.SessionStart, lastFormat), NoCmdLine ? "" : match.Process.CmdLine, match.SourceFile, (match.Process.IsNew ? 1 : 0), + moduleDriverInfo, + + match?.ReadyDetails?.HasDeepSleepTimes == true ? match?.ReadyDetails?.MinDeepSleepUs : (double?) null, + match?.ReadyDetails?.HasNonDeepSleepTimes == true ? match?.ReadyDetails?.MinNonDeepSleepUs : (double?)null, + + match?.ReadyDetails?.HasDeepSleepTimes == true ? match?.ReadyDetails?.MaxDeepSleepUs : (double?)null, + match?.ReadyDetails?.HasNonDeepSleepTimes == true ? match?.ReadyDetails?.MaxNonDeepSleepUs : (double?)null, + + match?.ReadyDetails?.HasDeepSleepTimes == true ? match?.ReadyDetails?.Percentile5DeepSleepUs : (double?)null, + match?.ReadyDetails?.HasNonDeepSleepTimes == true ? match?.ReadyDetails?.Percentile5NonDeepSleepUs : (double?)null, + + match?.ReadyDetails?.HasDeepSleepTimes == true ? match?.ReadyDetails?.Percentile25DeepSleepUs : (double?)null, + match?.ReadyDetails?.HasNonDeepSleepTimes == true ? match?.ReadyDetails?.Percentile25NonDeepSleepUs : (double?)null, + + match?.ReadyDetails?.HasDeepSleepTimes == true ? match?.ReadyDetails?.Percentile50DeepSleepUs : (double?)null, + match?.ReadyDetails?.HasNonDeepSleepTimes == true ? match?.ReadyDetails?.Percentile50NonDeepSleepUs : (double?)null, + + match?.ReadyDetails?.HasDeepSleepTimes == true ? match?.ReadyDetails?.Percentile90DeepSleepUs : (double?)null, + match?.ReadyDetails?.HasNonDeepSleepTimes == true ? match?.ReadyDetails?.Percentile90NonDeepSleepUs : (double?)null, + + match?.ReadyDetails?.HasDeepSleepTimes == true ? match?.ReadyDetails?.Percentile95DeepSleepUs : (double?)null, + match?.ReadyDetails?.HasNonDeepSleepTimes == true ? match?.ReadyDetails?.Percentile95NonDeepSleepUs : (double?)null, + + match?.ReadyDetails?.HasDeepSleepTimes == true ? match?.ReadyDetails?.Percentile99DeepSleepUs : (double?)null, + match?.ReadyDetails?.HasNonDeepSleepTimes == true ? match?.ReadyDetails?.Percentile99NonDeepSleepUs : (double?)null, + + match?.ReadyDetails?.HasDeepSleepTimes == true ? match?.ReadyDetails?.SumGreater99PercentDeepSleepUs : (double?)null, + match?.ReadyDetails?.HasNonDeepSleepTimes == true ? match?.ReadyDetails?.SumGreater99PercentNonDeepSleepUs : (double?)null, + + match?.ReadyDetails?.HasDeepSleepTimes == true ? match?.ReadyDetails?.SumDeepSleepUs : (double?)null, + match?.ReadyDetails?.HasNonDeepSleepTimes == true ? match?.ReadyDetails?.SumNonDeepSleepUs : (double?)null, + + match?.ReadyDetails?.HasDeepSleepTimes == true ? match?.ReadyDetails?.CSwitchCountDeepSleep : (double?)null, + match?.ReadyDetails?.HasNonDeepSleepTimes == true ? match?.ReadyDetails?.CSwitchCountNonDeepSleep : (double?)null, + match.ContextSwitchCount + ); } /// @@ -1209,6 +1358,8 @@ private void ProcessTotalMatches(List matches) } } + + private void PrintProcessTotalMatches(List matches) { foreach (var group in matches.GroupBy(x => x.Process.GetProcessName(this.UsePrettyProcessName)).OrderBy(x => x.Sum(SortBySortOrder))) @@ -1219,14 +1370,14 @@ private void PrintProcessTotalMatches(List matches) long diff = group.ETWMaxBy(x => x.PerformedAt).CPUMs - cpu; - PrintCPUTotal(cpu, subgroup.First().Process, String.Join(" ", subgroup.Select(x => Path.GetFileNameWithoutExtension(x.SourceFile)).ToHashSet()) + $" Diff: {diff:N0} ms ", subgroup.First().SessionStart, subgroup.FirstOrDefault().Module); + PrintCPUTotal(cpu, subgroup.First().ProcessPriority, subgroup.First().Process, String.Join(" ", subgroup.Select(x => Path.GetFileNameWithoutExtension(x.SourceFile)).ToHashSet()) + $" Diff: {diff:N0} ms ", subgroup.First().SessionStart, subgroup.FirstOrDefault().Module); } } } private void WriteCSVProcessTotal(List matches) { - OpenCSVWithHeader(Col_CSVOptions, Col_TestCase, Col_Date, Col_TestTimeinms, "CPU ms", Col_Baseline, Col_Process, Col_ProcessName, + OpenCSVWithHeader(Col_CSVOptions, Col_TestCase, Col_Date, Col_TestTimeinms, "CPU ms", Col_AveragePriority, Col_Baseline, Col_Process, "ParentPid", Col_ProcessName, Col_StartTime, Col_CommandLine, Col_SourceJsonFile, "SourceDirectory", "IsNewProcess", Col_FileVersion, Col_VersionString, Col_ProductVersion, Col_ProductName, Col_Description, Col_Directory); @@ -1238,7 +1389,8 @@ private void WriteCSVProcessTotal(List matches) string productName = match.Module?.ProductName?.Trim() ?? ""; string description = match.Module?.Description?.Trim() ?? ""; string directory = match.Module?.ModulePath ?? ""; - WriteCSVLine(CSVOptions, match.TestName, match.PerformedAt, match.DurationInMs, match.CPUMs, match.BaseLine, match.ProcessAndPid, match.Process.GetProcessName(UsePrettyProcessName), match.Process.StartTime, match.Process.CmdLine, + + WriteCSVLine(CSVOptions, match.TestName, match.PerformedAt, match.DurationInMs, match.CPUMs, GetNullIfZero(match.ProcessPriority), match.BaseLine, match.ProcessAndPid, match.Process.ParentPid, match.Process.GetProcessName(UsePrettyProcessName), match.Process.StartTime, match.Process.CmdLine, Path.GetFileNameWithoutExtension(match.SourceFile), Path.GetDirectoryName(match.SourceFile), (match.Process.IsNew ? 1 : 0), fileVersion, versionString, productVersion, productName, description, directory); } @@ -1272,6 +1424,7 @@ void SortByValueStatePreparer(IEnumerable data) SortOrders.StartTime, SortOrders.CSwitchCount, SortOrders.ReadyAvg, + SortOrders.Priority, }; /// @@ -1297,6 +1450,7 @@ internal double SortBySortOrder(MatchData data) SortOrders.Last => IsProcessTotalMode ? (data.Process.EndTime == DateTimeOffset.MaxValue ? 0 : data.Process.EndTime.Ticks) : data.LastCallTime.Ticks, // in CPU total mode we can sort by process end time with -SortBy Last SortOrders.ReadyAvg => data.ReadyAverageUs, SortOrders.CSwitchCount => data.ContextSwitchCount, + SortOrders.Priority => data.ProcessPriority, _ => data.CPUMs, // by default sort by CPU }; } diff --git a/ETWAnalyzer/EventDump/DumpFileDirBase.cs b/ETWAnalyzer/EventDump/DumpFileDirBase.cs index 57fd4c01..df3a398f 100644 --- a/ETWAnalyzer/EventDump/DumpFileDirBase.cs +++ b/ETWAnalyzer/EventDump/DumpFileDirBase.cs @@ -155,6 +155,10 @@ protected void OpenCSVWithHeader(params string[] csvColumns) } } + protected object GetNullIfZero(V value) + { + return value.Equals(default(V)) ? null : value; + } protected void WriteCSVLine(params object[] columnArgs) { diff --git a/ETWAnalyzer/EventDump/DumpPower.cs b/ETWAnalyzer/EventDump/DumpPower.cs index 6f3bdf37..2df4a56a 100644 --- a/ETWAnalyzer/EventDump/DumpPower.cs +++ b/ETWAnalyzer/EventDump/DumpPower.cs @@ -5,10 +5,10 @@ using ETWAnalyzer.Extract.Power; using ETWAnalyzer.Infrastructure; using ETWAnalyzer.ProcessTools; +using Microsoft.Windows.EventTracing.Processes; using System; using System.Collections.Generic; using System.Linq; -using System.Transactions; namespace ETWAnalyzer.EventDump { @@ -101,14 +101,35 @@ private List ReadFileData() if (lret[i].PowerConfiguration.Equals(lret[k].PowerConfiguration)) { skipped.Add(lret[i].PowerConfiguration); - skipped.Add(lret[k].PowerConfiguration); } } } - Console.WriteLine($"Skipped {skipped.Count} entries with identical power configurations."); - lret = lret.TakeWhile(x => !skipped.Contains(x.PowerConfiguration)).ToList(); - Console.WriteLine($"Remaining {lret.Count} entries."); + // Keep of each skip group one file. Otherwise we would print of a large list of files with duplicates 0 entries. + List alreadySkipped = new(); + int origCount = lret.Count; + + lret = lret.Where(x => + { + if (skipped.Contains(x.PowerConfiguration)) + { + if (alreadySkipped.Contains(x.PowerConfiguration)) + { + ColorConsole.WriteLine($"Skipped {x.SourceFile}"); + return false; + } + else + { + alreadySkipped.Add(x.PowerConfiguration); + return true; + } + } + else + { + return true; + } + }).ToList(); + Console.WriteLine($"Remaining {lret.Count}/{origCount} entries."); } return lret; @@ -122,7 +143,7 @@ private void PrintMatches(List matches) ColorConsole.WriteEmbeddedColorLine($"{"File Date ",ColumnWidth}: ", null, true); - foreach(var match in matches) + foreach (var match in matches) { ColorConsole.WriteEmbeddedColorLine($"{match.PerformedAt,ColumnWidth}", FileConsoleColor, true); } @@ -130,19 +151,17 @@ private void PrintMatches(List matches) Console.WriteLine(); ColorConsole.WriteEmbeddedColorLine($"{"File Name ",ColumnWidth}: ", null, true); - foreach (var match in matches) - { - ColorConsole.WriteEmbeddedColorLine($"{GetPrintFileName(match.SourceFile),ColumnWidth}", FileConsoleColor, true); - } - Console.WriteLine(); + + PrintFileNameMultiLineIndented(matches, ColumnWidth); + ColorConsole.WriteEmbeddedColorLine("[green]CPU Power Configuration[/green]"); - foreach (Formatter formatter in formatters.Where( x => ShowOnlyDiffValuesWhenEnabled(matches,x)) ) + foreach (Formatter formatter in formatters.Where(x => ShowOnlyDiffValuesWhenEnabled(matches, x))) { PrintDetails(formatter); ColorConsole.WriteEmbeddedColorLine($"{formatter.Header,ColumnWidth}: ", null, true); - + foreach (MatchData data in matches) { ColorConsole.WriteEmbeddedColorLine($"{formatter.PrintNoDup(data.PowerConfiguration),-40}", null, true); @@ -154,12 +173,12 @@ private void PrintMatches(List matches) List> idleFormatters = GetIdleFormatters(); ColorConsole.WriteEmbeddedColorLine("[green]Idle Configuration[/green]"); - foreach(Formatter idleformatter in idleFormatters.Where(x => ShowOnlyDiffValuesWhenEnabled(matches, x))) + foreach (Formatter idleformatter in idleFormatters.Where(x => ShowOnlyDiffValuesWhenEnabled(matches, x))) { PrintDetails(idleformatter); ColorConsole.WriteEmbeddedColorLine($"{idleformatter.Header,ColumnWidth}: ", null, true); - + foreach (MatchData data in matches) { ColorConsole.WriteEmbeddedColorLine($"{idleformatter.PrintNoDup(data.PowerConfiguration),ColumnWidth}", null, true); @@ -184,6 +203,65 @@ private void PrintMatches(List matches) } } + + /// + /// Print a list of file names column wise to console with a given width. + /// + /// List of matches + /// + private void PrintFileNameMultiLineIndented(List matches, int columnWidth) + { + List fileNames = new(); + foreach (var match in matches) + { + fileNames.Add(match.SourceFile); + } + + if( fileNames.Count == 1) + { + columnWidth = -1000; + } + + int iteration = 0; + int filenameWidth = Math.Abs(columnWidth) - 3; + + while (true) + { + bool hasData = false; + List parts = new List(); + foreach (var file in fileNames) + { + var str = new string(file.Skip(iteration * filenameWidth).Take(filenameWidth).ToArray()); + if (!hasData) + { + hasData = str.Length > 0; + } + parts.Add(str); + } + + if( !parts.All(String.IsNullOrEmpty) ) + { + if (iteration > 0) // print first column again but empty + { + ColorConsole.Write(" ".WithWidth(Math.Abs(columnWidth) + 2)); + } + + foreach (var part in parts) + { + ColorConsole.WriteEmbeddedColorLine(part.WithWidth(columnWidth), FileConsoleColor, true); + } + Console.WriteLine(); + } + + if (!hasData) + { + break; + } + + iteration++; + } + } + /// /// Check if all values are equal /// @@ -435,6 +513,61 @@ private List> GetProcessorFormatters() { List> formatters = []; + var activeProfile = new Formatter() + { + Header = "ActiveProfile", + Description = "Curently active Power Profile", + Help = "", + Print = (power) => power.ActivePowerProfile == BasePowerProfile.Custom ? $"{power.ActivePowerProfile}: {power.ActivePowerProfileGuid}" : power.ActivePowerProfile.ToString(), + }; + formatters.Add(activeProfile); + + var baseProfile = new Formatter() + { + Header = "Base Profile", + Description = "Used base profile from which not set settings are inherited.", + Help = "", + Print = (power) => power.BaseProfile.ToString(), + }; + formatters.Add(baseProfile); + + var autonomous = new Formatter() + { + Header = "Autonomous Mode", + Description = "Processor performance autonomous mode", + Help = " Specify whether processors should autonomously determine their target performance state."+Environment.NewLine+"Subgroup:"+Environment.NewLine+" Processor power management"+Environment.NewLine+"Possible values (index - hexadecimal or string value - friendly name - descr):"+Environment.NewLine+" 0 - 00000000 - Disabled - Determine target performance state using operating system algorithms."+Environment.NewLine+" 1 - 00000001 - Enabled - Determine target performance state using autonomous selection."+Environment.NewLine+"Subgroup / Setting GUIDs:"+Environment.NewLine+" 54533251-82be-4824-96c1-47b60b740d00 / 8baa4a8a-14c6-4451-8e8b-14bdbd197537", + Print = (power) => power.AutonomousMode.ToString(), + }; + formatters.Add(autonomous); + + var heteroPolicyInEffect = new Formatter() + { + Header = "HeteroPolicyInEffect", + Description = "Heterogeneous policy in effect", + Help = "Specify what policy to be used on systems with at least two different Processor Power Efficiency Classes."+Environment.NewLine+"Subgroup:"+Environment.NewLine+" Processor power management"+Environment.NewLine+"Possible values (index - hexadecimal or string value - friendly name - descr):"+Environment.NewLine+" 0 - 00000000 - Use heterogeneous policy 0 - Heterogeneous policy 0."+Environment.NewLine+" 1 - 00000001 - Use heterogeneous policy 1 - Heterogeneous policy 1."+Environment.NewLine+" 2 - 00000002 - Use heterogeneous policy 2 - Heterogeneous policy 2."+Environment.NewLine+" 3 - 00000003 - Use heterogeneous policy 3 - Heterogeneous policy 3."+Environment.NewLine+" 4 - 00000004 - Use heterogeneous policy 4 - Heterogeneous policy 4."+Environment.NewLine+"Subgroup / Setting GUIDs:"+Environment.NewLine+" 54533251-82be-4824-96c1-47b60b740d00 / 7f2f5cfa-f10c-4823-b5e1-e93ae85f46b5", + Print = (power) => power.HeteroPolicyInEffect.ToString(), + }; + formatters.Add(heteroPolicyInEffect); + + var heteroThreadSchedulingPolicy = new Formatter() + { + Header = "HeteroPolicyThreadScheduling", + Description = "Heterogeneous thread scheduling policy", + Help = "Specify what thread scheduling policy to use on heterogeneous systems."+Environment.NewLine+"Subgroup:"+Environment.NewLine+" Processor power management"+Environment.NewLine+"Possible values (index - hexadecimal or string value - friendly name - descr):"+Environment.NewLine+" 0 - 00000000 - All processors - Schedule to any available processor."+Environment.NewLine+" 1 - 00000001 - Performant processors - Schedule exclusively to more performant processors."+Environment.NewLine+" 2 - 00000002 - Prefer performant processors - Schedule to more performant processors when possible."+Environment.NewLine+" 3 - 00000003 - Efficient processors - Schedule exclusively to more efficient processors."+Environment.NewLine+" 4 - 00000004 - Prefer efficient processors - Schedule to more efficient processors when possible."+Environment.NewLine+" 5 - 00000005 - Automatic - Let the system choose an appropriate policy."+Environment.NewLine+"Subgroup / Setting GUIDs:"+Environment.NewLine+" 54533251-82be-4824-96c1-47b60b740d00 / 93b8b6dc-0698-4d1c-9ee4-0644e900c85d", + Print = (power) => power.HeteroPolicyThreadScheduling.ToString(), + }; + formatters.Add(heteroThreadSchedulingPolicy); + + var heteroThreadSchedulingPolicyShort = new Formatter() + { + Header = "HeteroPolicyThreadSchedulingShort", + Description = "Heterogeneous short running thread scheduling policy", + Help = "Specify what thread scheduling policy to use for short running threads on heterogeneous systems."+Environment.NewLine+"Subgroup:"+Environment.NewLine+" Processor power management"+Environment.NewLine+"Possible values (index - hexadecimal or string value - friendly name - descr):"+Environment.NewLine+" 0 - 00000000 - All processors - Schedule to any available processor."+Environment.NewLine+" 1 - 00000001 - Performant processors - Schedule exclusively to more performant processors."+Environment.NewLine+" 2 - 00000002 - Prefer performant processors - Schedule to more performant processors when possible."+Environment.NewLine+" 3 - 00000003 - Efficient processors - Schedule exclusively to more efficient processors."+Environment.NewLine+" 4 - 00000004 - Prefer efficient processors - Schedule to more efficient processors when possible."+Environment.NewLine+" 5 - 00000005 - Automatic - Let the system choose an appropriate policy."+Environment.NewLine+"Subgroup / Setting GUIDs:"+Environment.NewLine+" 54533251-82be-4824-96c1-47b60b740d00 / bae08b81-2d5e-4688-ad6a-13243356654b", + Print = (power) => power.HeteroPolicyThreadSchedulingShort.ToString(), + }; + formatters.Add(heteroThreadSchedulingPolicyShort); + + var boostMode = new Formatter { Header = "BoostMode", @@ -599,6 +732,13 @@ internal void WriteToCSV(List matches) { OpenCSVWithHeader(Col_CSVOptions, Col_TestCase, Col_TestTimeinms, Col_SourceJsonFile, Col_Machine, "Profile Recorded At (s)", + "Active Profile", + "Active Profile Guid", + "Base Profile", + "Autonomous Mode", + "Hetero Policy In Effect", + "Hetero Policy Thread Scheduling", + "Hetero Policy Thread Scheduling Short", "BoostMode","Boost Policy %", "DecreasePolicy", "DecreaseStabilizationInterval", "DecreaseThreshold %", "IncreasePolicy", "IncreaseStabilizationInterval", "IncreaseThreshold %", "LatencySensitivityPerformance %", "MaxEfficiencyClass0Frequency", @@ -623,6 +763,13 @@ internal void WriteToCSV(List matches) WriteCSVLine(CSVOptions, match.TestName, match.TestDurationInMs, match.SourceFile, match.Machine, power.TimeSinceTraceStartS, + power.ActivePowerProfile, + power.ActivePowerProfileGuid, + power.BaseProfile, + power.AutonomousMode, + power.HeteroPolicyInEffect, + power.HeteroPolicyThreadScheduling, + power.HeteroPolicyThreadSchedulingShort, power.BoostMode, power.BoostPolicyPercent, power.DecreasePolicy, power.DecreaseStabilizationInterval, power.DecreaseThresholdPercent, power.IncreasePolicy, power.IncreaseStabilizationInterval, power.IncreaseThresholdPercent, power.LatencySensitivityPerformancePercent, power.MaxEfficiencyClass0Frequency, diff --git a/ETWAnalyzer/EventDump/DumpStats.cs b/ETWAnalyzer/EventDump/DumpStats.cs index 4899eac6..ee941abb 100644 --- a/ETWAnalyzer/EventDump/DumpStats.cs +++ b/ETWAnalyzer/EventDump/DumpStats.cs @@ -3,6 +3,7 @@ using ETWAnalyzer.EventDump; using ETWAnalyzer.Extract; +using ETWAnalyzer.Extract.CPU.Extended; using ETWAnalyzer.Extract.Disk; using ETWAnalyzer.Infrastructure; using ETWAnalyzer.ProcessTools; @@ -102,8 +103,8 @@ class DumpStats : DumpFileDirBase { "OSBuild", m => m.OSBuild }, { "OSVersion", m => m.OSVersion }, { "MemorySizeMB", m => m.MemorySizeMB }, - { "NumberOfProcessors", m => m.NumberOfProcessors }, - { "CPUSpeedMHz", m => m.CPUSpeedMHz }, + { "NumberOfProcessors", FormatNumberOfProcessors }, + { "CPUSpeedMHz", FormatSpeedMHz }, { "CPUVendor", m => m.CPUVendor }, { "CPUName", m => m.CPUName }, { "Disk", m => FormatDisks(m.Disks) }, @@ -121,6 +122,54 @@ class DumpStats : DumpFileDirBase }; + /// + /// Print when existing number of P and E Cores separately. + /// + /// + /// + static string FormatNumberOfProcessors(Match data) + { + string lret = data.NumberOfProcessors.ToString(); + if( data?.Topology?.Count > 0) + { + var lookup = data.Topology.Values.ToLookup(x => x.EfficiencyClass); + if (lookup.Count > 1) // we have P and E Cores at all + { + foreach (var group in lookup.OrderBy(x => x.First().EfficiencyClass)) + { + lret += $" Efficiency Class {group.Key}: {group.Count(),5} "; + } + } + } + return lret.TrimEnd(); + } + + /// + /// Print for P and E-Cores nominal CPU Frequency + /// + /// + /// + static string FormatSpeedMHz(Match data) + { + string lret = data.CPUSpeedMHz.ToString(); + if (data?.Topology?.Count > 0) + { + var lookup = data.Topology.Values.ToLookup(x => x.EfficiencyClass); + + if (lookup.Count > 1) // just print when we have P and E Cores + { + lret = "".WithWidth(3); + + foreach (var group in lookup.OrderBy(x => x.First().EfficiencyClass)) + { + lret += $"Efficiency Class {group.Key}: {group.First().NominalFrequencyMHz,5} MHz "; + } + } + } + + return lret.TrimEnd(); ; + } + private static string FormatDisks(IReadOnlyList disks) { if( disks == null ) @@ -174,6 +223,7 @@ class Match public string CPUName { get; internal set; } public bool? CPUHyperThreadingEnabled { get; internal set; } public string BaseLine { get; internal set; } + public IReadOnlyDictionary Topology { get; internal set; } } @@ -226,6 +276,9 @@ public override List ExecuteInternal() continue; } + var cpuToplogy = file.Extract?.CPU?.Topology; + + Match m = new() { TestCase = file.TestName, @@ -240,6 +293,7 @@ public override List ExecuteInternal() OSBuild = file.Extract.OSBuild, OSVersion = file.Extract.OSVersion.ToString(), MemorySizeMB = file.Extract.MemorySizeMB, + Topology = cpuToplogy, NumberOfProcessors = file.Extract.NumberOfProcessors, CPUSpeedMHz = file.Extract.CPUSpeedMHz, CPUName = file.Extract.CPUName, diff --git a/ETWAnalyzer/Extract/CPU/CPUStats.cs b/ETWAnalyzer/Extract/CPU/CPUStats.cs index da6bdc78..909d9c01 100644 --- a/ETWAnalyzer/Extract/CPU/CPUStats.cs +++ b/ETWAnalyzer/Extract/CPU/CPUStats.cs @@ -4,9 +4,11 @@ using ETWAnalyzer.Extract.CPU; using ETWAnalyzer.Extract.CPU.Extended; using ETWAnalyzer.Extractors; +using Newtonsoft.Json; using System; using System.Collections.Generic; using System.IO; +using System.Linq; namespace ETWAnalyzer.Extract { @@ -21,13 +23,22 @@ public class CPUStats : ICPUStats public Dictionary PerProcessCPUConsumptionInMs { get; - } = new Dictionary(); + } = new(); /// /// Simple stat which contains the total CPU in ms per process /// IReadOnlyDictionary ICPUStats.PerProcessCPUConsumptionInMs => PerProcessCPUConsumptionInMs; + /// + /// Average process priority of all threads taken from CPU sampling data if present. + /// + public Dictionary PerProcessAvgCPUPriority + { + get; + } = new(); + + IReadOnlyDictionary ICPUStats.PerProcessAvgCPUPriority => PerProcessAvgCPUPriority; /// /// Contains methods which have CPU/Wait > 10ms (default) @@ -60,6 +71,14 @@ public CPUPerProcessMethodList PerProcessMethodCostsInclusive /// public Dictionary Topology { get; set; } = new(); + /// + /// Returns true if CPU data is set and CPU has E-Cores + /// + [JsonIgnore] + public bool HasECores + { + get => Topology != null && Topology.Count > 0 && Topology.Values.Any(x => x.EfficiencyClass > 0); + } IReadOnlyDictionary myReadOnly; @@ -107,17 +126,20 @@ public CPUTimeLine TimeLine internal string DeserializedFileName { get; set; } + /// /// Ctor which fills the data. This is also used by Json.NET during deserialization. /// /// + /// /// /// /// CPU informations /// Extended metrics - public CPUStats(Dictionary perProcessCPUConsumptionInMs, CPUPerProcessMethodList perProcessMethodCostsInclusive, CPUTimeLine timeLine, Dictionary cpuInfos, CPUExtended extendedMetrics) + public CPUStats(Dictionary perProcessCPUConsumptionInMs, Dictionary perProcessAvgCPUPriority, CPUPerProcessMethodList perProcessMethodCostsInclusive, CPUTimeLine timeLine, Dictionary cpuInfos, CPUExtended extendedMetrics) { PerProcessCPUConsumptionInMs = perProcessCPUConsumptionInMs; + PerProcessAvgCPUPriority = perProcessAvgCPUPriority; PerProcessMethodCostsInclusive = perProcessMethodCostsInclusive; TimeLine = timeLine; Topology = cpuInfos; diff --git a/ETWAnalyzer/Extract/CPU/Extended/CPUExtended.cs b/ETWAnalyzer/Extract/CPU/Extended/CPUExtended.cs index 149a6bf3..ffe51ce7 100644 --- a/ETWAnalyzer/Extract/CPU/Extended/CPUExtended.cs +++ b/ETWAnalyzer/Extract/CPU/Extended/CPUExtended.cs @@ -45,6 +45,12 @@ public IReadOnlyDictionary MethodIndexToCPUMet } } + /// + /// When true CPU frequency data was collected. + /// + [JsonIgnore] + public bool HasFrequencyData { get => CPUToFrequencyDurations.Count > 0; } + /// /// Get for a given core the sampled CPU Frequency at a given time which is present in ETL when Microsoft-Windows-Kernel-Processor-Power provider is enabled. /// @@ -334,6 +340,11 @@ public interface ICPUExtended /// Time in WPA trace Time in seconds since Session start for which you want to get the current time. /// Average CPU Frequency in MHz which was sampled in 15-30ms time slices. int GetFrequency(CPUNumber nCore, float timeS); + + /// + /// When true CPU frequency data was collected. + /// + public bool HasFrequencyData { get; } } diff --git a/ETWAnalyzer/Extract/CPU/Extended/FrequencySource.cs b/ETWAnalyzer/Extract/CPU/Extended/FrequencySource.cs index bfe85857..0286cd91 100644 --- a/ETWAnalyzer/Extract/CPU/Extended/FrequencySource.cs +++ b/ETWAnalyzer/Extract/CPU/Extended/FrequencySource.cs @@ -32,7 +32,7 @@ public class FrequencySource List myDurations; /// - /// Round flaot to 4 decimal places which is by far enough precision since the CPU frequency is sampled only every 15-30ms. + /// Round float to 4 decimal places which is by far enough precision since the CPU frequency is sampled only every 15-30ms. /// /// number to round. /// rounded number to 4 decimal places. diff --git a/ETWAnalyzer/Extract/CPU/Extended/IReadyTimes.cs b/ETWAnalyzer/Extract/CPU/Extended/IReadyTimes.cs deleted file mode 100644 index 559d3c06..00000000 --- a/ETWAnalyzer/Extract/CPU/Extended/IReadyTimes.cs +++ /dev/null @@ -1,142 +0,0 @@ -//// SPDX-FileCopyrightText: © 2023 Siemens Healthcare GmbH -//// SPDX-License-Identifier: MIT - -using Newtonsoft.Json; -using System.Collections.Generic; - -namespace ETWAnalyzer.Extract.CPU.Extended -{ - /// - /// Ready details - /// - public interface IReadyTimes - { - /// - /// Minimum Ready time in microseconds. - /// - float MinUs { get; } - - /// - /// Maximum Ready time in microseconds. - /// - float MaxUs { get; } - - /// - /// 5% Percentile Ready time in microseconds. - /// - float Percentile5 { get; } - - /// - /// 25% Percentile Ready time in microseconds. - /// - float Percentile25 { get; } - - /// - /// Median = 50% Percentile Ready time in microseconds. - /// - float Percentile50 { get; } - - /// - /// 90% Percentile Ready time in microseconds. - /// - float Percentile90 { get; } - - /// - /// 95% Percentile Ready time in microseconds. - /// - float Percentile95 { get; } - - /// - /// 99% Percentile Ready time in microseconds. - /// - float Percentile99 { get; } - - } - - - - /// - /// Ready time percentiles. - /// This class is serialized to Json file - /// - public class ReadyTimes : IReadyTimes - { - /// - /// Contains when filled Ready Min,Max,Percentiles 5,25,50,90,95,99 - /// - public List ReadyTimesUs { get; set; } = []; - - /// - /// Add Ready time details for a given method. - /// - /// Minimum Ready time in s - /// Maximum Ready time in s - /// 5% Percentile Ready Time in s - /// 25% Percentile Ready Time in s - /// 50% Percentile Ready Time in s - /// 90% Percentile Ready Time in s - /// 95% Percentile Ready Time in s - /// 99% Percentile Ready Time in s - public void AddReadyTimes(float minS, float maxS, float percentile5, float percentile25, float percentile50, float percentile90, float percentile95, float percentile99) - { - ReadyTimesUs.Add(minS); - ReadyTimesUs.Add(maxS); - ReadyTimesUs.Add(percentile5); - ReadyTimesUs.Add(percentile25); - ReadyTimesUs.Add(percentile50); - ReadyTimesUs.Add(percentile90); - ReadyTimesUs.Add(percentile95); - ReadyTimesUs.Add(percentile99); - } - - const float Million = 1000000.0f; - - /// - /// Minimum Ready time in microseconds. - /// - [JsonIgnore] - public float MinUs { get => ReadyTimesUs[0] * Million; } - - /// - /// Maximum Ready time in microseconds. - /// - [JsonIgnore] - public float MaxUs { get => ReadyTimesUs[1] * Million; } - - /// - /// 5% Percentile Ready time in microseconds. - /// - [JsonIgnore] - public float Percentile5 { get => ReadyTimesUs[2] * Million; } - - /// - /// 25% Percentile Ready time in microseconds. - /// - [JsonIgnore] - public float Percentile25 { get => ReadyTimesUs[3] * Million; } - - /// - /// Median = 50% Percentile Ready time in microseconds. - /// - [JsonIgnore] - public float Percentile50 { get => ReadyTimesUs[4] * Million; } - - /// - /// 90% Percentile Ready time in microseconds. - /// - [JsonIgnore] - public float Percentile90 { get => ReadyTimesUs[5] * Million; } - - /// - /// 95% Percentile Ready time in microseconds. - /// - [JsonIgnore] - public float Percentile95 { get => ReadyTimesUs[6] * Million; } - - /// - /// 99% Percentile Ready time in microseconds. - /// - [JsonIgnore] - public float Percentile99 { get => ReadyTimesUs[7] * Million; } - } -} diff --git a/ETWAnalyzer/Extract/CPU/Extended/ReadyTimes.cs b/ETWAnalyzer/Extract/CPU/Extended/ReadyTimes.cs new file mode 100644 index 00000000..781aebe3 --- /dev/null +++ b/ETWAnalyzer/Extract/CPU/Extended/ReadyTimes.cs @@ -0,0 +1,400 @@ +//// SPDX-FileCopyrightText: © 2023 Siemens Healthcare GmbH +//// SPDX-License-Identifier: MIT + +using Newtonsoft.Json; +using System.Collections.Generic; + +namespace ETWAnalyzer.Extract.CPU.Extended +{ + /// + /// Ready details which contains percentiles for CPU deep sleep states, Ready percentiles for process interference along with count and sum for total delay summed accross all threads inside one process for a given method in method inclusive ready time. + /// + public interface IReadyTimes + { + /// + /// true when DeepSleep ready times are present. + /// + bool HasDeepSleepTimes { get; } + + /// + /// true when non DeepSleep ready times are present + /// + bool HasNonDeepSleepTimes { get; } + + /// + /// Number of context switch events. + /// Context Switch events did originate from idle or own process in Windows C-State 1 which allows to measure CPU unpark time without other process interference. + /// + int CSwitchCountDeepSleep { get; } + + /// + /// Number of context switch events which did not originate from an DeepSleep thread. + /// + int CSwitchCountNonDeepSleep { get; } + + /// + /// Minimum Ready time in microseconds. + /// + double MinNonDeepSleepUs { get; } + + /// + /// Minimum Ready time in microseconds. + /// Context Switch events did originate from idle or own process in Windows C-State 1 which allows to measure CPU unpark time without other process interference. + /// + double MinDeepSleepUs { get; } + + + /// + /// Maximum Ready time in microseconds. + /// + double MaxNonDeepSleepUs { get; } + + /// + /// Maximum Ready time in microseconds. + /// Context Switch events did originate from idle or own process in Windows C-State 1 which allows to measure CPU unpark time without other process interference. + /// + double MaxDeepSleepUs { get; } + + + /// + /// 5% Percentile Ready time in microseconds. + /// + double Percentile5NonDeepSleepUs { get; } + + /// + /// 5% Percentile Ready time in microseconds. + /// Context Switch events did originate from idle or own process in Windows C-State 1 which allows to measure CPU unpark time without other process interference. + /// + double Percentile5DeepSleepUs { get; } + + + /// + /// 25% Percentile Ready time in microseconds. + /// Context Switch events did originate from idle or own process in Windows C-State 1 which allows to measure CPU unpark time without other process interference. + /// + double Percentile25DeepSleepUs { get; } + + /// + /// 25% Percentile Ready time in microseconds. + /// + double Percentile25NonDeepSleepUs { get; } + + + /// + /// Median = 50% Percentile Ready time in microseconds. + /// Context Switch events did originate from idle or own process in Windows C-State 1 which allows to measure CPU unpark time without other process interference. + /// + double Percentile50DeepSleepUs { get; } + + + /// + /// Median = 50% Percentile Ready time in microseconds. + /// + double Percentile50NonDeepSleepUs { get; } + + /// + /// 90% Percentile Ready time in microseconds. + /// + double Percentile90NonDeepSleepUs { get; } + + /// + /// 90% Percentile Ready time in microseconds. + /// Context Switch events did originate from idle or own process in Windows C-State 1 which allows to measure CPU unpark time without other process interference. + /// + double Percentile90DeepSleepUs { get; } + + + /// + /// 95% Percentile Ready time in microseconds. + /// + double Percentile95NonDeepSleepUs { get; } + + /// + /// 95% Percentile Ready time in microseconds. + /// Context Switch events did originate from idle or own process in Windows C-State 1 which allows to measure CPU unpark time without other process interference. + /// + double Percentile95DeepSleepUs { get; } + + + /// + /// 99% Percentile Ready time in microseconds. + /// + double Percentile99NonDeepSleepUs { get; } + + /// + /// 99% Percentile Ready time in microseconds. + /// Context Switch events did originate from idle or own process in Windows C-State 1 which allows to measure CPU unpark time without other process interference. + /// + double Percentile99DeepSleepUs { get; } + + /// + /// Sum of DeepSleep Ready time in microseconds. + /// Context Switch events did originate from idle or own process in Windows C-State 1 which allows to measure CPU unpark time without other process interference. + /// + public double SumDeepSleepUs { get; } + + /// + /// Sum of Non DeepSleep Ready time in microseconds. + /// This sums the Ready time from other processes which interfere. Additionally all other events which are not summed by are part of this metric. + /// + public double SumNonDeepSleepUs { get; } + + /// + /// Sum of Non DeepSleep Ready time of all events which are abover the 99% percentile in microseconds. + /// That value is useful to check if most of our waits are originating from rare but very slow peak ready times. + /// + public double SumGreater99PercentNonDeepSleepUs { get; } + + /// + /// Sum of DeepSleep Ready time of all events which are abover the 99% percentile in microseconds. + /// That value is useful to check if most of our waits are originating from rare but very slow peak ready times. + /// + public double SumGreater99PercentDeepSleepUs { get; } + } + + + + /// + /// Ready time percentiles. + /// This class is serialized to Json file + /// + public class ReadyTimes : IReadyTimes + { + /// + /// Contains when filled Version, Count, Ready Min,Max,Percentiles 5,25,50,90,95,99,Sum + /// + public List Other { get; set; } = []; + + /// + /// DeepSleep Ready times + /// + public List DeepSleep { get;set; } = []; + + /// + /// Ready Time version + /// + const double Version = 1.0d; + + const double Thousand = 1_000.0d; + + const int VersionV1Idx = 0; + const int CountV1Idx = 1; + const int MinV1Idx = 2; + const int MaxV1Idx = 3; + const int Percentile5V1Idx = 4; + const int Percentile25V1Idx = 5; + const int Percentile50V1Idx = 6; + const int Percentile90V1Idx = 7; + const int Percentile95V1Idx = 8; + const int Percentile99V1Idx = 9; + const int SumV1Idx = 10; + const int SumV1_99PercentIdx = 11; + + /// + /// true when DeepSleep ready times are present. + /// + [JsonIgnore] + public bool HasDeepSleepTimes { get => DeepSleep.Count > 0; } + + /// + /// true hwen non DeepSleep ready times are present + /// + [JsonIgnore] + public bool HasNonDeepSleepTimes { get => Other.Count > 0; } + + /// + /// Number of context switch events which did originate from an DeepSleep thread. + /// DeepSleep Ready thread events are useful to find how long a parked CPU did need to wake up from deep power states. + /// + [JsonIgnore] + public int CSwitchCountDeepSleep { get => (int)DeepSleep[CountV1Idx]; } + + /// + /// Number of context switch events which did not originate from an DeepSleep thread. + /// + [JsonIgnore] + public int CSwitchCountNonDeepSleep { get => (int)Other[CountV1Idx]; } + + /// + /// Minimum Ready time in microseconds. + /// + [JsonIgnore] + public double MinNonDeepSleepUs { get => Other[MinV1Idx]; } + + /// + /// Minimum Ready time in microseconds. + /// + [JsonIgnore] + public double MinDeepSleepUs { get => DeepSleep[MinV1Idx]; } + + /// + /// Maximum Ready time in microseconds. + /// + [JsonIgnore] + public double MaxNonDeepSleepUs { get => Other[MaxV1Idx]; } + + /// + /// Maximum Ready time in microseconds. + /// + [JsonIgnore] + public double MaxDeepSleepUs { get => DeepSleep[MaxV1Idx]; } + + + /// + /// 5% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile5NonDeepSleepUs { get => Other[Percentile5V1Idx]; } + + /// + /// 5% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile5DeepSleepUs { get => DeepSleep[Percentile5V1Idx]; } + + + /// + /// 25% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile25NonDeepSleepUs { get => Other[Percentile25V1Idx]; } + + /// + /// 25% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile25DeepSleepUs { get => DeepSleep[Percentile25V1Idx]; } + + + /// + /// Median = 50% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile50NonDeepSleepUs { get => Other[Percentile50V1Idx]; } + + /// + /// Median = 50% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile50DeepSleepUs { get => DeepSleep[Percentile50V1Idx]; } + + + /// + /// 90% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile90NonDeepSleepUs { get => Other[Percentile90V1Idx]; } + + /// + /// 90% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile90DeepSleepUs { get => DeepSleep[Percentile90V1Idx]; } + + + /// + /// 95% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile95NonDeepSleepUs { get => Other[Percentile95V1Idx]; } + + /// + /// 95% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile95DeepSleepUs { get => DeepSleep[Percentile95V1Idx]; } + + + /// + /// 99% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile99NonDeepSleepUs { get => Other[Percentile99V1Idx]; } + + /// + /// 99% Percentile Ready time in microseconds. + /// + [JsonIgnore] + public double Percentile99DeepSleepUs { get => DeepSleep[Percentile99V1Idx]; } + + + /// + /// Sum of DeepSleep Ready time in microseconds + /// + [JsonIgnore] + public double SumDeepSleepUs { get => DeepSleep[SumV1Idx]; } + + /// + /// Sum of DeepSleep Ready time of all events which are abover the 99% percentile in microseconds. + /// That value is useful to check if most of our waits are originating from rare but very slow peak ready times. + /// + [JsonIgnore] + public double SumGreater99PercentDeepSleepUs { get => DeepSleep[SumV1_99PercentIdx]; } + + /// + /// Sum of Non DeepSleep Ready time in microseconds + /// + [JsonIgnore] + public double SumNonDeepSleepUs { get => Other[SumV1Idx]; } + + /// + /// Sum of Non DeepSleep Ready time of all events which are abover the 99% percentile in microseconds. + /// That value is useful to check if most of our waits are originating from rare but very slow peak ready times. + /// + [JsonIgnore] + public double SumGreater99PercentNonDeepSleepUs { get => Other[SumV1_99PercentIdx]; } + + + + + /// + /// Add Ready time details for a given method. The data must be supplied in nanoseconds. Internally it will be stored in microsecond precision to get short strings in the serialized format. + /// + /// if true DeepSleep ready times are added to Other times + /// count of cswitch events + /// sum of all context switch events in nanoseconds + /// Minimum Ready time in nanoseconds + /// Maximum Ready time in nanoseconds + /// 5% Percentile Ready Time in nanoseconds + /// 25% Percentile Ready Time in nanoseconds + /// 50% Percentile Ready Time in nanoseconds + /// 90% Percentile Ready Time in nanoseconds + /// 95% Percentile Ready Time in nanoseconds + /// 99% Percentile Ready Time in nanoseconds + /// Sum of all ready events which are above the 99% percentile in nanoseconds. + public void AddReadyTimes(bool deepSleep, int count, long minNanoS, long maxNanoS, long percentile5NanoS, long percentile25NanoS, long percentile50NanoS, long percentile90NanoS, long percentile95NanoS, long percentile99NanoS, decimal sumNanoS, decimal sumAbove99PercentileNanoS) + { + if (deepSleep) + { + DeepSleep.Add(Version); + DeepSleep.Add(count); + DeepSleep.Add((double) minNanoS / Thousand); + DeepSleep.Add((double) maxNanoS / Thousand); + DeepSleep.Add((double) percentile5NanoS / Thousand); + DeepSleep.Add((double) percentile25NanoS / Thousand); + DeepSleep.Add((double) percentile50NanoS / Thousand); + DeepSleep.Add((double) percentile90NanoS / Thousand); + DeepSleep.Add((double) percentile95NanoS / Thousand); + DeepSleep.Add((double) percentile99NanoS / Thousand); + DeepSleep.Add((double) sumNanoS / Thousand); + DeepSleep.Add((double) sumAbove99PercentileNanoS / Thousand); + } + else + { + Other.Add(Version); + Other.Add(count); + Other.Add((double) minNanoS / Thousand); + Other.Add((double) maxNanoS / Thousand); + Other.Add((double) percentile5NanoS / Thousand); + Other.Add((double) percentile25NanoS /Thousand); + Other.Add((double) percentile50NanoS /Thousand); + Other.Add((double) percentile90NanoS /Thousand); + Other.Add((double) percentile95NanoS /Thousand); + Other.Add((double) percentile99NanoS / Thousand); + Other.Add((double) sumNanoS / Thousand); + Other.Add((double) sumAbove99PercentileNanoS / Thousand); + } + } + + } +} diff --git a/ETWAnalyzer/Extract/CPU/ICPUStats.cs b/ETWAnalyzer/Extract/CPU/ICPUStats.cs index 015f9871..5035890b 100644 --- a/ETWAnalyzer/Extract/CPU/ICPUStats.cs +++ b/ETWAnalyzer/Extract/CPU/ICPUStats.cs @@ -17,6 +17,11 @@ public interface ICPUStats /// IReadOnlyDictionary PerProcessCPUConsumptionInMs { get; } + /// + /// Average process priority taken from CPU sampling data when present + /// + IReadOnlyDictionary PerProcessAvgCPUPriority { get; } + /// /// Contains methods which have CPU/Wait > 10ms (default) /// diff --git a/ETWAnalyzer/Extract/ETWExtract.cs b/ETWAnalyzer/Extract/ETWExtract.cs index 85b04fe4..9b8e957c 100644 --- a/ETWAnalyzer/Extract/ETWExtract.cs +++ b/ETWAnalyzer/Extract/ETWExtract.cs @@ -502,7 +502,7 @@ public ETWProcessIndex GetProcessIndexByPidAtTime(int pid, DateTimeOffset timeWh for (int i = 0; i < Processes.Count; i++) { - if (Processes[i].ProcessID == pid && timeWhenProcessDidExist > Processes[i].StartTime && timeWhenProcessDidExist < Processes[i].EndTime) + if (Processes[i].ProcessID == pid && timeWhenProcessDidExist >= Processes[i].StartTime && timeWhenProcessDidExist <= Processes[i].EndTime) { lret = (ETWProcessIndex)i; } diff --git a/ETWAnalyzer/Extract/Power/BasePowerProfile.cs b/ETWAnalyzer/Extract/Power/BasePowerProfile.cs new file mode 100644 index 00000000..69eb6f12 --- /dev/null +++ b/ETWAnalyzer/Extract/Power/BasePowerProfile.cs @@ -0,0 +1,36 @@ +//// SPDX-FileCopyrightText: © 2024 Siemens Healthcare GmbH +//// SPDX-License-Identifier: MIT + +namespace ETWAnalyzer.Extract.Power +{ + /// + /// Well known base power profile names + /// + public enum BasePowerProfile + { + /// + /// Custom power profile + /// + Custom = 0, + + /// + /// + /// + PowerSaver, + + /// + /// + /// + Balanced, + + /// + /// + /// + HighPerformance, + + /// + /// + /// + UltimatePerformance, + } +} diff --git a/ETWAnalyzer/Extract/Power/HeteroThreadSchedulingPolicy.cs b/ETWAnalyzer/Extract/Power/HeteroThreadSchedulingPolicy.cs new file mode 100644 index 00000000..43069edd --- /dev/null +++ b/ETWAnalyzer/Extract/Power/HeteroThreadSchedulingPolicy.cs @@ -0,0 +1,42 @@ +//// SPDX-FileCopyrightText: © 2024 Siemens Healthcare GmbH +//// SPDX-License-Identifier: MIT + + +namespace ETWAnalyzer.Extract.Power +{ + /// + /// Defines how long/short running threads are scheduled on which core type + /// + public enum HeteroThreadSchedulingPolicy + { + /// + /// Schedule to any available processor. + /// + AllProcessors = 0, + + /// + /// Schedule exclusively to more performant processors. + /// + PerformantProcessors = 1, + + /// + /// Schedule to more performant processors when possible. + /// + PreferPerformantProcessors = 2, + + /// + /// Schedule exclusively to more efficient processors. + /// + EfficientProcessors = 3, + + /// + /// Schedule to more efficient processors when possible. + /// + PreferEfficientProcessors = 4, + + /// + /// Let the system choose an appropriate policy. + /// + Automatic = 5, + } +} diff --git a/ETWAnalyzer/Extract/Power/IPowerConfiguration.cs b/ETWAnalyzer/Extract/Power/IPowerConfiguration.cs index 3d7e8c53..29596608 100644 --- a/ETWAnalyzer/Extract/Power/IPowerConfiguration.cs +++ b/ETWAnalyzer/Extract/Power/IPowerConfiguration.cs @@ -9,7 +9,7 @@ namespace ETWAnalyzer.Extract.Power /// /// Windows Power Profile settings /// - public interface IPowerConfiguration : IEquatable + public interface IPowerConfiguration { /// /// Time stamp when this snapshot was taken. @@ -137,6 +137,42 @@ public interface IPowerConfiguration : IEquatable /// int TimeWindowSize { get; } + + /// + /// Power profiles inherit settings from their base profile + /// + public BasePowerProfile BaseProfile { get; } + + /// + /// Hetero Policy which is active. + /// + public int HeteroPolicyInEffect { get; } + + /// + /// Short running thread scheduling policy + /// + public HeteroThreadSchedulingPolicy HeteroPolicyThreadSchedulingShort { get; } + + /// + /// Long running thread scheduling policy + /// + public HeteroThreadSchedulingPolicy HeteroPolicyThreadScheduling { get; } + + /// + /// When true CPU manages frequency on its own. + /// + public bool AutonomousMode { get; } + + /// + /// Currently active Power profile + /// + public BasePowerProfile ActivePowerProfile { get; } + + /// + /// Active Power profile Guid + /// + public Guid ActivePowerProfileGuid { get; } + /// /// Idle Configuration parameters /// diff --git a/ETWAnalyzer/Extract/Power/PowerConfiguration.cs b/ETWAnalyzer/Extract/Power/PowerConfiguration.cs index 92bfd953..768aca6a 100644 --- a/ETWAnalyzer/Extract/Power/PowerConfiguration.cs +++ b/ETWAnalyzer/Extract/Power/PowerConfiguration.cs @@ -19,7 +19,7 @@ public enum FrequencyValueMHz /// /// Windows Power Profile settings /// - public class PowerConfiguration : IPowerConfiguration + public class PowerConfiguration : IPowerConfiguration, IEquatable { /// /// Time stamp when this snapshot was taken. @@ -51,6 +51,10 @@ public class PowerConfiguration : IPowerConfiguration /// public PercentValue BoostPolicyPercent { get; set; } + /// + /// Power profiles inherit settings from their base profile + /// + public BasePowerProfile BaseProfile { get; set; } /// /// Gets a value that indicates how aggressive the performance states should be changed @@ -160,24 +164,70 @@ public class PowerConfiguration : IPowerConfiguration /// public ProcessorParkingConfiguration ProcessorParkingConfiguration { get; set; } = new(); + /// + /// Hetero Policy which is active. + /// + public int HeteroPolicyInEffect { get; set; } + + /// + /// Short running thread scheduling policy + /// + public HeteroThreadSchedulingPolicy HeteroPolicyThreadSchedulingShort { get; set; } + + /// + /// Long running thread scheduling policy + /// + public HeteroThreadSchedulingPolicy HeteroPolicyThreadScheduling { get; set; } + + /// + /// When true CPU manages frequency on its own. + /// + public bool AutonomousMode { get; set; } + + /// + /// Currently active Power profile + /// + public BasePowerProfile ActivePowerProfile { get; set; } + + /// + /// Active Power profile Guid + /// + public Guid ActivePowerProfileGuid { get; set; } + + /// + /// + /// + /// + /// + public override bool Equals(object obj) + { + return Equals(obj as PowerConfiguration); + } + /// /// /// /// /// - public bool Equals(IPowerConfiguration other) + public bool Equals(PowerConfiguration other) { - if(ReferenceEquals(null, other)) + if (ReferenceEquals(null, other)) { return false; - } - - - return this.BoostMode == other.BoostMode && + } + + return + this.ActivePowerProfile == other.ActivePowerProfile && + this.AutonomousMode == other.AutonomousMode && + this.BaseProfile == other.BaseProfile && + this.BoostMode == other.BoostMode && this.BoostPolicyPercent == other.BoostPolicyPercent && this.DecreasePolicy == other.DecreasePolicy && this.DecreaseStabilizationInterval == other.DecreaseStabilizationInterval && this.DecreaseThresholdPercent == other.DecreaseThresholdPercent && + this.HeteroPolicyInEffect == other.HeteroPolicyInEffect && + this.HeteroPolicyThreadScheduling == other.HeteroPolicyThreadScheduling && + this.HeteroPolicyThreadSchedulingShort == other.HeteroPolicyThreadSchedulingShort && this.IncreasePolicy == other.IncreasePolicy && this.IncreaseStabilizationInterval == other.IncreaseStabilizationInterval && this.IncreaseThresholdPercent == other.IncreaseThresholdPercent && @@ -193,5 +243,15 @@ public bool Equals(IPowerConfiguration other) this.ProcessorParkingConfiguration.Equals(other.ProcessorParkingConfiguration) && this.IdleConfiguration.Equals(other.IdleConfiguration); } + + /// + /// Should not be used. + /// + /// + /// + public override int GetHashCode() + { + throw new NotImplementedException(); + } } } diff --git a/ETWAnalyzer/Extractors/CPU/CPUExtractor.cs b/ETWAnalyzer/Extractors/CPU/CPUExtractor.cs index c6f3fe4e..d0dc6098 100644 --- a/ETWAnalyzer/Extractors/CPU/CPUExtractor.cs +++ b/ETWAnalyzer/Extractors/CPU/CPUExtractor.cs @@ -52,6 +52,26 @@ class CPUExtractor : ExtractorBase /// public bool NoReady { get; internal set; } + /// + /// Ignore CPU sampling data. Used when CPU sampling data is corrupt + /// + public bool NoSampling { get; internal set; } + + /// + /// Ignore Context Switch data. Can conserve memory during extraction at the cost of missing thread wait/ready data. + /// + public bool NoCSwitch { get; internal set; } + + /// + /// True when it is not disabled and we have data + /// + bool CanUseCpuSamplingData { get => mySamplingData?.HasResult == true && !NoSampling; } + + /// + /// True when it is not disabld and we have CSwitch data + /// + bool CanUseCPUCSwitchData { get => myCpuSchedlingData?.HasResult == true && !NoCSwitch; } + /// /// Just a rough guess for initial dictionary size /// @@ -73,6 +93,7 @@ class CPUExtractor : ExtractorBase /// IPendingResult mySamplingData; + /// /// Context Switch data /// @@ -83,14 +104,27 @@ class CPUExtractor : ExtractorBase /// readonly ConcurrentDictionary myPerProcessCPU = new(); + /// + /// Per Process Priority + /// + readonly Dictionary> myPerProcessPriority = new(); + public CPUExtractor() { } public override void RegisterParsers(ITraceProcessor processor) { - mySamplingData = processor.UseCpuSamplingData(); - myCpuSchedlingData = processor.UseCpuSchedulingData(); + if (!NoSampling) + { + mySamplingData = processor.UseCpuSamplingData(); + } + + if (!NoCSwitch) + { + myCpuSchedlingData = processor.UseCpuSchedulingData(); + } + NeedsSymbols = true; } @@ -98,8 +132,7 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) { using var logger = new PerfLogger("Extract CPU"); - // access CSwitch data while we are processing CPU sampling data - Task.Run(() => { var _ = myCpuSchedlingData.Result?.ThreadActivity?.FirstOrDefault(); }); + WarmupCSwitchData(); if (TimelineDataExtractionIntervalS != null) { @@ -112,7 +145,8 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) } // inspired by https://github.com/microsoft/eventtracing-processing-samples/blob/master/GetCpuSampleDuration/Program.cs - ConcurrentDictionary> methodSamplesPerProcess = new(UsedConcurrency,1000); + ConcurrentDictionary> methodSamplesPerProcess = new(UsedConcurrency, 1000); + ConcurrentDictionary>> processKeyPrioritiesFromSwitch = new(UsedConcurrency, 1000); StackPrinter printer = new(StackFormat.DllAndMethod); ParallelOptions concurrency = new ParallelOptions @@ -121,8 +155,9 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) }; bool hasSamplesWithStacks = false; + Dictionary indexCache = BuildProcessIndexCache(results); - if (mySamplingData.HasResult) + if (CanUseCpuSamplingData) { Parallel.ForEach(mySamplingData.Result.Samples, concurrency, (ICpuSample sample) => { @@ -138,7 +173,7 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) var process = new ProcessKey(sample.Process.ImageName, sample.Process.Id, sample.Process.CreateTime.HasValue ? sample.Process.CreateTime.Value.DateTimeOffset : default(DateTimeOffset)); - AddTotalCPU(process, sample, myPerProcessCPU); + AddTotalCPUAndPriority(process, indexCache, sample, myPerProcessCPU, myPerProcessPriority); AddPerMethodAndProcessCPU(results, process, sample, methodSamplesPerProcess, printer); if (myTimelineExtractor != null) { @@ -148,10 +183,11 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) } // When we have context switch data recorded we can also calculate the thread wait time stacktags - if (myCpuSchedlingData.HasResult) + if( CanUseCPUCSwitchData ) { - Parallel.ForEach(myCpuSchedlingData.Result.ThreadActivity, concurrency, (ICpuThreadActivity slice) => + Parallel.ForEach(myCpuSchedlingData.Result.ThreadActivity, concurrency, (ICpuThreadActivity sliceV1) => { + ICpuThreadActivity2 slice = sliceV1.AsCpuThreadActivity2(); if (slice?.Process?.ImageName == null) { return; @@ -164,13 +200,14 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) var process = new ProcessKey(slice.Process.ImageName, slice.Process.Id, slice.Process.CreateTime.HasValue ? slice.Process.CreateTime.Value.DateTimeOffset : default(DateTimeOffset)); AddPerMethodAndProcessWaits(results, process, slice, methodSamplesPerProcess, printer, hasSamplesWithStacks); + AddProcessPriority(results, process, slice, processKeyPrioritiesFromSwitch); }); } // convert dictionary with kvp to format ProcessName(pid) and sample count in ms Dictionary perProcessSamplesInMs = new(); // sort by cpu then by process name and then by pid to get stable sort order - foreach (var kvp in myPerProcessCPU.OrderByDescending(x => x.Value).ThenBy(x => x.Key.Name).ThenBy( x=> x.Key.Pid) ) + foreach (var kvp in myPerProcessCPU.OrderByDescending(x => x.Value).ThenBy(x => x.Key.Name).ThenBy(x => x.Key.Pid)) { perProcessSamplesInMs.Add(kvp.Key, (uint)kvp.Value.TotalMilliseconds); } @@ -179,13 +216,13 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) { ContainsAllCPUData = ExtractAllCPUData, HasCPUSamplingData = hasSamplesWithStacks, - HasCSwitchData = myCpuSchedlingData.HasResult && myCpuSchedlingData.Result?.ContextSwitches?.Count > 0, + HasCSwitchData = CanUseCPUCSwitchData, }; // speed up time range calculation Parallel.ForEach(methodSamplesPerProcess, concurrency, (process) => { - foreach(KeyValuePair methodCPU in process.Value) + foreach (KeyValuePair methodCPU in process.Value) { var tmp = methodCPU.Value.ReadyTimeRange.GetDuration(); tmp = methodCPU.Value.WaitTimeRange.GetDuration(); @@ -198,13 +235,13 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) { foreach (KeyValuePair methodToMs in process2Method.Value) { - + MethodIndex methodIndex = inclusiveSamplesPerMethod.AddMethod(process2Method.Key, methodToMs.Key, methodToMs.Value, cutOffMs); - if (methodIndex != MethodIndex.Invalid && results?.CPU?.ExtendedCPUMetrics?.CPUToFrequencyDurations?.Count > 0) + if (methodIndex != MethodIndex.Invalid && results?.CPU?.HasECores == true) { if (process2Method.Key.Pid > WindowsConstants.IdleProcessId) { - var perCoreTypeCPUUsage = methodToMs.Value.GetAverageFrequenciesPerEfficiencyClass(results.CPU); + CPUUsage[] perCoreTypeCPUUsage = methodToMs.Value.GetAverageFrequenciesPerEfficiencyClass(results.CPU); if (perCoreTypeCPUUsage != null) { ETWProcessIndex processIdx = results.GetProcessIndexByPID(process2Method.Key.Pid, process2Method.Key.StartTime); @@ -243,16 +280,102 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) results.CPU.ExtendedCPUMetrics.RemapMethodIndicies(methodIndexMap); } - results.CPU = new CPUStats(perProcessSamplesInMs, inclusiveSamplesPerMethod, myTimelineExtractor?.Timeline, results.CPU?.Topology, results.CPU?.ExtendedCPUMetrics); + Dictionary processPriorities = GetProcessPriorities(indexCache, myPerProcessPriority, processKeyPrioritiesFromSwitch); + + results.CPU = new CPUStats(perProcessSamplesInMs, processPriorities, inclusiveSamplesPerMethod, myTimelineExtractor?.Timeline, results.CPU?.Topology, results.CPU?.ExtendedCPUMetrics); // Try to release memory as early as possible mySamplingData = null; myCpuSchedlingData = null; } + private void WarmupCSwitchData() + { + if (CanUseCPUCSwitchData) + { + // access CSwitch data while we are processing CPU sampling data + Task.Run(() => { var _ = myCpuSchedlingData.Result?.ThreadActivity?.FirstOrDefault(); }); + } + } + private void AddProcessPriority(ETWExtract results, ProcessKey process, ICpuThreadActivity2 slice, ConcurrentDictionary>> processKeyPrioritiesFromSwitch) + { + if( slice.SwitchIn.Priority != null) + { + int prio = slice.SwitchIn.Priority.Value; + List> list = processKeyPrioritiesFromSwitch.GetOrAdd(process, (key) => new List>()); + TraceDuration runDuration = slice.SwitchOut.ContextSwitch.Timestamp - slice.SwitchIn.ContextSwitch.Timestamp; + lock (list) + { + list.Add(new KeyValuePair(prio, runDuration.TimeSpan)); + } + } + } - private void AddPerMethodAndProcessWaits(ETWExtract extract, ProcessKey process, ICpuThreadActivity slice, ConcurrentDictionary> methodSamplesPerProcess, StackPrinter printer, bool hasCpuSampleData) + private static Dictionary BuildProcessIndexCache(ETWExtract results) + { + Dictionary indexCache = new(); + foreach (var process in results.Processes) + { + if (process.ProcessID > WindowsConstants.IdleProcessId && !String.IsNullOrEmpty(process.ProcessName)) + { + ETWProcessIndex idx = results.GetProcessIndexByPID(process.ProcessID, process.StartTime); + indexCache[process.ToProcessKey()] = idx; + } + else + { + if (process.ProcessName != null) // name can be null but pid can exist. + { + indexCache[process.ToProcessKey()] = ETWProcessIndex.Invalid; + } + } + } + + return indexCache; + } + + /// + /// Merge process priorities from Context switch and CPU sampling data + /// + /// + /// Process priorities from CPU sampling data + /// Raw data from all context switch events in a process with the assigned priority and duration. + /// Dictionary which is stored in extract. + private Dictionary GetProcessPriorities(Dictionary indexCache, Dictionary> perProcessPriority, ConcurrentDictionary>> processKeyPrioritiesFromSwitch) + { + Dictionary lret = new(); + foreach (var kvp in perProcessPriority) + { + lret[kvp.Key] = (float)Math.Round(kvp.Value.Average(), 1); + } + + foreach (var process2Prio in processKeyPrioritiesFromSwitch) + { + decimal totalWeight = 0.0m; + decimal totalTime = 0.0m; + foreach(KeyValuePair prioTime in process2Prio.Value) + { + totalWeight += ((decimal) prioTime.Value.TotalMilliseconds) * prioTime.Key; + totalTime += (decimal)prioTime.Value.TotalMilliseconds; + } + + decimal averagePrio = totalWeight / totalTime; + + + if( indexCache.TryGetValue(process2Prio.Key, out ETWProcessIndex procIndex) ) + { + if (!lret.ContainsKey(procIndex)) + { + lret[procIndex] = (float)Math.Round(averagePrio, 1); + } + } + } + + + return lret; + } + + private void AddPerMethodAndProcessWaits(ETWExtract extract, ProcessKey process, ICpuThreadActivity2 slice, ConcurrentDictionary> methodSamplesPerProcess, StackPrinter printer, bool hasCpuSampleData) { if (slice?.Process?.ImageName == null) // Image Name can be null sometimes { @@ -326,7 +449,7 @@ private void AddPerMethodAndProcessWaits(ETWExtract extract, ProcessKey process, { TraceTimestamp readyStart = slice.SwitchIn.ContextSwitch.Timestamp - slice.ReadyDuration.Value; stats.ReadyTimeRange.Add(readyStart, slice.ReadyDuration.Value); - stats.AddExtendedReadyMetrics(extract.CPU, (CPUNumber)slice.Processor, (float)readyStart.RelativeTimestamp.TotalSeconds, (float)slice.ReadyDuration.Value.TotalSeconds, slice.Thread.Id, slice.Thread.ProcessorAffinity); + stats.AddExtendedReadyMetrics(slice); } decimal time = slice.StopTime.RelativeTimestamp.TotalSeconds; @@ -451,9 +574,11 @@ private static void UpdateMethodTimingAndThreadId(CPUMethodData stats, decimal t /// Update per process CPU usage from CPU Sampling data. This is preferred. /// /// + /// map of processKey instances to ETWProcessIndex /// /// - private static void AddTotalCPU(ProcessKey process, ICpuSample sample, ConcurrentDictionary perProcessCPU) + /// + private static void AddTotalCPUAndPriority(ProcessKey process, Dictionary indexCache, ICpuSample sample, ConcurrentDictionary perProcessCPU, Dictionary> perProcessPriority) { Duration duration = default; do @@ -463,6 +588,23 @@ private static void AddTotalCPU(ProcessKey process, ICpuSample sample, Concurren perProcessCPU.TryAdd(process, default); } } while (!perProcessCPU.TryUpdate(process, sample.Weight + duration, duration)); + + lock(perProcessPriority) + { + if (indexCache.TryGetValue(process, out ETWProcessIndex idx)) + { + if (!perProcessPriority.TryGetValue(idx, out List prios)) + { + prios = new(); + perProcessPriority.Add(idx, prios); + } + + if (sample.Priority != null) + { + prios.Add(sample.Priority.Value); + } + } + } } /// diff --git a/ETWAnalyzer/Extractors/CPU/CPUMethodData.cs b/ETWAnalyzer/Extractors/CPU/CPUMethodData.cs index 821fa28d..5067a026 100644 --- a/ETWAnalyzer/Extractors/CPU/CPUMethodData.cs +++ b/ETWAnalyzer/Extractors/CPU/CPUMethodData.cs @@ -7,6 +7,7 @@ using ETWAnalyzer.Infrastructure; using ETWAnalyzer.TraceProcessorHelpers; using Microsoft.Windows.EventTracing; +using Microsoft.Windows.EventTracing.Cpu; using System; using System.Collections.Concurrent; using System.Collections.Generic; @@ -20,6 +21,11 @@ namespace ETWAnalyzer.Extractors.CPU /// internal class CPUMethodData { + /// + /// We calculate metrics only if at least this number of CSwitch events are present to get meaningful data + /// + const int MinCSwitchCount = 50; + /// /// Contains CPU data summed across all threads /// @@ -53,7 +59,7 @@ public Duration CpuInMs class CPUDetails { public int UsedCores { get; set; } - public List ProfilingData { get; set; } = new(); + public List ProfilingData { get; set; } = new(10); } /// @@ -130,31 +136,86 @@ public CPUUsage[] GetAverageFrequenciesPerEfficiencyClass(CPUStats context) public ReadyTimes GetReadyMetrics(CPUStats context) { ReadyTimes lret = new ReadyTimes(); - List readyDurations = []; + List deepSleepReadyDurationNanoS = []; + List interferenceReadyDurationNanoS = []; + foreach(var ready in CPUToReadyDuration) { - readyDurations.AddRange(ready.Value.Select(x => x.DurationS)); + deepSleepReadyDurationNanoS.AddRange( ready.Value.Where(x => x.DeepSleepReady).Select(x => x.DurationNanoS)); + interferenceReadyDurationNanoS.AddRange( ready.Value.Where(x => !x.DeepSleepReady).Select(x => x.DurationNanoS)); + } + + if (deepSleepReadyDurationNanoS.Count > MinCSwitchCount) + { + deepSleepReadyDurationNanoS.Sort(); + + lret.AddReadyTimes(deepSleep: true, + deepSleepReadyDurationNanoS.Count, + deepSleepReadyDurationNanoS.Min(), + deepSleepReadyDurationNanoS.Max(), + deepSleepReadyDurationNanoS.Percentile(0.05f), + deepSleepReadyDurationNanoS.Percentile(0.25f), + deepSleepReadyDurationNanoS.Percentile(0.50f), + deepSleepReadyDurationNanoS.Percentile(0.90f), + deepSleepReadyDurationNanoS.Percentile(0.95f), + deepSleepReadyDurationNanoS.Percentile(0.99f), + GetSum(deepSleepReadyDurationNanoS), + GetSumAbove99Percentile(deepSleepReadyDurationNanoS)); } - if (readyDurations.Count > 50) + if (interferenceReadyDurationNanoS.Count > MinCSwitchCount) { - readyDurations.Sort(); - lret.AddReadyTimes(readyDurations.Min(), - readyDurations.Max(), - readyDurations.Percentile( 0.05f ), - readyDurations.Percentile( 0.25f ), - readyDurations.Percentile( 0.50f ), - readyDurations.Percentile( 0.90f ), - readyDurations.Percentile( 0.95f ), - readyDurations.Percentile( 0.99f )); - - return lret; + interferenceReadyDurationNanoS.Sort(); + + lret.AddReadyTimes(deepSleep: false, + interferenceReadyDurationNanoS.Count, + interferenceReadyDurationNanoS.Min(), + interferenceReadyDurationNanoS.Max(), + interferenceReadyDurationNanoS.Percentile(0.05f), + interferenceReadyDurationNanoS.Percentile(0.25f), + interferenceReadyDurationNanoS.Percentile(0.50f), + interferenceReadyDurationNanoS.Percentile(0.90f), + interferenceReadyDurationNanoS.Percentile(0.95f), + interferenceReadyDurationNanoS.Percentile(0.99f), + GetSum(interferenceReadyDurationNanoS), + GetSumAbove99Percentile(interferenceReadyDurationNanoS)); } - else + + // return null in case we have no events to make serialized data more compact + return (lret.DeepSleep.Count > 0 || lret.Other.Count > 0) ? lret: null; + } + + /// + /// Get sum of sorted list for all values which are above the 99% percentile. + /// + /// + /// 99 Percentile sum. + decimal GetSumAbove99Percentile(List values) + { + decimal sum = 0.0m; + int skip = (int)(values.Count * 0.99); + for (int i = skip; i < values.Count; i++) + { + sum += (decimal)values[i]; + } + + return sum; + } + + /// + /// Get sum of long values with decimal precision. + /// + /// + /// + decimal GetSum(List values) + { + decimal sum = 0.0m; + foreach(var value in values) { - return null; + sum += (decimal)value; } + return sum; } /// @@ -217,7 +278,7 @@ internal CPUMethodData() { } - internal class ProfilingData + internal struct ProfilingData { public float DurationS { get; set; } public float StartTimeS { get; set; } @@ -241,7 +302,7 @@ internal class ProfilingData /// public void AddForExtendedMetrics(CPUStats cpuStats, CPUNumber cpu, float start, float end, int threadId, long cpuAffinityMask, string debugData) { - if (cpuStats.ExtendedCPUMetrics != null && cpuStats.ExtendedCPUMetrics.CPUToFrequencyDurations.Count > 0) + if (cpuStats.ExtendedCPUMetrics != null) { if( !CPUToFrequencyDuration.TryGetValue(cpu, out List frequencyDurations) ) { @@ -255,7 +316,11 @@ public void AddForExtendedMetrics(CPUStats cpuStats, CPUNumber cpu, float start, { // Use default frequency if we get no frequency data or CPU was turned off but this is not possible if we get sampling/CWSwitch data // CPU Frequency data from ETW provider is sampled with a granularity of 15-30ms. - averageFrequency = cpuStats.Topology[cpu].NominalFrequencyMHz; + + if( cpuStats?.Topology?.TryGetValue(cpu, out var topology) == true) // sometimes not all cores are covered by topology + { + averageFrequency = topology.NominalFrequencyMHz; + } } ulong enabledCPUs = 0; @@ -275,34 +340,50 @@ public void AddForExtendedMetrics(CPUStats cpuStats, CPUNumber cpu, float start, }); } } - + + /// + /// Working structure to collect intermediate data from context switch events. Not serialied to Json + /// internal class ReadyEvent { - public float StartTimeS { get; set; } + public long StartTimeNanoS { get; set; } - public float DurationS { get; set; } + public long DurationNanoS { get; set; } public int ThreadId { get; set; } - public long EnabledCPUs { get; set; } + public bool DeepSleepReady { get; set; } } - internal void AddExtendedReadyMetrics(CPUStats cpu, CPUNumber processor, float readyStartS, float readyDurationS, int threadId, long cpuAffinityMask) + + /// + /// Collect extended Ready delays coming from processor deep sleep states and cross thread interference. + /// + /// Thread activity which contains context switch events. + internal void AddExtendedReadyMetrics(ICpuThreadActivity2 slice) { lock (this) { - if( !CPUToReadyDuration.TryGetValue(processor, out var readies) ) + CPUNumber processor = (CPUNumber)slice.Processor; + if ( !CPUToReadyDuration.TryGetValue(processor, out var readies) ) { readies = []; CPUToReadyDuration[processor] = readies; } + if( slice.PreviousActivityOnProcessor == null ) // + { + return; + } + + // just record data from idle thread to calculate cpu wakup time from sleep and deep sleep states readies.Add(new ReadyEvent { - StartTimeS = readyStartS, - DurationS = readyDurationS, - ThreadId = threadId, -#if NET6_0_OR_GREATER - EnabledCPUs = (long)System.Runtime.Intrinsics.X86.Popcnt.X64.PopCount((ulong)cpuAffinityMask), -#endif + StartTimeNanoS = (slice.SwitchIn.ContextSwitch.Timestamp - slice.ReadyDuration.Value).RelativeTimestamp.Nanoseconds, + DurationNanoS = slice.ReadyDuration.Value.Nanoseconds, + ThreadId = slice.Thread.Id, + // We are interested in the performance impact of deep sleep states which is the processor power up time. + // All other delays are the ready times from shallow sleep states (should be fast) and thread interference from other threads of the same or other processes. + // Windows abstracts shallow sleep states (C1/C1E) as CState = 0 and all deeper sleep states as CState = 1 + DeepSleepReady = slice.PreviousActivityOnProcessor.Process.Id == WindowsConstants.IdleProcessId && slice?.SwitchIn?.ContextSwitch?.PreviousCState == 1, }); } } diff --git a/ETWAnalyzer/Extractors/CPU/CpuFrequencyExtractor.cs b/ETWAnalyzer/Extractors/CPU/CpuFrequencyExtractor.cs index a31a08bd..52326815 100644 --- a/ETWAnalyzer/Extractors/CPU/CpuFrequencyExtractor.cs +++ b/ETWAnalyzer/Extractors/CPU/CpuFrequencyExtractor.cs @@ -1,17 +1,8 @@ -using Microsoft.Windows.EventTracing.Cpu; +using ETWAnalyzer.Extract; +using ETWAnalyzer.Extract.CPU.Extended; +using ETWAnalyzer.Infrastructure; using Microsoft.Windows.EventTracing; using System; -using System.Collections.Generic; -using System.Linq; -using System.Text; -using System.Threading.Tasks; -using ETWAnalyzer.Infrastructure; -using ETWAnalyzer.Extract; -using ETWAnalyzer.TraceProcessorHelpers; -using ETWAnalyzer.Extract.CPU; -using ETWAnalyzer.Analyzers.Exception.ResultPrinter; -using ETWAnalyzer.ProcessTools; -using ETWAnalyzer.Extract.CPU.Extended; namespace ETWAnalyzer.Extractors.CPU { @@ -40,14 +31,18 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) { if( cpu.AverageFrequency == null) { - Console.WriteLine($"Warning: File {results.SourceETLFileName} contains no CPU frequency ETW data, but CPU Frequency is null. This happens when the CaptureState for the Microsoft-Windows-Kernel-Processor-Power provider is missing."); + Console.WriteLine($"Warning: File {results.SourceETLFileName} contains CPU frequency ETW data, but AverageFrequency is null. This happens when the CaptureState for the Microsoft-Windows-Kernel-Processor-Power provider is missing."); break; } - frequencyData.AddFrequencyDuration((CPUNumber)cpu.Processor, (float) cpu.StartTime.RelativeTimestamp.TotalSeconds, (float) cpu.StopTime.RelativeTimestamp.TotalSeconds, (int) cpu.AverageFrequency.Value.TotalMegahertz); + + if (cpu.AverageFrequency.Value.TotalMegahertz > 0.0m) // sometimes we get 0 readings which are spurious events which are arriving also sometimes even if we did not record Frequency data + { + frequencyData.AddFrequencyDuration((CPUNumber)cpu.Processor, (float)cpu.StartTime.RelativeTimestamp.TotalSeconds, (float)cpu.StopTime.RelativeTimestamp.TotalSeconds, (int)cpu.AverageFrequency.Value.TotalMegahertz); + } } // Frequency Extractor comes always before CPU extractor - results.CPU = new CPUStats(null, null, null, results?.CPU?.Topology, frequencyData); + results.CPU = new CPUStats(null, null, null, null, results?.CPU?.Topology, frequencyData); } } } diff --git a/ETWAnalyzer/Extractors/CPU/StackTagExtractor.cs b/ETWAnalyzer/Extractors/CPU/StackTagExtractor.cs index 12abc556..28d503cf 100644 --- a/ETWAnalyzer/Extractors/CPU/StackTagExtractor.cs +++ b/ETWAnalyzer/Extractors/CPU/StackTagExtractor.cs @@ -62,6 +62,28 @@ public string SpecialStacktagFile } = ConfigFiles.SpecialStackTagFile; public int? Concurrency { get; internal set; } + /// + /// Ignore CPU sampling data. Used when CPU sampling data is corrupt + /// + public bool NoSampling { get; internal set; } + + + /// + /// Ignore Context Switch data. Can conserve memory during extraction at the cost of missing thread wait/ready data. + /// + public bool NoCSwitch { get; internal set; } + + /// + /// True when it is not disabled and we have data + /// + bool CanUseCpuSamplingData { get => mySamplingData?.HasResult == true && !NoSampling; } + + /// + /// True when it is not disabld and we have CSwitch data + /// + bool CanUseCPUCSwitchData { get => myCpuSchedlingData?.HasResult == true && !NoCSwitch; } + + /// /// GC/JIT Stacktags are thrown away when smaller 10ms /// @@ -76,8 +98,16 @@ public override void RegisterParsers(ITraceProcessor processor) { NeedsSymbols = true; myStackTags = processor.UseStackTags(); - mySamplingData = processor.UseCpuSamplingData(); - myCpuSchedlingData = processor.UseCpuSchedulingData(); + + if (!NoSampling) + { + mySamplingData = processor.UseCpuSamplingData(); + } + + if (!NoCSwitch) + { + myCpuSchedlingData = processor.UseCpuSchedulingData(); + } } public override void Extract(ITraceProcessor processor, ETWExtract results) @@ -134,30 +164,33 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) void ExtractStackTagsFromProfilingAndContextSwitchEvents(IStackTagMapper mapper, Dictionary> tags, bool addDefaultStackTag) { - // Get Stack Tag information from CPU Sampling data - foreach (ICpuSample sample in mySamplingData.Result.Samples) + if (CanUseCpuSamplingData) { - DateTimeOffset createTime = DateTimeOffset.MinValue; - if ((sample?.Process?.CreateTime).HasValue) + // Get Stack Tag information from CPU Sampling data + foreach (ICpuSample sample in mySamplingData.Result.Samples) { - createTime = sample.Process.CreateTime.Value.DateTimeOffset; - } + DateTimeOffset createTime = DateTimeOffset.MinValue; + if ((sample?.Process?.CreateTime).HasValue) + { + createTime = sample.Process.CreateTime.Value.DateTimeOffset; + } - string imageName = sample?.Process?.ImageName; - if (imageName == null) - { - continue; - } + string imageName = sample?.Process?.ImageName; + if (imageName == null) + { + continue; + } - var key = new ProcessKey(imageName, sample.Process.Id, createTime); + var key = new ProcessKey(imageName, sample.Process.Id, createTime); - AddSampleDuration(mapper, tags, sample, key, addDefaultStackTag); + AddSampleDuration(mapper, tags, sample, key, addDefaultStackTag); + } } // When we have context switch data recorded we can also calculate the thread wait time stacktags - if (myCpuSchedlingData.HasResult) + if( CanUseCPUCSwitchData ) { foreach (ICpuThreadActivity slice in myCpuSchedlingData.Result.ThreadActivity) { diff --git a/ETWAnalyzer/Extractors/ExtractSerializer.cs b/ETWAnalyzer/Extractors/ExtractSerializer.cs index 0871ae43..cada8fa8 100644 --- a/ETWAnalyzer/Extractors/ExtractSerializer.cs +++ b/ETWAnalyzer/Extractors/ExtractSerializer.cs @@ -110,8 +110,8 @@ public List Serialize(string outputFile, ETWExtract extract) extract.Modules = null; } - // write extended CPU file only if we have data inside it - if( extract?.CPU?.ExtendedCPUMetrics != null && ( extract.CPU.ExtendedCPUMetrics.CPUToFrequencyDurations.Count > 0 || extract.CPU.ExtendedCPUMetrics.MethodData.Count > 0) ) + // write extended CPU file only if we have data inside it or we have E-Core data + if( extract?.CPU?.ExtendedCPUMetrics != null && ( extract.CPU.ExtendedCPUMetrics.HasFrequencyData || extract.CPU.ExtendedCPUMetrics.MethodData.Count > 0) ) { using var frequencyStream = GetOutputStreamFor(outputFile, ExtendedCPUPostFix, outputFiles); Serialize(frequencyStream, extract.CPU.ExtendedCPUMetrics); diff --git a/ETWAnalyzer/Extractors/MachineDetailsExtractor.cs b/ETWAnalyzer/Extractors/MachineDetailsExtractor.cs index 49bb951b..d0609173 100644 --- a/ETWAnalyzer/Extractors/MachineDetailsExtractor.cs +++ b/ETWAnalyzer/Extractors/MachineDetailsExtractor.cs @@ -83,7 +83,7 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) }; } - results.CPU = new CPUStats(results?.CPU?.PerProcessCPUConsumptionInMs, results?.CPU?.PerProcessMethodCostsInclusive, results?.CPU?.TimeLine, cpuTopology, null); + results.CPU = new CPUStats(results?.CPU?.PerProcessCPUConsumptionInMs, results?.CPU?.PerProcessAvgCPUPriority, results?.CPU?.PerProcessMethodCostsInclusive, results?.CPU?.TimeLine, cpuTopology, null); } } catch (InvalidTraceDataException ex) diff --git a/ETWAnalyzer/Extractors/Power/PowerExtractor.cs b/ETWAnalyzer/Extractors/Power/PowerExtractor.cs index 2def1d38..f1d75a55 100644 --- a/ETWAnalyzer/Extractors/Power/PowerExtractor.cs +++ b/ETWAnalyzer/Extractors/Power/PowerExtractor.cs @@ -4,8 +4,13 @@ using ETWAnalyzer.Extract; using ETWAnalyzer.Extract.Power; using ETWAnalyzer.Infrastructure; +using ETWAnalyzer.TraceProcessorHelpers; using Microsoft.Windows.EventTracing; +using Microsoft.Windows.EventTracing.Events; using System; +using System.Collections.Generic; +using System.Linq; +using System.Runtime.InteropServices; namespace ETWAnalyzer.Extractors.Power { @@ -19,6 +24,25 @@ internal class PowerExtractor : ExtractorBase /// IPendingResult myPower; + /// + /// Power Event Data which are not parsed by TraceProcssing + /// + IPendingResult myPowerEvents; + + + /// + /// As long as these settings are missing from TraceProcessing we parse them on our own. + /// + static Dictionary> mySettingParsers = new() + { + { new Guid("245d8541-3943-4422-b025-13a784f679b7"), ParsePowerProfileBaseGuid }, + { new Guid("8baa4a8a-14c6-4451-8e8b-14bdbd197537"), ParseProcessorAutonomousMode }, + { new Guid("93b8b6dc-0698-4d1c-9ee4-0644e900c85d"), ParseHeteroThreadSchedulingPolicy }, + { new Guid("bae08b81-2d5e-4688-ad6a-13243356654b"), ParseHeteroThreadSchedulingPolicyShort }, + { new Guid("7f2f5cfa-f10c-4823-b5e1-e93ae85f46b5"), ParseHeteroPolicyInEffect }, + { new Guid("31f9f286-5084-42fe-b720-2b0264993763"), ParseActivePowerScheme }, + }; + /// /// Register Power parser. /// @@ -27,6 +51,7 @@ public override void RegisterParsers(ITraceProcessor processor) { base.RegisterParsers(processor); myPower = processor.UsePowerConfigurationData(); + myPowerEvents = processor.UseGenericEvents(KernelPowerConstants.Guid); } /// @@ -102,6 +127,119 @@ public override void Extract(ITraceProcessor processor, ETWExtract results) previous = powerData; } } + + if (myPowerEvents.HasResult) + { + foreach (var powerEvent in myPowerEvents.Result.Events) + { + if (powerEvent.Id == KernelPowerConstants.PowerSettingsRundownEventId) + { + if (mySettingParsers.TryGetValue(powerEvent.Fields[0].AsGuid, out var parser)) + { + parser(powerEvent, results); + } + } + } + } + } + } + + + + static PowerConfiguration Get(ETWExtract extract) + { + return extract.PowerConfiguration.FirstOrDefault(); + } + + private static void ParseHeteroPolicyInEffect(IGenericEvent @event, ETWExtract extract) + { + PowerConfiguration cfg = Get(extract); + if (cfg != null) + { + cfg.HeteroPolicyInEffect = (int)ReadUInt32(@event.Fields[2].AsBinary); + } + } + + private static void ParseHeteroThreadSchedulingPolicyShort(IGenericEvent @event, ETWExtract extract) + { + PowerConfiguration cfg = Get(extract); + if (cfg != null) + { + cfg.HeteroPolicyThreadSchedulingShort = (HeteroThreadSchedulingPolicy)ReadUInt32(@event.Fields[2].AsBinary); + } + + } + + private static void ParseHeteroThreadSchedulingPolicy(IGenericEvent @event, ETWExtract extract) + { + PowerConfiguration cfg = Get(extract); + if (cfg != null) + { + cfg.HeteroPolicyThreadScheduling = (HeteroThreadSchedulingPolicy)ReadUInt32(@event.Fields[2].AsBinary); + } + + } + + private static void ParseProcessorAutonomousMode(IGenericEvent @event, ETWExtract extract) + { + PowerConfiguration cfg = Get(extract); + if (cfg != null) + { + cfg.AutonomousMode = ReadBoolean(@event.Fields[2].AsBinary); + } + + } + + private static void ParseActivePowerScheme(IGenericEvent @event, ETWExtract extract) + { + PowerConfiguration cfg = Get(extract); + if (cfg != null) + { + Guid currentProfile = new Guid(@event.Fields[2].AsBinary.ToArray()); + KernelPowerConstants.BasePowerProfiles.TryGetValue(currentProfile, out var powerProfile); + cfg.ActivePowerProfile = powerProfile; + cfg.ActivePowerProfileGuid = currentProfile; + } + } + + static void ParsePowerProfileBaseGuid(IGenericEvent ev, ETWExtract extract) + { + PowerConfiguration cfg = Get(extract); + if (cfg != null) + { + Guid baseProfile = new Guid(ev.Fields[2].AsBinary.ToArray()); + KernelPowerConstants.BasePowerProfiles.TryGetValue(baseProfile, out var powerProfile); + cfg.BaseProfile = powerProfile; + } + } + + + static bool ReadBoolean(IReadOnlyList data) + { + return ReadUInt32(data) != 0; + } + + static uint ReadUInt32(IReadOnlyList data) + { + return ReadUnmanaged(data); + } + + unsafe static T ReadUnmanaged(IReadOnlyList data) where T : unmanaged + { + checked + { + ushort num = (ushort)sizeof(T); + ValidateRemainingLength((ushort)data.Count, num); + T result = MemoryMarshal.Read(data.ToArray().AsSpan()); + return result; + } + } + + static void ValidateRemainingLength(int remainingLength, int neededLength) + { + if (remainingLength < neededLength) + { + throw new InvalidTraceDataException($"The trace contains an event that failed to parse. {neededLength} bytes were needed but only " + $"{remainingLength} bytes were available."); } } } diff --git a/ETWAnalyzer/Infrastructure/Numeric.cs b/ETWAnalyzer/Infrastructure/Numeric.cs index 864afbfc..1762f4c7 100644 --- a/ETWAnalyzer/Infrastructure/Numeric.cs +++ b/ETWAnalyzer/Infrastructure/Numeric.cs @@ -76,5 +76,96 @@ public static float Percentile(this List values, float percentile) return values[k - 1] + d * (values[k] - values[k - 1]); } } + + /// + /// Calculate the percentile with interpolation between values. The returned value does not + /// necessarily exist. It interpolates between two values based on the relative distance. + /// Excel uses this approach. + /// + /// Sequence of sorted values. + /// Percentile to calculate. + /// Median value which might be interpolated. + public static decimal Percentile(this List values, decimal percentile) + { + if (values == null) + { + throw new ArgumentNullException(nameof(values)); + } + + if (values.Count == 0) + { + return 0; + } + + int N = values.Count; + decimal n = (N - 1) * percentile + 1; + + + + if (n == 1.0m) + { + return values[0]; + } + else if (n == N) + { + return values[N - 1]; + } + else + { + int k = (int)n; + decimal d = n - k; +#if DEBUG + + Debug.Assert(values[k] >= values[k - 1], "Input array is not sorted!"); +#endif + return values[k - 1] + d * (values[k] - values[k - 1]); + } + } + + + /// + /// Calculate the percentile with interpolation between values. The returned value does not + /// necessarily exist. It interpolates between two values based on the relative distance. + /// Excel uses this approach. + /// + /// Sequence of sorted values. + /// Percentile to calculate. + /// Median value which might be interpolated. + public static long Percentile(this List values, float percentile) + { + if (values == null) + { + throw new ArgumentNullException(nameof(values)); + } + + if (values.Count == 0) + { + return 0; + } + + int N = values.Count; + float n = (N - 1) * percentile + 1; + + + + if (n == 1.0f) + { + return values[0]; + } + else if (n == N) + { + return values[N - 1]; + } + else + { + int k = (int)n; + float d = n - k; +#if DEBUG + + Debug.Assert(values[k] >= values[k - 1], "Input array is not sorted!"); +#endif + return (long) (values[k - 1] + d * (values[k] - values[k - 1])); + } + } } } diff --git a/ETWAnalyzer/Properties/AssemblyInfo.cs b/ETWAnalyzer/Properties/AssemblyInfo.cs index abcc1139..a8671441 100644 --- a/ETWAnalyzer/Properties/AssemblyInfo.cs +++ b/ETWAnalyzer/Properties/AssemblyInfo.cs @@ -42,4 +42,4 @@ // by using the '*' as shown below: // [assembly: AssemblyVersion("1.0.*")] [assembly: AssemblyVersion("1.0.0.0")] -[assembly: AssemblyFileVersion("3.0.0.0")] +[assembly: AssemblyFileVersion("3.0.0.1")] diff --git a/ETWAnalyzer/TraceProcessorHelpers/KernelPowerConstants.cs b/ETWAnalyzer/TraceProcessorHelpers/KernelPowerConstants.cs new file mode 100644 index 00000000..6225b242 --- /dev/null +++ b/ETWAnalyzer/TraceProcessorHelpers/KernelPowerConstants.cs @@ -0,0 +1,24 @@ +//// SPDX-FileCopyrightText: © 2024 Siemens Healthcare GmbH +//// SPDX-License-Identifier: MIT + + +using ETWAnalyzer.Extract.Power; +using System; +using System.Collections.Generic; + +namespace ETWAnalyzer.TraceProcessorHelpers +{ + internal class KernelPowerConstants + { + public static readonly Guid Guid = new Guid("331c3b3a-2005-44c2-ac5e-77220c37d6b4"); + public const int PowerSettingsRundownEventId = 111; + + public static readonly Dictionary BasePowerProfiles = new Dictionary() + { + { new Guid("381b4222-f694-41f0-9685-ff5bb260df2e"), BasePowerProfile.Balanced }, + { new Guid("8c5e7fda-e8bf-4a96-9a85-a6e23a8c635c"), BasePowerProfile.HighPerformance }, + { new Guid("a1841308-3541-4fab-bc81-f71556f20b4a"), BasePowerProfile.PowerSaver }, + { new Guid("e9a42b02-d5df-448d-aa00-03f14749eb61"), BasePowerProfile.UltimatePerformance }, + }; + } +} diff --git a/ETWAnalyzer/runtimeconfig.template.json b/ETWAnalyzer/runtimeconfig.template.json index 824f4ec2..7f28ebda 100644 --- a/ETWAnalyzer/runtimeconfig.template.json +++ b/ETWAnalyzer/runtimeconfig.template.json @@ -1,7 +1,6 @@ { "configProperties": { "System.GC.Server": true, - "System.GC.HeapCount": 4, "System.GC.NoAffinitize": true } } \ No newline at end of file diff --git a/ETWAnalyzer_iTest/ProgramTestsLong.cs b/ETWAnalyzer_iTest/ProgramTestsLong.cs index ebf00f21..7959e3c3 100644 --- a/ETWAnalyzer_iTest/ProgramTestsLong.cs +++ b/ETWAnalyzer_iTest/ProgramTestsLong.cs @@ -3,6 +3,7 @@ using ETWAnalyzer; using ETWAnalyzer.Extract; +using ETWAnalyzer.Extract.CPU.Extended; using ETWAnalyzer.Extract.Exceptions; using ETWAnalyzer.Extract.Modules; using ETWAnalyzer.Extractors; @@ -163,7 +164,7 @@ public void Can_Extract_From_ETLFolder_Check_Extract() if (!TestContext.IsInGithubPipeline()) // when we are executed with symbol server access then use it to resolve method names { - extractArgs = extractArgs.Concat(new string[] { "-symserver", "MS" }).ToArray(); + // extractArgs = extractArgs.Concat(new string[] { "-symserver", "MS" }).ToArray(); } Program.MainCore(extractArgs); @@ -394,9 +395,56 @@ private void CheckServerExtract(ETWExtract extractedServer, string extractJsonFi Assert.Equal(1133445uL, extractedServer.Disk.TotalDiskServiceTimeInus); Assert.Equal(386783uL, extractedServer.Disk.TotalDiskWriteTimeTimeInus); + + ETWProcessIndex serializerTestsProcIdx = extractedServer.GetProcessIndex("SerializerTests.exe (22416)"); // Check CPU summary data Assert.Equal(121, extractedServer.CPU.PerProcessCPUConsumptionInMs.Count); Assert.Equal(3430u, extractedServer.CPU.PerProcessCPUConsumptionInMs.Where( x=> x.Key.Name == "SerializerTests.exe" && x.Key.Pid == 22416).FirstOrDefault().Value ); + Assert.Equal(8.2f, extractedServer.CPU.PerProcessAvgCPUPriority[serializerTestsProcIdx]); + + // we need to set file name to be able to deserialize extended CPU data + extractedServer.DeserializedFileName = extractJsonFileName; + + // Check extended metrics + // CPU ms Wait ms Ready ms ReadyAvg CSwitches Method + // 2,571 ms 91 ms 2 ms 17 us 125 SerializerTests.TestBase`2[System.__Canon,System.__Canon].Test + //Min: 1.8 us 5 % 5.4 us 25 % 6.6 us 50 % 7.7 us 90 %: 32 us 95 %: 49 us 99 %: 59 us Max: 62 us Sum: 0.0009 s Count: 61 DeepSleep + //Min: 1.5 us 5 % 6.3 us 25 % 7.8 us 50 % 11.4 us 90 %: 44 us 95 %: 68 us 99 %: 98 us Max: 115 us Sum: 0.0013 s Count: 64 NonDeepSleep + MethodIndex idx = (MethodIndex)extractedServer.CPU.PerProcessMethodCostsInclusive.MethodNames.FindIndex(x => x == "SerializerTests.dll!SerializerTests.TestBase`2[System.__Canon,System.__Canon].Test"); + ProcessMethodIdx procThreadIdx = serializerTestsProcIdx.Create(idx); + ICPUMethodData extendedCPUTestMethod = ((IETWExtract)extractedServer).CPU.ExtendedCPUMetrics.MethodIndexToCPUMethodData[procThreadIdx]; + Assert.Equal(1.8, extendedCPUTestMethod.ReadyMetrics.MinDeepSleepUs); + Assert.Equal(1.5, extendedCPUTestMethod.ReadyMetrics.MinNonDeepSleepUs); + + Assert.Equal(5.4, extendedCPUTestMethod.ReadyMetrics.Percentile5DeepSleepUs); + Assert.Equal(6.3, Math.Round(extendedCPUTestMethod.ReadyMetrics.Percentile5NonDeepSleepUs, 1)); + + Assert.Equal(6.6, Math.Round(extendedCPUTestMethod.ReadyMetrics.Percentile25DeepSleepUs, 1)); + Assert.Equal(7.8, Math.Round(extendedCPUTestMethod.ReadyMetrics.Percentile25NonDeepSleepUs, 1)); + + Assert.Equal(7.7, Math.Round(extendedCPUTestMethod.ReadyMetrics.Percentile50DeepSleepUs, 1)); + Assert.Equal(11.4, Math.Round(extendedCPUTestMethod.ReadyMetrics.Percentile50NonDeepSleepUs, 1)); + + Assert.Equal(32, Math.Round(extendedCPUTestMethod.ReadyMetrics.Percentile90DeepSleepUs, 0)); + Assert.Equal(44, Math.Round(extendedCPUTestMethod.ReadyMetrics.Percentile90NonDeepSleepUs, 0)); + + Assert.Equal(48, Math.Round(extendedCPUTestMethod.ReadyMetrics.Percentile95DeepSleepUs, 0, MidpointRounding.ToZero)); + Assert.Equal(68, Math.Round(extendedCPUTestMethod.ReadyMetrics.Percentile95NonDeepSleepUs, 0)); + + Assert.Equal(59, Math.Round(extendedCPUTestMethod.ReadyMetrics.Percentile99DeepSleepUs, 0)); + Assert.Equal(98, Math.Round(extendedCPUTestMethod.ReadyMetrics.Percentile99NonDeepSleepUs, 0)); + + Assert.Equal(62, Math.Round(extendedCPUTestMethod.ReadyMetrics.MaxDeepSleepUs, 0)); + Assert.Equal(115, Math.Round(extendedCPUTestMethod.ReadyMetrics.MaxNonDeepSleepUs, 0)); + + Assert.Equal(852.5, extendedCPUTestMethod.ReadyMetrics.SumDeepSleepUs); + Assert.Equal(1283.5, extendedCPUTestMethod.ReadyMetrics.SumNonDeepSleepUs); + + Assert.Equal(61, extendedCPUTestMethod.ReadyMetrics.CSwitchCountDeepSleep); + Assert.Equal(64, extendedCPUTestMethod.ReadyMetrics.CSwitchCountNonDeepSleep); + + + // Check CPU Method Level Data // @@ -412,6 +460,8 @@ private void CheckServerExtract(ETWExtract extractedServer, string extractJsonFi MethodCost cost = methods.Costs.Where(x => x.Method == "SerializerTests.dll!SerializerTests.Program.Combined").First(); Assert.Equal(2899u, cost.CPUMs); Assert.Equal(5u, cost.ReadyMs); + Assert.Equal(16u, cost.ReadyAverageUs); + Assert.Equal(347u, cost.ContextSwitchCount); Assert.Equal(1227u, cost.WaitMs); Assert.Equal(1, cost.Threads); Assert.Equal(3.7385f, cost.FirstOccurenceInSecond); diff --git a/ETWAnalyzer_uTest/CPUPerProcessMethodListTests.cs b/ETWAnalyzer_uTest/CPUPerProcessMethodListTests.cs index 8d0cd45c..f935aa88 100644 --- a/ETWAnalyzer_uTest/CPUPerProcessMethodListTests.cs +++ b/ETWAnalyzer_uTest/CPUPerProcessMethodListTests.cs @@ -70,7 +70,7 @@ public void Can_Serialize_Deserialize_CPU_Stats() { ETWExtract extract = new ETWExtract(); CPUPerProcessMethodList list = GetTestData(); - extract.CPU = new CPUStats(null, list, null,null, null); + extract.CPU = new CPUStats(null, null, list, null,null, null); MemoryStream stream = new MemoryStream(); ExtractSerializer.Serialize(stream, extract); diff --git a/ETWAnalyzer_uTest/EventDump/DumpCPUMethodTests.cs b/ETWAnalyzer_uTest/EventDump/DumpCPUMethodTests.cs index 797bc8d7..1ac078aa 100644 --- a/ETWAnalyzer_uTest/EventDump/DumpCPUMethodTests.cs +++ b/ETWAnalyzer_uTest/EventDump/DumpCPUMethodTests.cs @@ -184,7 +184,7 @@ SingleTest CreateSingleTest(string directory) DummyMethod, }; - extract.CPU = new CPUStats(null, new CPUPerProcessMethodList() + extract.CPU = new CPUStats(null, null, new CPUPerProcessMethodList() { MethodStatsPerProcess = new List { @@ -212,6 +212,7 @@ SingleTest CreateSingleTest(string directory) ProcessName = "cmd.exe", CmdLine = "hi", StartTime = new DateTimeOffset(1, 1, 1, 0, 2, 0, TimeSpan.Zero), + EndTime = DateTimeOffset.MaxValue, IsNew = true, }; @@ -223,6 +224,7 @@ SingleTest CreateSingleTest(string directory) ProcessName = "2222.exe", CmdLine = "hi", StartTime = new DateTimeOffset(1, 1, 1, 0, 1, 0, TimeSpan.Zero), + EndTime = DateTimeOffset.MaxValue, IsNew = true, }; static readonly ProcessKey myCmdProcessKey2 = myCmdProcess2.ToProcessKey(); @@ -266,6 +268,7 @@ SingleTest CreateSingleTest(string directory) new DumpCPUMethod.MatchData { CPUMs = 15000, + ProcessPriority = 8.0f, WaitMs = 900, ReadyMs = 40, Method = "Wait900MsMethod_15000msCPU", @@ -277,6 +280,7 @@ SingleTest CreateSingleTest(string directory) new DumpCPUMethod.MatchData { CPUMs = 1000, + ProcessPriority= 8.0f, WaitMs = 5000, ReadyMs = 100, Method = "Wait5000MsMethod_1000msCPU", @@ -855,6 +859,11 @@ List GetTestData() { proc1, 5000 }, { proc2, 6000 }, }, + new Dictionary + { + { (ETWProcessIndex) 0, 8.0f}, + { (ETWProcessIndex) 1, 6.0f}, + }, methodList, null, null, @@ -868,12 +877,13 @@ List GetTestData() [Fact] - public void TotalMode_Not_SetMeans_It_Is_Off_CPU_Summary() + public void TotalMode_Not_SetMeans_It_Is_Off_CPU_NoPriority_Summary() { using ExceptionalPrinter redirect = new(myWriter,true); using CultureSwitcher invariant = new(); DumpCPUMethod dumper = new(); + dumper.NoPriorityDetails = true; dumper.ShowTotal = null; List matches = new(); @@ -894,18 +904,46 @@ public void TotalMode_Not_SetMeans_It_Is_Off_CPU_Summary() Assert.Equal("\t 6,000 ms test2.exe(2000) ", lines[3]); } - [Fact] - public void TotalMode_Total_CPU_Summary() + public void TotalMode_Not_SetMeans_It_Is_Off_CPU_Summary() { using ExceptionalPrinter redirect = new(myWriter, true); using CultureSwitcher invariant = new(); DumpCPUMethod dumper = new(); - // prevent parsing random json files in test directory - dumper.FileOrDirectoryQueries = new List { "dummy" }; + dumper.ShowTotal = null; + + List matches = new(); + + List files = GetTestData(); + + foreach (var file in files) + { + dumper.AddAndPrintTotalStats(matches, file); + } + + redirect.Flush(); + var lines = redirect.GetSingleLines(); + Assert.Equal(4, lines.Count); + Assert.Equal("\t CPU ms Priority Process Name ", lines[0]); + Assert.Equal("1/1/2000 12:00:00 AM ", lines[1]); + Assert.Equal("\t 5,000 ms 8.0 test1.exe(1024) ", lines[2]); + Assert.Equal("\t 6,000 ms 6.0 test2.exe(2000) ", lines[3]); + } - dumper.ShowTotal = TotalModes.Total; + + [Fact] + public void TotalMode_Total_CPU_Summary() + { + using ExceptionalPrinter redirect = new(myWriter, true); + using CultureSwitcher invariant = new(); + + DumpCPUMethod dumper = new() + { + // prevent parsing random json files in test directory + FileOrDirectoryQueries = new List { "dummy" }, + ShowTotal = TotalModes.Total, + }; List matches = new(); @@ -926,15 +964,18 @@ public void TotalMode_Total_CPU_Summary() [Fact] - public void TotalMode_Process_CPU_Summary() + public void TotalMode_Process_CPU_NoPriority_Summary() { using ExceptionalPrinter redirect = new(myWriter, true); using CultureSwitcher invariant = new(); - DumpCPUMethod dumper = new(); - // prevent parsing random json files in test directory - dumper.FileOrDirectoryQueries = new List { "dummy" }; - dumper.ShowTotal = TotalModes.Process; + DumpCPUMethod dumper = new() + { + // prevent parsing random json files in test directory + FileOrDirectoryQueries = new List { "dummy" }, + ShowTotal = TotalModes.Process, + NoPriorityDetails=true, + }; List matches = new(); @@ -955,6 +996,39 @@ public void TotalMode_Process_CPU_Summary() Assert.Equal("\t 6,000 ms test2.exe(2000) ", lines[3]); } + [Fact] + public void TotalMode_Process_CPU_Summary() + { + using ExceptionalPrinter redirect = new(myWriter, true); + using CultureSwitcher invariant = new(); + + DumpCPUMethod dumper = new() + { + // prevent parsing random json files in test directory + FileOrDirectoryQueries = new List { "dummy" }, + ShowTotal = TotalModes.Process, + }; + + + List matches = new(); + + List files = GetTestData(); + + foreach (var file in files) + { + dumper.AddAndPrintTotalStats(matches, file); + } + + redirect.Flush(); + var lines = redirect.GetSingleLines(); + + Assert.Equal(4, lines.Count); + Assert.Equal("\t CPU ms Priority Process Name ", lines[0]); + Assert.Equal("1/1/2000 12:00:00 AM CPU 11,000 ms ", lines[1]); + Assert.Equal("\t 5,000 ms 8.0 test1.exe(1024) ", lines[2]); + Assert.Equal("\t 6,000 ms 6.0 test2.exe(2000) ", lines[3]); + } + [Fact] public void TotalMode_NotSet_None_CPU_MethodLevel() { @@ -978,7 +1052,7 @@ public void TotalMode_NotSet_None_CPU_MethodLevel() Assert.Equal(14, lines.Count); - Assert.Equal(" CPU ms Wait msMethod", lines[0]); + Assert.Equal(" CPU ms Wait ms Method", lines[0]); Assert.Equal("1/1/0500 12:00:00 AM File3 ", lines[1]); Assert.Equal(" 2222.exe(2222) + hi", lines[2]); Assert.Equal(" 1 ms 1 ms Wait1MsMethod_1msCPU ", lines[3]); @@ -1036,7 +1110,7 @@ public void TotalMode_Method_CPU_MethodLevel() Assert.Equal(15, lines.Count); - Assert.Equal(" CPU ms Wait msMethod" ,lines[0]); + Assert.Equal(" CPU ms Wait ms Method" ,lines[0]); Assert.Equal("1/1/0500 12:00:00 AM CPU 2 ms Wait 2 ms Total 4 ms File3 ", lines[1]); Assert.Equal(" CPU 1 ms Wait: 1 ms Total: 2 ms 2222.exe(2222) + hi" , lines[2]); Assert.Equal(" 1 ms 1 ms Wait1MsMethod_1msCPU " , lines[3]); @@ -1081,6 +1155,7 @@ public void CPU_ProcessTotalMode_Uses_ProcessSortOrder() DumpCPUMethod dumper = new() { + NoPriorityDetails =true, FileOrDirectoryQueries = new List { "dummy" }, ProcessFormatOption = DumpBase.TimeFormats.s, SortOrder = SortOrders.StartTime, @@ -1114,6 +1189,33 @@ public void CPU_ProcessTotalMode_Default_SortsByCPU() }; + Assert.True(dumper.IsProcessTotalMode); + + var matches = CreateTestData(); + dumper.PrintMatches(matches); + + redirect.Flush(); + var lines = redirect.GetSingleLines(); + + Assert.Equal(3, lines.Count); + Assert.Equal("\t CPU ms Priority Process Name ", lines[0]); + Assert.Equal("\t 16,001 ms 8.0 2222.exe(2222) +60.000 hi ", lines[2]); + } + + [Fact] + public void CPU_ProcessTotalMode_NoPriority_SortsByCPU() + { + using ExceptionalPrinter redirect = new(myWriter, true); + using CultureSwitcher invariant = new(); + + DumpCPUMethod dumper = new() + { + NoPriorityDetails = true, + FileOrDirectoryQueries = new List { "dummy" }, + ProcessFormatOption = DumpBase.TimeFormats.s, + }; + + Assert.True(dumper.IsProcessTotalMode); var matches = CreateTestData(); @@ -1158,7 +1260,7 @@ public void Process_Summary_CanPrint_ByProcessStartTime() { { myCmdProcess, 7 }, { myCmdProcess2, 16001 }, - }, null, null, null, null), + }, new Dictionary(), null, null, null, null), }; @@ -1202,7 +1304,7 @@ public void Process_Summary_Default_SortByCPU() { { myCmdProcess, 7 }, { myCmdProcess2, 16001 }, - }, null, null, null, null), + }, null, null, null, null, null), }; diff --git a/ETWAnalyzer_uTest/Extract/TimelineExtractorTests.cs b/ETWAnalyzer_uTest/Extract/TimelineExtractorTests.cs index b2a7e212..bf31ece1 100644 --- a/ETWAnalyzer_uTest/Extract/TimelineExtractorTests.cs +++ b/ETWAnalyzer_uTest/Extract/TimelineExtractorTests.cs @@ -112,7 +112,7 @@ public void Can_Serialize_Deserialize_Timeline() ProcessKey key = new("tester.exe", 100, DateTimeOffset.MinValue); - extract.CPU = new CPUStats(null, null, GetSampleData(key),null, null); + extract.CPU = new CPUStats(null, null, null, GetSampleData(key),null, null); MemoryStream stream = new(); ExtractSerializer.Serialize(stream, extract); diff --git a/ETWAnalyzer_uTest/GlobalSuppressions.cs b/ETWAnalyzer_uTest/GlobalSuppressions.cs index 4e44797c..8b400471 100644 --- a/ETWAnalyzer_uTest/GlobalSuppressions.cs +++ b/ETWAnalyzer_uTest/GlobalSuppressions.cs @@ -6,3 +6,4 @@ using System.Diagnostics.CodeAnalysis; [assembly: SuppressMessage("Usage", "xUnit1013:Public method should be marked as test", Justification = "", Scope = "member", Target = "~M:ETWAnalyzer_uTest.ExceptionOccurrenceAnalyzerTests.Can_Update_ArisenExceptionHistoryFile_For_TestRuns_Of_Two_TestTypes")] +[assembly: SuppressMessage("Interoperability", "CA1416:Plattformkompatibilität überprüfen", Justification = "", Scope = "member", Target = "~M:ETWAnalyzer_uTest.TestInfrastructure.TestContext.IsAdministrator~System.Boolean")]