diff --git a/src/PerfView/PerfViewData.cs b/src/PerfView/PerfViewData.cs index 4aed50cdd..94aff55e6 100644 --- a/src/PerfView/PerfViewData.cs +++ b/src/PerfView/PerfViewData.cs @@ -9479,6 +9479,7 @@ public partial class EventPipePerfViewData : PerfViewFile public override bool SupportsProcesses => m_supportsProcesses; private bool m_supportsProcesses; + private bool m_hasUniversal; public override List GetProcesses(TextWriter log) { @@ -9532,6 +9533,7 @@ protected override Action OpenImpl(Window parentWindow, StatusBar worker bool hasExceptions = false; bool hasUniversalSystem = false; bool hasUniversalCPU = false; + bool hasUniversalCSwitch = false; if (m_traceLog != null) { foreach (TraceEventCounts eventStats in m_traceLog.Stats) @@ -9591,6 +9593,7 @@ protected override Action OpenImpl(Window parentWindow, StatusBar worker } else if (eventStats.ProviderGuid == UniversalSystemTraceEventParser.ProviderGuid) { + m_hasUniversal = true; hasUniversalSystem = true; m_supportsProcesses = true; } @@ -9599,6 +9602,11 @@ protected override Action OpenImpl(Window parentWindow, StatusBar worker hasUniversalCPU = true; m_supportsProcesses = true; } + else if (eventStats.ProviderGuid == UniversalEventsTraceEventParser.ProviderGuid && eventStats.EventName.StartsWith("cswitch")) + { + hasUniversalCSwitch = true; + m_supportsProcesses = true; + } } } @@ -9616,6 +9624,11 @@ protected override Action OpenImpl(Window parentWindow, StatusBar worker { m_Children.Add(new PerfViewStackSource(this, "CPU")); } + + if (hasUniversalCSwitch) + { + m_Children.Add(new PerfViewStackSource(this, "Thread Time")); + } } else // dotnet-trace { @@ -9908,6 +9921,11 @@ protected internal override StackSource OpenStackSourceImpl(string streamName, T return stackSource; } + case "Thread Time": + { + var eventLog = GetTraceLog(log); + return eventLog.ThreadTimeStacks(); + } default: { var eventLog = GetTraceLog(log); @@ -10103,7 +10121,7 @@ protected internal override void ConfigureStackWindow(string stackSourceName, St stackWindow.ExcludeRegExTextBox.Text = excludePat; } - if (stackSourceName.Contains("Thread Time")) + if (!m_hasUniversal && stackSourceName.Contains("Thread Time")) { stackWindow.ScalingPolicy = ScalingPolicyKind.TimeMetric; stackWindow.FoldRegExTextBox.Text += ";UNMANAGED_CODE_TIME;CPU"; diff --git a/src/TraceEvent/Computers/ThreadTimeComputer.cs b/src/TraceEvent/Computers/ThreadTimeComputer.cs index 4050d0518..5515fe3cb 100644 --- a/src/TraceEvent/Computers/ThreadTimeComputer.cs +++ b/src/TraceEvent/Computers/ThreadTimeComputer.cs @@ -10,12 +10,14 @@ // using Microsoft.Diagnostics.Tracing.Parsers; using Microsoft.Diagnostics.Tracing.Parsers.Clr; using Microsoft.Diagnostics.Tracing.Parsers.Kernel; +using Microsoft.Diagnostics.Tracing.Parsers.Universal.Events; using Microsoft.Diagnostics.Tracing.Session; using Microsoft.Diagnostics.Tracing.Stacks; using System; using System.Collections.Generic; using System.Diagnostics; using System.Net; +using System.Threading; using Address = System.UInt64; namespace Microsoft.Diagnostics.Tracing @@ -38,11 +40,21 @@ public ThreadTimeStackComputer(TraceLog eventLog, SymbolReader symbolReader) m_symbolReader = symbolReader; m_threadState = new ThreadState[eventLog.Threads.Count]; + for (int i = 0; i < m_threadState.Length; i++) + { + m_threadState[i] = new ThreadState(); + } + m_IRPToThread = new Dictionary(32); // We assume to begin with that all processors are idle (it will fix itself shortly). m_numIdleProcs = eventLog.NumberOfProcessors; m_threadIDUsingProc = new int[m_numIdleProcs]; + m_threadIndexUsingProc = new ThreadIndex[m_numIdleProcs]; + for(int i=0; i< m_threadIndexUsingProc.Length; i++) + { + m_threadIndexUsingProc[i] = ThreadIndex.Invalid; + } m_lastPacketForProcess = new NetworkInfo[eventLog.Processes.Count]; for (int i = 0; i < m_lastPacketForProcess.Length; i++) @@ -51,6 +63,7 @@ public ThreadTimeStackComputer(TraceLog eventLog, SymbolReader symbolReader) } MiniumReadiedTimeMSec = 0.5F; // We tend to only care about this if we are being starved. + InitializeForUniversal(); } /// /// If set we compute thread time using Tasks @@ -114,6 +127,9 @@ public void GenerateThreadTimeStacks(MutableTraceEventStackSource outputStackSou TraceLogEventSource eventSource = traceEvents == null ? m_eventLog.Events.GetSource() : traceEvents.GetSource(); + + UniversalEventsTraceEventParser universalEventsParser = new UniversalEventsTraceEventParser(eventSource); + if (GroupByStartStopActivity) { UseTasks = true; @@ -170,6 +186,7 @@ public void GenerateThreadTimeStacks(MutableTraceEventStackSource outputStackSou if (!BlockedTimeOnly) { eventSource.Kernel.PerfInfoSample += OnSampledProfile; + universalEventsParser.cpu += OnUniversalCPUSample; // WE add these too, because they are reasonably common so they can add a level of detail. eventSource.Clr.GCAllocationTick += OnSampledProfile; @@ -315,6 +332,18 @@ public void GenerateThreadTimeStacks(MutableTraceEventStackSource outputStackSou { eventSource.Dynamic.All += delegate (TraceEvent data) { + // Ignore UniversalSystem. + if (data.ProviderGuid == UniversalSystemTraceEventParser.ProviderGuid) + { + return; + } + + // Ignore UniversalEvents. + if (data.ProviderGuid == UniversalEventsTraceEventParser.ProviderGuid) + { + return; + } + // TODO decide what the correct heuristic is. // Currently I only do this for things that might be an EventSoruce (uses the name->Guid hashing) // Most importantly, it excludes the high volume CLR providers. @@ -376,6 +405,7 @@ public void GenerateThreadTimeStacks(MutableTraceEventStackSource outputStackSou // Add my own callbacks. eventSource.Kernel.ThreadCSwitch += OnThreadCSwitch; + universalEventsParser.cswitch += OnUniversalCSwitch; eventSource.Kernel.AddCallbackForEvents(OnDiskIO); eventSource.Kernel.AddCallbackForEvents(OnDiskIOInit); eventSource.Kernel.ThreadStart += OnThreadStart; @@ -423,6 +453,27 @@ public void GenerateThreadTimeStacks(MutableTraceEventStackSource outputStackSou m_threadState = null; } + private void InitializeForUniversal() + { + if (m_eventLog.Stats.Contains(UniversalEventsTraceEventParser.ProviderGuid, "cswitch")) + { + // Set has cswitches, since we don't get thread start events, and the computer needs to know + // that there will be cswitch events. + m_traceHasCSwitches = true; + + // Initialize all threads to blocked. For Windows traces, this happens when a thread start event is encountered. + // For Linux, we don't get these events, so we must pre-initialize them. + + foreach (TraceThread thread in m_eventLog.Threads) + { + // Threads start off blocked. + Debug.Assert(m_threadState[(int)thread.ThreadIndex].ThreadUninitialized); + Debug.Assert(m_threadState[(int)thread.ThreadIndex].LastCPUStackRelativeMSec == 0); + m_threadState[(int)thread.ThreadIndex].LogBlockingStart(timeRelativeMSec: 0, processorNumber: 0, thread, this); + } + } + } + private void Clr_GCAllocationTick(GCAllocationTickTraceData obj) { throw new NotImplementedException(); @@ -648,6 +699,87 @@ private void OnSampledProfile(TraceEvent data) } } + private void OnUniversalCSwitch(SampleTraceData data) + { + // This event fires when a thread is switched back in. + // The timestamp is the time at which the thread was switched back in. + // The value is the amount of time that thread was switched out. + + TraceThread thread = data.Thread(); + if (thread == null) + { + Debug.WriteLine("Warning, no thread at " + data.TimeStampRelativeMSec.ToString("f3")); + return; + } + + // Get the blocking stack. + StackSourceCallStackIndex stackIndex = GetCallStack(data, thread); + + // If the thread wasn't previously marked as blocked, then mark it. + if (!m_threadState[(int)thread.ThreadIndex].ThreadBlocked) + { + double startTimeStampRelMsec = m_eventLog.QPCTimeToRelMSec(data.TimeStampQPC - (long)data.Value); + m_threadState[(int)thread.ThreadIndex].LogBlockingStart( + startTimeStampRelMsec, + data.ProcessorNumber, + thread, + this); + } + + // Mark that this thread is no longer blocked. + m_threadState[(int)thread.ThreadIndex].LogBlockingEnd( + data.TimeStampRelativeMSec, data.ProcessorNumber, stackIndex, thread, this); + + // Specify the CPU that is being used by this thread. + m_threadIndexUsingProc[data.ProcessorNumber] = thread.ThreadIndex; + } + + private void OnUniversalCPUSample(SampleTraceData data) + { + TraceThread thread = data.Thread(); + if (thread == null) + { + Debug.WriteLine("Warning, no thread at " + data.TimeStampRelativeMSec.ToString("f3")); + return; + } + + ThreadIndex oldThreadIndex = m_threadIndexUsingProc[data.ProcessorNumber]; + if (oldThreadIndex != ThreadIndex.Invalid && oldThreadIndex != thread.ThreadIndex) + { + // Mark the old thread as blocked. + if (m_threadState[(int)oldThreadIndex].ThreadRunning) + { + TraceThread oldThread = m_eventLog.Threads[oldThreadIndex]; + m_threadState[(int)oldThreadIndex].LogBlockingStart( + data.TimeStampRelativeMSec, + data.ProcessorNumber, + oldThread, + this); + } + + // Mark the new thread as unblocked. + if (m_threadState[(int)thread.ThreadIndex].ThreadBlocked) + { + m_threadState[(int)thread.ThreadIndex].LogBlockingEnd( + data.TimeStampRelativeMSec, + data.ProcessorNumber, + m_threadState[(int)thread.ThreadIndex].LastCPUCallStack, + thread, + this); + } + } + + StackSourceCallStackIndex stackIndex = GetCallStack(data, thread); + m_threadState[(int)thread.ThreadIndex].LogCPUStack( + data.TimeStampRelativeMSec, + stackIndex, + thread, + this, + isCPUSample: true); + + m_threadIndexUsingProc[data.ProcessorNumber] = thread.ThreadIndex; + } + // THis is for the TaskWaitEnd. We want to have a stack event if 'data' does not have one, we lose the fact that // ANYTHING happened on this thread. Thus we log the stack of the activity so that data does not need a stack. private void OnTaskUnblock(TraceEvent data) @@ -810,6 +942,12 @@ private Func GetTopFramesForActivityComp /// private struct ThreadState { + public ThreadState() + { + LastCPUCallStack = StackSourceCallStackIndex.Invalid; + ReadyThreadCallStack = CallStackIndex.Invalid; + } + public void LogCPUStack(double timeRelativeMSec, StackSourceCallStackIndex stackIndex, TraceThread thread, ThreadTimeStackComputer computer, bool isCPUSample) { // THere is a small amount of cleanup after logging thread death. We will ignore this. @@ -1045,7 +1183,7 @@ public void AddCPUSample(double timeRelativeMSec, TraceThread thread, ThreadTime public ushort ProcessorNumberWhereAwakened; internal double LastCPUStackRelativeMSec; - private StackSourceCallStackIndex LastCPUCallStack; + internal StackSourceCallStackIndex LastCPUCallStack; private double ReadyThreadRelativeMSec; private CallStackIndex ReadyThreadCallStack; @@ -1326,6 +1464,12 @@ private struct AspNetRequestInfo /// private int m_numIdleProcs; // Count of bits idle threads in m_threadIDUsingProc + /// + /// For universal traces, we need to keep track of the ThreadIndex because the context switch events only come in when a thread switches back in. + /// This allows us to keep track of what thread was using a processor when a different thread starts using a processor. + /// + private ThreadIndex[] m_threadIndexUsingProc; + private bool m_traceHasCSwitches; // Does the trace have CSwitches (decide what kind of view to create) private StackSourceSample m_sample; // Reusable scratch space diff --git a/src/TraceEvent/EventPipe/EventPipeMetadata.cs b/src/TraceEvent/EventPipe/EventPipeMetadata.cs index 9190950e2..b971d9bba 100644 --- a/src/TraceEvent/EventPipe/EventPipeMetadata.cs +++ b/src/TraceEvent/EventPipe/EventPipeMetadata.cs @@ -42,7 +42,7 @@ internal unsafe class EventPipeMetadata public static EventPipeMetadata ReadV5OrLower(ref SpanReader reader, int pointerSize, int processId, int fileFormatVersionNumber) { // Read in the header (The header does not include payload parameter information) - var metadata = new EventPipeMetadata(pointerSize, processId); + var metadata = new EventPipeMetadata(pointerSize, processId, EventPipeFieldLayoutVersion.FileFormatV5OrLess); metadata.ParseHeader(ref reader, fileFormatVersionNumber); // If the metadata contains no parameter metadata, don't attempt to read it. @@ -83,7 +83,7 @@ public static EventPipeMetadata ReadV5OrLower(ref SpanReader reader, int pointer /// public static EventPipeMetadata ReadV6OrGreater(ref SpanReader reader, int pointerSize) { - var metadata = new EventPipeMetadata(pointerSize); + var metadata = new EventPipeMetadata(pointerSize, EventPipeFieldLayoutVersion.FileFormatV6OrGreater); int metadataLength = reader.ReadUInt16(); long offset = reader.StreamOffset; SpanReader metadataReader = new SpanReader(reader.ReadBytes(metadataLength), offset); @@ -94,16 +94,18 @@ public static EventPipeMetadata ReadV6OrGreater(ref SpanReader reader, int point return metadata; } - private EventPipeMetadata(int pointerSize) - : this(pointerSize, -1) + private EventPipeMetadata(int pointerSize, EventPipeFieldLayoutVersion fieldLayoutVersion) + : this(pointerSize, -1, fieldLayoutVersion) { } /// /// 'processID' is the process ID for the whole stream or -1 is this is a V6+ stream that can support multiple processes. /// - private EventPipeMetadata(int pointerSize, int processId) + private EventPipeMetadata(int pointerSize, int processId, EventPipeFieldLayoutVersion fieldLayoutVersion) { + _fieldLayoutVersion = fieldLayoutVersion; + // Get the event record and fill in fields that we can without deserializing anything. _eventRecord = (TraceEventNativeMethods.EVENT_RECORD*)Marshal.AllocHGlobal(sizeof(TraceEventNativeMethods.EVENT_RECORD)); ClearMemory(_eventRecord, sizeof(TraceEventNativeMethods.EVENT_RECORD)); @@ -175,7 +177,12 @@ private void InitDefaultParameters() // ID. We'll need to refactor up the stack if we want to expose a bigger ID. _eventRecord->EventHeader.ThreadId = unchecked((int)eventData.ThreadId); _eventRecord->EventHeader.ProcessId = unchecked((int)eventData.ProcessId); - if (eventData.ThreadIndexOrId == eventData.CaptureThreadIndexOrId && eventData.CaptureProcNumber != -1) + + // Set the processor number for V6+ file formats. For V5 and below we only set it if the ThreadId == CaptureThreadId + // to ensure that we don't surface a thread ID as a processor ID. + if ((eventData.CaptureProcNumber != -1) && + ((_fieldLayoutVersion == EventPipeFieldLayoutVersion.FileFormatV5OrLess && eventData.ThreadIndexOrId == eventData.CaptureThreadIndexOrId) || + (_fieldLayoutVersion == EventPipeFieldLayoutVersion.FileFormatV6OrGreater))) { // Its not clear how the caller is supposed to distinguish between events that we know were on // processor 0 vs. lacking information about what processor number the thread is on and @@ -959,6 +966,7 @@ private void StripStartStopInEventName() } } + private EventPipeFieldLayoutVersion _fieldLayoutVersion; private TraceEventNativeMethods.EVENT_RECORD* _eventRecord; private TraceEventNativeMethods.EVENT_HEADER_EXTENDED_DATA_ITEM* _extendedDataBuffer; private Guid* _relatedActivityBuffer; diff --git a/src/TraceEvent/Parsers/UniversalSystemTraceEventParser.cs b/src/TraceEvent/Parsers/UniversalSystemTraceEventParser.cs index 4694b1a3e..f39c478ad 100644 --- a/src/TraceEvent/Parsers/UniversalSystemTraceEventParser.cs +++ b/src/TraceEvent/Parsers/UniversalSystemTraceEventParser.cs @@ -480,6 +480,10 @@ internal sealed class ELFProcessMappingSymbolMetadata : ProcessMappingSymbolMeta public string DebugLink { get; set; } [JsonPropertyName("build_id")] public string BuildId { get; set; } + [JsonPropertyName("p_vaddr")] + public ulong VirtualAddress { get; set; } + [JsonPropertyName("p_offset")] + public ulong FileOffset { get; set; } } internal enum ProcessMappingSymbolMetadataFileType diff --git a/src/TraceEvent/TraceEvent.Tests/Universal/UniversalTests.cs b/src/TraceEvent/TraceEvent.Tests/Universal/UniversalTests.cs index b964b5c63..fd6ab55c3 100644 --- a/src/TraceEvent/TraceEvent.Tests/Universal/UniversalTests.cs +++ b/src/TraceEvent/TraceEvent.Tests/Universal/UniversalTests.cs @@ -105,6 +105,9 @@ public void ELFProcessMappingMetadata_Empty() ELFProcessMappingSymbolMetadata peMetadata = (ELFProcessMappingSymbolMetadata)metadata; Assert.Null(peMetadata.DebugLink); Assert.Null(peMetadata.BuildId); + Assert.Equal((ulong)0, peMetadata.VirtualAddress); + Assert.Equal((ulong)0, peMetadata.FileOffset); + } } } \ No newline at end of file diff --git a/src/TraceEvent/TraceLog.cs b/src/TraceEvent/TraceLog.cs index fe3baaa2c..c1c550de3 100644 --- a/src/TraceEvent/TraceLog.cs +++ b/src/TraceEvent/TraceLog.cs @@ -4735,6 +4735,19 @@ public override string ToString() return sb.ToString(); } + internal bool Contains(Guid providerId, string eventNameSearchVal) + { + foreach (var counts in m_counts.Values) + { + if (counts.ProviderGuid == providerId && + counts.EventName.Contains(eventNameSearchVal)) + { + return true; + } + } + return false; + } + #region private /// /// Given an event 'data' look up the statistics for events that type. @@ -9126,7 +9139,7 @@ private unsafe R2RPerfMapSymbolModule OpenR2RPerfMapForModuleFile(SymbolReader s else { symReader.m_log.WriteLine("ERROR: The R2R perfmap does not match the loaded module. Actual Signature = " + symbolModule.Signature + " Requested Signature = " + moduleFile.R2RPerfMapSignature); - return null; + throw new Exception("ERROR: The R2R perfmap does not match the loaded module."); } } }