diff --git a/.ado.yml b/.ado.yml index fb6125e23..555879a26 100644 --- a/.ado.yml +++ b/.ado.yml @@ -50,4 +50,4 @@ jobs: name: Azure Pipelines steps: - - template: /.pipelines/perfcollect-job.yml \ No newline at end of file + - template: /.pipelines/perfcollect-job.yml diff --git a/src/Directory.Build.props b/src/Directory.Build.props index a0302cdd7..26894e6ec 100644 --- a/src/Directory.Build.props +++ b/src/Directory.Build.props @@ -1,5 +1,5 @@ - + False @@ -44,6 +44,7 @@ 1.38.0 1.11.4 0.3.1 + 0.2.510501 4.61.3 4.61.3 7.1.2 @@ -108,4 +109,4 @@ false - \ No newline at end of file + diff --git a/src/PerfView.TestUtilities/PerfView.TestUtilities.csproj b/src/PerfView.TestUtilities/PerfView.TestUtilities.csproj index 2d006b850..df2503d7c 100644 --- a/src/PerfView.TestUtilities/PerfView.TestUtilities.csproj +++ b/src/PerfView.TestUtilities/PerfView.TestUtilities.csproj @@ -2,7 +2,7 @@ - net462 + net462;net8.0 Unit test utility library. Copyright © Microsoft 2017 @@ -38,4 +38,4 @@ ..\MSFT.snk - \ No newline at end of file + diff --git a/src/TraceEvent/EventPipe/EventPipeEventSource.cs b/src/TraceEvent/EventPipe/EventPipeEventSource.cs index 0756e83f0..db5f9d40f 100644 --- a/src/TraceEvent/EventPipe/EventPipeEventSource.cs +++ b/src/TraceEvent/EventPipe/EventPipeEventSource.cs @@ -125,6 +125,12 @@ public DateTime QPCTimeToTimeStamp(long QPCTime) /// public int MinimumVersionCanRead => 0; + /// + /// Called after headers are deserialized. This is especially useful in a streaming scenario + /// because the headers are only read after Process() is called. + /// + internal Action HeadersDeserialized; + protected override void Dispose(bool disposing) { if (_deserializer != null) @@ -144,6 +150,7 @@ public override bool Process() Debug.Assert(_deserializer != null); } + HeadersDeserialized?.Invoke(); if (FileFormatVersionNumber >= 3) { diff --git a/src/TraceEvent/TraceEvent.Tests/Parsing/EventPipeParsing.cs b/src/TraceEvent/TraceEvent.Tests/Parsing/EventPipeParsing.cs index cc5ed8842..066c9476d 100644 --- a/src/TraceEvent/TraceEvent.Tests/Parsing/EventPipeParsing.cs +++ b/src/TraceEvent/TraceEvent.Tests/Parsing/EventPipeParsing.cs @@ -1,4 +1,5 @@ using FastSerialization; +using Microsoft.Diagnostics.NETCore.Client; using Microsoft.Diagnostics.Tracing; using Microsoft.Diagnostics.Tracing.Etlx; using Microsoft.Diagnostics.Tracing.EventPipe; @@ -7,11 +8,14 @@ using System; using System.Collections.Generic; using System.Diagnostics; +using System.Diagnostics.Tracing; using System.IO; using System.Linq; using System.Text; +using System.Threading.Tasks; using Xunit; using Xunit.Abstractions; +using static Microsoft.Diagnostics.Tracing.Etlx.TraceLog; namespace TraceEventTests { @@ -20,15 +24,54 @@ public class EventPipeParsing : EventPipeTestBase private class EventRecord { public int TotalCount; - public string FirstSeriazliedSample; + public string FirstSerializedSample; + } + + private class EventStatistics + { + public SortedDictionary Records = new SortedDictionary(StringComparer.Ordinal); + + public void Record(TraceEvent data) => Record(data.ProviderName + "/" + data.EventName, data); + + public void Record(string eventName, TraceEvent data) + { + if (Records.ContainsKey(eventName)) + { + Records[eventName].TotalCount++; + } + else + { + Records[eventName] = new EventRecord() + { + TotalCount = 1, + FirstSerializedSample = new String(data.ToString().Replace("\n", "\\n").Replace("\r", "\\r").Take(1000).ToArray()) + }; + } + } + + override + public string ToString() + { + StringBuilder sb = new StringBuilder(1024 * 1024); + foreach (var item in Records) + { + sb.AppendLine($"{item.Key}, {item.Value.TotalCount}, {item.Value.FirstSerializedSample}"); + } + + return sb.ToString(); + } } public EventPipeParsing(ITestOutputHelper output) : base(output) { } - - [Theory()] + +#if NETCOREAPP3_0_OR_GREATER + [Theory(Skip = "Snapshot difs due to increased float accuracy on newer .NET versions.")] +#else + [Theory] +#endif [MemberData(nameof(TestEventPipeFiles))] public void Basic(string eventPipeFileName) { @@ -38,30 +81,13 @@ public void Basic(string eventPipeFileName) string eventPipeFilePath = Path.Combine(UnZippedDataDir, eventPipeFileName); Output.WriteLine(string.Format("Processing the file {0}, Making ETLX and scanning.", Path.GetFullPath(eventPipeFilePath))); - - var eventStatistics = new SortedDictionary(StringComparer.Ordinal); + var eventStatistics = new EventStatistics(); using (var traceLog = new TraceLog(TraceLog.CreateFromEventPipeDataFile(eventPipeFilePath))) { var traceSource = traceLog.Events.GetSource(); - traceSource.AllEvents += delegate (TraceEvent data) - { - string eventName = data.ProviderName + "/" + data.EventName; - - if (eventStatistics.ContainsKey(eventName)) - { - eventStatistics[eventName].TotalCount++; - } - else - { - eventStatistics[eventName] = new EventRecord() - { - TotalCount = 1, - FirstSeriazliedSample = new String(data.ToString().Replace("\n", "\\n").Replace("\r", "\\r").Take(1000).ToArray()) - }; - } - }; + traceSource.AllEvents += eventStatistics.Record; // Process traceSource.Process(); @@ -79,7 +105,7 @@ public void Streaming(string eventPipeFileName) string eventPipeFilePath = Path.Combine(UnZippedDataDir, eventPipeFileName); Output.WriteLine(string.Format("Processing the file {0}", Path.GetFullPath(eventPipeFilePath))); - var eventStatistics = new SortedDictionary(StringComparer.Ordinal); + var eventStatistics = new EventStatistics(); long curStreamPosition = 0; using (MockStreamingOnlyStream s = new MockStreamingOnlyStream(new FileStream(eventPipeFilePath, FileMode.Open, FileAccess.Read, FileShare.Read))) @@ -95,7 +121,6 @@ public void Streaming(string eventPipeFileName) Assert.InRange(newStreamPosition, curStreamPosition, curStreamPosition + 103_000); curStreamPosition = newStreamPosition; - string eventName = data.ProviderName + "/" + data.EventName; // For whatever reason the parse filtering below produces a couple extra events @@ -108,18 +133,7 @@ public void Streaming(string eventPipeFileName) eventName == "Microsoft-Windows-DotNETRuntime/Method") return; - if (eventStatistics.ContainsKey(eventName)) - { - eventStatistics[eventName].TotalCount++; - } - else - { - eventStatistics[eventName] = new EventRecord() - { - TotalCount = 1, - FirstSeriazliedSample = new String(data.ToString().Replace("\n", "\\n").Replace("\r", "\\r").Take(1000).ToArray()) - }; - } + eventStatistics.Record(eventName, data); }; // this is somewhat arbitrary looking set of parser event callbacks empirically @@ -148,6 +162,61 @@ public void Streaming(string eventPipeFileName) ValidateEventStatistics(eventStatistics, eventPipeFileName); } +#if NETCOREAPP3_0_OR_GREATER + [Theory] +#else + [Theory(Skip = "EventPipeSession connection is only available to target apps on .NET Core 3.0 or later")] +#endif + [InlineData(true)] + [InlineData(false)] + public async Task SessionStreaming(bool initialRundown) + { + var client = new DiagnosticsClient(Process.GetCurrentProcess().Id); + var rundownConfig = initialRundown ? EventPipeRundownConfiguration.Enable(client) : EventPipeRundownConfiguration.None(); + var providers = new[] + { + new EventPipeProvider(SampleProfilerTraceEventParser.ProviderName, EventLevel.Informational), + }; + using (var session = client.StartEventPipeSession(providers, requestRundown: false)) + { + using (var traceSource = CreateFromEventPipeSession(session, rundownConfig)) + { + var sampleEventParser = new SampleProfilerTraceEventParser(traceSource); + + // Signal that we have received the first event. + var eventCallStackIndex = new TaskCompletionSource(); + sampleEventParser.ThreadSample += delegate (ClrThreadSampleTraceData e) + { + eventCallStackIndex.TrySetResult(e.CallStackIndex()); + }; + + // Process in the background (this is blocking). + var processingTask = Task.Run(traceSource.Process); + + // Verify the event can be symbolicated on the fly if (initialRundown == true). + var callStackIndex = await eventCallStackIndex.Task; + Assert.NotEqual(CallStackIndex.Invalid, callStackIndex); + var codeAddressIndex = traceSource.TraceLog.CallStacks.CodeAddressIndex(callStackIndex); + Assert.NotEqual(CodeAddressIndex.Invalid, codeAddressIndex); + var methodIndex = traceSource.TraceLog.CodeAddresses.MethodIndex(codeAddressIndex); + if (initialRundown) + { + Assert.NotEqual(MethodIndex.Invalid, methodIndex); + var method = traceSource.TraceLog.CodeAddresses.Methods[methodIndex]; + Assert.NotEmpty(method.FullMethodName); + } + else + { + Assert.Equal(MethodIndex.Invalid, methodIndex); + } + + // Stop after receiving the first event. + session.Stop(); + await processingTask; + } + } + } + [Fact] public void CanParseHeaderOfV1EventPipeFile() { @@ -248,7 +317,7 @@ public void V4EventPipeFileHasProcNumbers() // Process traceSource.Process(); - for(int i = 0; i < traceSource.NumberOfProcessors; i++) + for (int i = 0; i < traceSource.NumberOfProcessors; i++) { Assert.NotEqual(0, counts[i]); } @@ -463,7 +532,7 @@ public void WellKnownDiagnosticSourceEventsHavePayloads() // and ignore the empty parameter metadata provided in the stream, treating the events // as if the runtime had provided the correct parameter schema. // - // I am concurrently working on a runtime fix and updated file format revision which can + // I am concurrently working on a runtime fix and updated file format revision which can // correctly encode these parameter types. However for back-compat with older runtimes we // need this. @@ -570,15 +639,9 @@ private void Dynamic_All(TraceEvent obj) throw new NotImplementedException(); } - private void ValidateEventStatistics(SortedDictionary eventStatistics, string eventPipeFileName) + private void ValidateEventStatistics(EventStatistics eventStatistics, string eventPipeFileName) { - StringBuilder sb = new StringBuilder(1024 * 1024); - foreach (var item in eventStatistics) - { - sb.AppendLine($"{item.Key}, {item.Value.TotalCount}, {item.Value.FirstSeriazliedSample}"); - } - - string actual = sb.ToString(); + string actual = eventStatistics.ToString(); string baselineFile = Path.Combine(TestDataDir, eventPipeFileName + ".baseline.txt"); string expected = File.ReadAllText(baselineFile); @@ -603,7 +666,7 @@ public MockStreamingOnlyStream(Stream innerStream) { _innerStream = innerStream; } - public long TestOnlyPosition { get { return _innerStream.Position; } } + public long TestOnlyPosition { get { return _innerStream.Position; } } public override bool CanRead => true; public override bool CanSeek => false; @@ -662,7 +725,7 @@ public void Write(string arg) public void WriteArray(T[] elements, Action writeElement) { WriteArrayLength(elements.Length); - for(int i = 0; i < elements.Length; i++) + for (int i = 0; i < elements.Length; i++) { writeElement(elements[i]); } @@ -779,7 +842,7 @@ private static void Align(BinaryWriter writer, long previousBytesWritten) } } - public static void WriteBlock(BinaryWriter writer, string name, Action writeBlockData, + public static void WriteBlock(BinaryWriter writer, string name, Action writeBlockData, long previousBytesWritten = 0) { Debug.WriteLine($"Starting block {name} position: {writer.BaseStream.Position + previousBytesWritten}"); @@ -931,7 +994,7 @@ MemoryStream GetFirstChunk() EventPipeWriter.WriteNetTraceHeader(writer); EventPipeWriter.WriteFastSerializationHeader(writer); EventPipeWriter.WriteTraceObject(writer); - EventPipeWriter.WriteMetadataBlock(writer, + EventPipeWriter.WriteMetadataBlock(writer, new EventMetadata(1, "Provider", "Event", 1)); ms.Position = 0; return ms; @@ -950,16 +1013,16 @@ MemoryStream GetNextChunk() else { // 20 blocks, each with 20 events in them - for(int i = 0; i < 20; i++) + for (int i = 0; i < 20; i++) { - EventPipeWriter.WriteEventBlock(writer, + EventPipeWriter.WriteEventBlock(writer, w => { for (int j = 0; j < 20; j++) { EventPipeWriter.WriteEventBlob(w, 1, _sequenceNumber++, payloadSize, WriteEventPayload); } - }, + }, _bytesWritten); } } @@ -987,7 +1050,7 @@ public override void Flush() public override int Read(byte[] buffer, int offset, int count) { int ret = _currentChunk.Read(buffer, offset, count); - if(ret == 0) + if (ret == 0) { _currentChunk = GetNextChunk(); _bytesWritten += _currentChunk.Length; diff --git a/src/TraceEvent/TraceEvent.Tests/Parsing/GeneralParsing.cs b/src/TraceEvent/TraceEvent.Tests/Parsing/GeneralParsing.cs index 04fb3b342..aac12abcc 100644 --- a/src/TraceEvent/TraceEvent.Tests/Parsing/GeneralParsing.cs +++ b/src/TraceEvent/TraceEvent.Tests/Parsing/GeneralParsing.cs @@ -21,7 +21,11 @@ public GeneralParsing(ITestOutputHelper output) /// and scans them (so you should get asserts if there is parsing problem) /// and ensures that no more than .1% of the events are /// +#if NETCOREAPP3_0_OR_GREATER + [Theory(Skip = "Snapshot difs due to increased float accuracy on newer .NET versions.")] +#else [Theory] +#endif [MemberData(nameof(TestEtlFiles))] public void ETW_GeneralParsing_Basic(string etlFileName) { diff --git a/src/TraceEvent/TraceEvent.Tests/Parsing/MultiFileMergeAll.cs b/src/TraceEvent/TraceEvent.Tests/Parsing/MultiFileMergeAll.cs index 98c1dbf87..3cb1f7d45 100644 --- a/src/TraceEvent/TraceEvent.Tests/Parsing/MultiFileMergeAll.cs +++ b/src/TraceEvent/TraceEvent.Tests/Parsing/MultiFileMergeAll.cs @@ -21,7 +21,11 @@ public MultiFileMergeAll(ITestOutputHelper output) /// This test unzips a zip file containing 4 etls files, open them as 1 trace /// and asserts the correct TraceLog size and event count /// +#if NETCOREAPP3_0_OR_GREATER + [Fact(Skip = "Snapshot difs due to increased float accuracy on newer .NET versions.")] +#else [Fact] +#endif public void ETW_MultiFileMergeAll_Basic() { PrepareTestData(); @@ -32,66 +36,68 @@ public void ETW_MultiFileMergeAll_Basic() Output.WriteLine(string.Format("Processing the file {0}, Making ETLX and scanning.", etlFilePath)); string eltxFilePath = Path.ChangeExtension(etlFilePath, ".etlx"); - TraceEventDispatcher source = new ETWTraceEventSource(fileNames, TraceEventSourceType.MergeAll); - TraceLog traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(source, eltxFilePath)); + using (TraceEventDispatcher source = new ETWTraceEventSource(fileNames, TraceEventSourceType.MergeAll)) + using (TraceLog traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(source, eltxFilePath))) + { - Assert.Equal(95506, traceLog.EventCount); - var stopEvents = traceLog.Events.Filter(e => e.EventName == "Activity2Stop/Stop"); - Assert.Equal(55, stopEvents.Count()); - Assert.Equal((uint)13205, (uint)stopEvents.Last().EventIndex); + Assert.Equal(95506, traceLog.EventCount); + var stopEvents = traceLog.Events.Filter(e => e.EventName == "Activity2Stop/Stop"); + Assert.Equal(55, stopEvents.Count()); + Assert.Equal((uint)13205, (uint)stopEvents.Last().EventIndex); - using (var file = new StreamReader($"{TestDataDir}\\diaghub-dotnetcore3.1-win-x64-diagsession.baseline.txt")) - { - var traceSource = traceLog.Events.GetSource(); - traceSource.AllEvents += delegate (TraceEvent data) + using (var file = new StreamReader($"{TestDataDir}\\diaghub-dotnetcore3.1-win-x64-diagsession.baseline.txt")) { - string eventName = data.ProviderName + "/" + data.EventName; - - // We are going to skip dynamic events from the CLR provider. - // The issue is that this depends on exactly which manifest is present - // on the machine, and I just don't want to deal with the noise of - // failures because you have a slightly different one. - if (data.ProviderName == "DotNet") + var traceSource = traceLog.Events.GetSource(); + traceSource.AllEvents += delegate (TraceEvent data) { - return; - } + string eventName = data.ProviderName + "/" + data.EventName; - // We don't want to use the manifest for CLR Private events since - // different machines might have different manifests. - if (data.ProviderName == "Microsoft-Windows-DotNETRuntimePrivate") - { - if (data.GetType().Name == "DynamicTraceEventData" || data.EventName.StartsWith("EventID")) + // We are going to skip dynamic events from the CLR provider. + // The issue is that this depends on exactly which manifest is present + // on the machine, and I just don't want to deal with the noise of + // failures because you have a slightly different one. + if (data.ProviderName == "DotNet") { return; } - } - // Same problem with classic OS events. We don't want to rely on the OS to parse since this could vary between baseline and test. - else if (data.ProviderName == "MSNT_SystemTrace") - { - // However we to allow a couple of 'known good' ones through so we test some aspects of the OS parsing logic in TraceEvent. - if (data.EventName != "SystemConfig/Platform" && data.EventName != "Image/KernelBase") + + // We don't want to use the manifest for CLR Private events since + // different machines might have different manifests. + if (data.ProviderName == "Microsoft-Windows-DotNETRuntimePrivate") { - return; + if (data.GetType().Name == "DynamicTraceEventData" || data.EventName.StartsWith("EventID")) + { + return; + } } - } - // In theory we have the same problem with any event that the OS supplies the parsing. I dont want to be too aggressive about - // turning them off, however becasuse I want those code paths tested + // Same problem with classic OS events. We don't want to rely on the OS to parse since this could vary between baseline and test. + else if (data.ProviderName == "MSNT_SystemTrace") + { + // However we to allow a couple of 'known good' ones through so we test some aspects of the OS parsing logic in TraceEvent. + if (data.EventName != "SystemConfig/Platform" && data.EventName != "Image/KernelBase") + { + return; + } + } + // In theory we have the same problem with any event that the OS supplies the parsing. I dont want to be too aggressive about + // turning them off, however becasuse I want those code paths tested - // TODO FIX NOW, this is broken and should be fixed. - // We are hacking it here so we don't turn off the test completely. - if (eventName == "DotNet/CLR.SKUOrVersion") - { - return; - } + // TODO FIX NOW, this is broken and should be fixed. + // We are hacking it here so we don't turn off the test completely. + if (eventName == "DotNet/CLR.SKUOrVersion") + { + return; + } - var evt = GeneralParsing.Parse(data); + var evt = GeneralParsing.Parse(data); - var line = file.ReadLine(); - Assert.Equal(evt, line); - }; + var line = file.ReadLine(); + Assert.Equal(evt, line); + }; - traceSource.Process(); + traceSource.Process(); + } } } } diff --git a/src/TraceEvent/TraceEvent.Tests/Speedscope/SpeedScopeExporterTests.cs b/src/TraceEvent/TraceEvent.Tests/Speedscope/SpeedScopeExporterTests.cs index dc653122a..3402f08bd 100644 --- a/src/TraceEvent/TraceEvent.Tests/Speedscope/SpeedScopeExporterTests.cs +++ b/src/TraceEvent/TraceEvent.Tests/Speedscope/SpeedScopeExporterTests.cs @@ -12,6 +12,13 @@ using static Microsoft.Diagnostics.Tracing.Stacks.StackSourceWriterHelper; +// For Debug.Listeners +#if NETCOREAPP3_0_OR_GREATER +using Trace = System.Diagnostics.Trace; +#else +using Trace = System.Diagnostics.Debug; +#endif + namespace TraceEventTests { public class SpeedScopeStackSourceWriterTests @@ -336,9 +343,9 @@ public void ValidationAllowsForCompleteResults() [InlineData("only_managed_samples.nettrace.zip")] public void CanConvertProvidedTraceFiles(string zippedTraceFileName) { - var debugListenersCopy = new TraceListener[Debug.Listeners.Count]; - Debug.Listeners.CopyTo(debugListenersCopy, index: 0); - Debug.Listeners.Clear(); + var debugListenersCopy = new TraceListener[Trace.Listeners.Count]; + Trace.Listeners.CopyTo(debugListenersCopy, index: 0); + Trace.Listeners.Clear(); string fileToUnzip = Path.Combine("inputs", "speedscope", zippedTraceFileName); string unzippedFile = Path.ChangeExtension(fileToUnzip, string.Empty); @@ -397,7 +404,7 @@ public void CanConvertProvidedTraceFiles(string zippedTraceFileName) } if (debugListenersCopy.Length > 0) { - Debug.Listeners.AddRange(debugListenersCopy); + Trace.Listeners.AddRange(debugListenersCopy); } } } diff --git a/src/TraceEvent/TraceEvent.Tests/TraceEvent.Tests.csproj b/src/TraceEvent/TraceEvent.Tests/TraceEvent.Tests.csproj index bde36b6d6..009f9c1d2 100644 --- a/src/TraceEvent/TraceEvent.Tests/TraceEvent.Tests.csproj +++ b/src/TraceEvent/TraceEvent.Tests/TraceEvent.Tests.csproj @@ -2,7 +2,7 @@ - net462 + net462;net8.0 TraceEventTests TraceEventTests Unit tests for TraceEvent. @@ -16,6 +16,7 @@ + @@ -52,7 +53,7 @@ - + diff --git a/src/TraceEvent/TraceEvent.csproj b/src/TraceEvent/TraceEvent.csproj index 7003f4598..1c9637326 100644 --- a/src/TraceEvent/TraceEvent.csproj +++ b/src/TraceEvent/TraceEvent.csproj @@ -1,5 +1,5 @@  - + netstandard2.0 @@ -41,6 +41,7 @@ $(NuspecProperties);SystemReflectionMetadataVersion=$(SystemReflectionMetadataVersion) $(NuspecProperties);SystemReflectionTypeExtensionsVersion=$(SystemReflectionTypeExtensionsVersion) $(NuspecProperties);SystemRuntimeCompilerServicesUnsafeVersion=$(SystemRuntimeCompilerServicesUnsafeVersion) + $(NuspecProperties);MicrosoftDiagnosticsNETCoreClientVersion=$(MicrosoftDiagnosticsNETCoreClientVersion) @@ -57,6 +58,7 @@ + diff --git a/src/TraceEvent/TraceLog.cs b/src/TraceEvent/TraceLog.cs index fdfc35ef0..01d8ff3ca 100644 --- a/src/TraceEvent/TraceLog.cs +++ b/src/TraceEvent/TraceLog.cs @@ -5,8 +5,8 @@ // #define DEBUG_SERIALIZE using FastSerialization; +using Microsoft.Diagnostics.NETCore.Client; using Microsoft.Diagnostics.Symbols; -using Microsoft.Diagnostics.Tracing.Compatibility; using Microsoft.Diagnostics.Tracing.EventPipe; using Microsoft.Diagnostics.Tracing.Parsers; using Microsoft.Diagnostics.Tracing.Parsers.AspNet; @@ -154,10 +154,203 @@ public static TraceLog OpenOrConvert(string etlOrEtlxFilePath, TraceLogOptions o /// public static TraceLogEventSource CreateFromTraceEventSession(TraceEventSession session) { - var traceLog = new TraceLog(session); + var traceLog = new TraceLog(session.Source); + traceLog.pointerSize = ETWTraceEventSource.GetOSPointerSize(); + + traceLog.realTimeQueue = new Queue(); + traceLog.realTimeFlushTimer = new Timer(_ => traceLog.FlushRealTimeEvents(1000), null, 1000, 1000); + traceLog.rawEventSourceToConvert.AllEvents += traceLog.onAllEventsRealTime; + + // See if we are on Win7 and have a separate kernel session associated with 'session' + if (session.m_kernelSession != null) + { + // Make sure both sources only dispatch one at a time by taking a lock during dispatch. + session.m_kernelSession.Source.lockObj = traceLog.realTimeQueue; + session.m_associatedWithTraceLog = true; // Indicate that it is OK to have the m_kernelSession. + session.Source.lockObj = traceLog.realTimeQueue; + + // Set up the callbacks to the kernel session. + traceLog.rawKernelEventSource = session.m_kernelSession.Source; + traceLog.SetupCallbacks(traceLog.rawKernelEventSource); + traceLog.rawKernelEventSource.unhandledEventTemplate.traceEventSource = traceLog; // Make everything point to the log as its source. + traceLog.rawKernelEventSource.AllEvents += traceLog.onAllEventsRealTime; + } + + return traceLog.realTimeSource; + } + + /// + /// From a EventPipeSession, create a real time TraceLog Event Source. Like an EventPipeEventSource a TraceLogEventSource + /// will deliver events in real time. However an TraceLogEventSource has an underlying Tracelog (which you can access with + /// the .Log Property) which lets you get at aggregated information (Processes, threads, images loaded, and perhaps most + /// importantly TraceEvent.CallStack() will work. Thus you can get real time stacks from events). + /// + /// + /// If enabled, a rundown is triggered immediately as a separate session. + /// This is used to initialize module and method information and then the session is closed. + /// This only makes sense in realtime sessions when you need to resolve function names during the session. + /// + /// + /// var client = new DiagnosticsClient(Process.GetCurrentProcess().Id); + /// EventPipeProvider[] providers = new[] + /// { new EventPipeProvider(ClrTraceEventParser.ProviderName, EventLevel.Informational, (long) ClrTraceEventParser.Keywords.Default), + /// new EventPipeProvider(SampleProfilerTraceEventParser.ProviderName, EventLevel.Informational), + /// }; + /// var session = client.StartEventPipeSession(providers, requestRundown: false); + /// var eventSource = TraceLog.CreateFromEventPipeSession(session, TraceLog.EventPipeRundownConfiguration.Enable(client)); + /// eventSource.Process(); + /// + public static TraceLogEventSource CreateFromEventPipeSession(EventPipeSession session, EventPipeRundownConfiguration rundownConfiguration = null) + { + var traceLog = new TraceLog(new EventPipeEventSource(session.EventStream)); + traceLog.rawEventSourceToConvert.AllEvents += traceLog.OnAllEventPipeEventsRealTime; + + var rundownDiagnosticsClient = rundownConfiguration?.m_client; + if (rundownDiagnosticsClient != null) + { + // Rundown events only come in after the session is stopped but we need them right from the start so that we + // can recognize loaded moodules and methods. Therefore, we start an additional session which will only collect + // rundown events and shut down immediately and feed this as an additional session to the TraceLog. + // Note: it doesn't matter what the actual provider is, just that we request rundown in the constructor. + using (var rundownSession = rundownDiagnosticsClient.StartEventPipeSession( + new EventPipeProvider(ClrTraceEventParser.ProviderName, EventLevel.Informational, (long)ClrTraceEventParser.Keywords.Default), + requestRundown: true + )) + { + traceLog.ProcessInitialRundown(rundownSession); + } + } + return traceLog.realTimeSource; } + /// + /// EventPipe real-time tracelog session configuration, used to populate the method and module information. + /// + public class EventPipeRundownConfiguration + { + internal readonly DiagnosticsClient m_client; + + private EventPipeRundownConfiguration(DiagnosticsClient client) { m_client = client; } + + /// + /// No rundown will be requested, thus it may be impossible to symbolicate events. This is OK, if you don't + /// require method/module info the captured events. + /// + public static EventPipeRundownConfiguration None() + { + return new EventPipeRundownConfiguration(null); + } + + /// + /// If the rundown is enabled and a DiagnosticsClient is given, TraceLog.CreateFromEventPipeSession will + /// create an additional short-lived diagnostics session to load all module/method information up to that + /// point. + /// + public static EventPipeRundownConfiguration Enable(DiagnosticsClient client) + { + return new EventPipeRundownConfiguration(client); + } + } + + private void ProcessInitialRundown(EventPipeSession session) + { + using (var source = new EventPipeEventSource(session.EventStream)) + { + SetupInitialRundownCallbacks(source); + + // Only stopping the session will cause the rundown events to be sent. + // However, we cannot stop it before starting to process the source. + // Therefore, we need attach to the first event and only then stop the session. + var completionSource = new TaskCompletionSource(); + source.AllEvents += delegate (TraceEvent _) + { + completionSource.TrySetResult(true); + }; + var task = Task.Run(source.Process); + completionSource.Task.Wait(); + session.Stop(); + task.Wait(); + } + } + + /// + /// Attaches callbacks to initialize modules and methods based on the rundown events. + /// Unlike SetupCallbacks(), these callbacks are attached before any events are processed so + /// they do not rely on ForAllUnresolvedCodeAddressesInRange() and instead record all the methods. + /// + private void SetupInitialRundownCallbacks(EventPipeEventSource rawEvents) + { + rawEvents.HeadersDeserialized += delegate () { CopyHeadersFrom(rawEvents); }; + + var clrRundownParser = new ClrRundownTraceEventParser(rawEvents); + Action onLoaderRundown = delegate (ModuleLoadUnloadTraceData data) + { + TraceProcess process = processes.GetOrCreateProcess(data.ProcessID, data.TimeStampQPC); + process.LoadedModules.ManagedModuleLoadOrUnload(data, false, true); + }; + + clrRundownParser.LoaderModuleDCStop += onLoaderRundown; + clrRundownParser.LoaderModuleDCStart += onLoaderRundown; + + clrRundownParser.MethodILToNativeMapDCStop += delegate (MethodILToNativeMapTraceData data) + { + codeAddresses.AddILMapping(data); + }; + + clrRundownParser.MethodDCStopVerbose += delegate (MethodLoadUnloadVerboseTraceData data) + { + // Note: we need this also for non-jitted methods, otherwise we won't resolve some frames, for example: + // "System.Private.CoreLib.il" - "System.Threading.Tasks.Task.Wait()" + TraceProcess process = processes.GetOrCreateProcess(data.ProcessID, data.TimeStampQPC); + process.InsertJITTEDMethod(data.MethodStartAddress, data.MethodSize, delegate () + { + TraceManagedModule module = process.LoadedModules.GetOrCreateManagedModule(data.ModuleID, data.TimeStampQPC); + MethodIndex methodIndex = CodeAddresses.Methods.NewMethod(GetFullName(data), module.ModuleFile.ModuleFileIndex, data.MethodToken); + return new TraceProcess.MethodLookupInfo(data.MethodStartAddress, data.MethodSize, methodIndex); + }); + }; + } + + private unsafe void OnAllEventPipeEventsRealTime(TraceEvent data) + { + TraceEventCounts countForEvent = Stats.GetEventCounts(data); + // Debug.Assert((int)data.EventIndex == eventCount); + countForEvent.m_count++; + countForEvent.m_eventDataLenTotal += data.EventDataLength; + + // Remember past events so we can hook up stacks to them. + data.eventIndex = (EventIndex)eventCount; + pastEventInfo.LogEvent(data, data.eventIndex, countForEvent); + + // currentID is used by the dispatcher to define the EventIndex. Make sure at both sources have the + // same notion of what that is if we have two dispatcher. + if (rawEventSourceToConvert != null) + { + rawEventSourceToConvert.currentID = (EventIndex)eventCount; + } + + var extendedDataCount = data.eventRecord->ExtendedDataCount; + if (extendedDataCount != 0) + { + bookKeepingEvent |= ProcessExtendedData(data, extendedDataCount, countForEvent); + } + + // This must occur after the call to ProcessExtendedData to ensure that if there is a stack for this event, + // that it has been associated before the event count is incremented. Otherwise, the stack will be associated with + // the next event, and not the current event. + eventCount++; + + // We need to look up the event to get the dispatch Target assigned. + TraceEvent rtEvent = realTimeSource.Lookup(data.eventRecord); + realTimeSource.Dispatch(rtEvent); + + // Clean up interim data structures - they're not necessary after the event has been processed (Dispatched). + eventsToStacks.Clear(); + eventsToCodeAddresses.Clear(); + cswitchBlockingEventsToStacks.Clear(); + } + /// /// Creates a ETLX file an Lttng Text file 'filePath'. /// @@ -544,88 +737,66 @@ private TraceLog() /// Functionality of TraceLog that does not depend on either remembering past EVENTS or require future /// knowledge (e.g. stacks of kernel events), will 'just work'. /// - private unsafe TraceLog(TraceEventSession session) + private unsafe TraceLog(TraceEventDispatcher source) : this() { IsRealTime = true; machineName = Environment.MachineName; realTimeSource = new TraceLogEventSource(events, ownsItsTraceLog: true); // Dispose - realTimeQueue = new Queue(); - realTimeFlushTimer = new Timer(FlushRealTimeEvents, null, 1000, 1000); - pointerSize = ETWTraceEventSource.GetOSPointerSize(); - //double lastTime = 0; + // Set up callbacks - we use the session's source for our input. + rawEventSourceToConvert = source; + SetupCallbacks(rawEventSourceToConvert); + rawEventSourceToConvert.unhandledEventTemplate.traceEventSource = this; // Make everything point to the log as its source. + } - // Set up callbacks that handle stack processing - Action onAllEvents = delegate (TraceEvent data) + private unsafe void onAllEventsRealTime(TraceEvent data) + { + // we need to guard our data structures from concurrent access. TraceLog data + // is modified by this code as well as code in FlushRealTimeEvents. + lock (realTimeQueue) { - // we need to guard our data structures from concurrent access. TraceLog data - // is modified by this code as well as code in FlushRealTimeEvents. - lock (realTimeQueue) - { - // we delay things so we have a chance to match up stacks. - - // if (!removeFromStream && data.Opcode != TraceEventOpcode.DataCollectionStart && data.ProcessID != 0 && data.ProviderGuid != ClrRundownTraceEventParser.ProviderGuid) - // Trace.WriteLine("REAL TIME QUEUE: " + data.ToString()); - TraceEventCounts countForEvent = Stats.GetEventCounts(data); - Debug.Assert((int)data.EventIndex == eventCount); - countForEvent.m_count++; - countForEvent.m_eventDataLenTotal += data.EventDataLength; - - // Remember past events so we can hook up stacks to them. - data.eventIndex = (EventIndex)eventCount; - pastEventInfo.LogEvent(data, data.eventIndex, countForEvent); + // we delay things so we have a chance to match up stacks. - // currentID is used by the dispatcher to define the EventIndex. Make sure at both sources have the - // same notion of what that is if we have two dispatcher. - if (rawKernelEventSource != null) - { - rawEventSourceToConvert.currentID = (EventIndex)eventCount; - rawKernelEventSource.currentID = (EventIndex)eventCount; - } + // if (!removeFromStream && data.Opcode != TraceEventOpcode.DataCollectionStart && data.ProcessID != 0 && data.ProviderGuid != ClrRundownTraceEventParser.ProviderGuid) + // Trace.WriteLine("REAL TIME QUEUE: " + data.ToString()); + TraceEventCounts countForEvent = Stats.GetEventCounts(data); + Debug.Assert((int)data.EventIndex == eventCount); + countForEvent.m_count++; + countForEvent.m_eventDataLenTotal += data.EventDataLength; - // Skip samples from the idle thread. - if (data.ProcessID == 0 && data is SampledProfileTraceData) - { - return; - } + // Remember past events so we can hook up stacks to them. + data.eventIndex = (EventIndex)eventCount; + pastEventInfo.LogEvent(data, data.eventIndex, countForEvent); - var extendedDataCount = data.eventRecord->ExtendedDataCount; - if (extendedDataCount != 0) - { - bookKeepingEvent |= ProcessExtendedData(data, extendedDataCount, countForEvent); - } + // currentID is used by the dispatcher to define the EventIndex. Make sure at both sources have the + // same notion of what that is if we have two dispatcher. + if (rawKernelEventSource != null) + { + rawEventSourceToConvert.currentID = (EventIndex)eventCount; + rawKernelEventSource.currentID = (EventIndex)eventCount; + } - // This must occur after the call to ProcessExtendedData to ensure that if there is a stack for this event, - // that it has been associated before the event count is incremented. Otherwise, the stack will be associated with - // the next event, and not the current event. - eventCount++; + // Skip samples from the idle thread. + if (data.ProcessID == 0 && data is SampledProfileTraceData) + { + return; + } - realTimeQueue.Enqueue(new QueueEntry(data.Clone(), Environment.TickCount)); + var extendedDataCount = data.eventRecord->ExtendedDataCount; + if (extendedDataCount != 0) + { + bookKeepingEvent |= ProcessExtendedData(data, extendedDataCount, countForEvent); } - }; - // See if we are on Win7 and have a separate kernel session associated with 'session' - if (session.m_kernelSession != null) - { - // Make sure both sources only dispatch one at a time by taking a lock during dispatch. - session.m_kernelSession.Source.lockObj = realTimeQueue; - session.m_associatedWithTraceLog = true; // Indicate that it is OK to have the m_kernelSession. - session.Source.lockObj = realTimeQueue; + // This must occur after the call to ProcessExtendedData to ensure that if there is a stack for this event, + // that it has been associated before the event count is incremented. Otherwise, the stack will be associated with + // the next event, and not the current event. + eventCount++; - // Set up the callbacks to the kernel session. - rawKernelEventSource = session.m_kernelSession.Source; - SetupCallbacks(rawKernelEventSource); - rawKernelEventSource.unhandledEventTemplate.traceEventSource = this; // Make everything point to the log as its source. - rawKernelEventSource.AllEvents += onAllEvents; + realTimeQueue.Enqueue(new QueueEntry(data.Clone(), Environment.TickCount)); } - - // We use the session's source for our input. - rawEventSourceToConvert = session.Source; - SetupCallbacks(rawEventSourceToConvert); - rawEventSourceToConvert.unhandledEventTemplate.traceEventSource = this; // Make everything point to the log as its source. - rawEventSourceToConvert.AllEvents += onAllEvents; } /// @@ -671,25 +842,19 @@ private unsafe void DispatchClonedEvent(TraceEvent toSend) } /// - /// Flushes any event that has waited around long enough + /// Flushes any event that has waited around for longer than minimumAgeMs. /// - private void FlushRealTimeEvents(object notUsed) + internal void FlushRealTimeEvents(int minimumAgeMs = 0) { lock (realTimeQueue) { var nowTicks = Environment.TickCount; // TODO review. - for (; ; ) + while (realTimeQueue.Count > 0) { - var count = realTimeQueue.Count; - if (count == 0) - { - break; - } - QueueEntry entry = realTimeQueue.Peek(); // If it has been in the queue less than 1 second, we we wait until next time) & 3FFFFFF does wrap around subtraction. - if (((nowTicks - entry.enqueueTick) & 0x3FFFFFFF) < 1000) + if (minimumAgeMs > 0 && ((nowTicks - entry.enqueueTick) & 0x3FFFFFFF) < minimumAgeMs) { break; } @@ -1077,6 +1242,21 @@ private void AddMarkThread(int threadID, long timeStamp, int heapNum) thread.process.markThreadsInGC[threadID] = heapNum; } } + + private void CopyHeadersFrom(TraceEventDispatcher rawEvents) + { + pointerSize = rawEvents.PointerSize; + _syncTimeUTC = rawEvents._syncTimeUTC; + _syncTimeQPC = rawEvents._syncTimeQPC; + _QPCFreq = rawEvents._QPCFreq; + sessionStartTimeQPC = rawEvents.sessionStartTimeQPC; + sessionEndTimeQPC = rawEvents.sessionEndTimeQPC; + cpuSpeedMHz = rawEvents.CpuSpeedMHz; + numberOfProcessors = rawEvents.NumberOfProcessors; + eventsLost = rawEvents.EventsLost; + osVersion = rawEvents.OSVersion; + } + /// /// SetupCallbacks installs all the needed callbacks for TraceLog Processing (stacks, process, thread, summaries etc) /// on the TraceEventSource rawEvents. @@ -1097,17 +1277,16 @@ private unsafe void SetupCallbacks(TraceEventDispatcher rawEvents) jsJittedMethods = new List(); sourceFilesByID = new Dictionary(); - // If this is a ETL file, we also need to compute all the normal TraceLog stuff the raw stream - pointerSize = rawEvents.PointerSize; - _syncTimeUTC = rawEvents._syncTimeUTC; - _syncTimeQPC = rawEvents._syncTimeQPC; - _QPCFreq = rawEvents._QPCFreq; - sessionStartTimeQPC = rawEvents.sessionStartTimeQPC; - sessionEndTimeQPC = rawEvents.sessionEndTimeQPC; - cpuSpeedMHz = rawEvents.CpuSpeedMHz; - numberOfProcessors = rawEvents.NumberOfProcessors; - eventsLost = rawEvents.EventsLost; - osVersion = rawEvents.OSVersion; + // We need to copy some information from the event source. + // An EventPipeEventSource won't have headers set until Process() is called, so we wait for the event trigger instead of copying right away. + if (rawEvents is EventPipeEventSource eventPipeEventSource) + { + eventPipeEventSource.HeadersDeserialized += delegate () { CopyHeadersFrom(rawEvents); }; + } + else + { + CopyHeadersFrom(rawEvents); + } // These parsers create state and we want to collect that so we put it on our 'parsers' list that we serialize. var kernelParser = rawEvents.Kernel; @@ -4331,13 +4510,15 @@ public override bool Process() TraceLog.rawKernelEventSource.Process(); TraceLog.rawEventSourceToConvert.StopProcessing(); }); - kernelTask.Start(); } TraceLog.rawEventSourceToConvert.Process(); if (kernelTask != null) { TraceLog.rawKernelEventSource.StopProcessing(); kernelTask.Wait(); + + // Flush all outstanding events in the realTimeQueue. + TraceLog.FlushRealTimeEvents(); } return true; } @@ -9132,11 +9313,7 @@ internal void AddILMapping(MethodILToNativeMapTraceData data) { var ilMap = new ILToNativeMap(); ilMap.Next = ILMapIndex.Invalid; - var process = log.Processes.GetProcess(data.ProcessID, data.TimeStampQPC); - if (process == null) - { - return; - } + var process = log.Processes.GetOrCreateProcess(data.ProcessID, data.TimeStampQPC); ilMap.ProcessIndex = process.ProcessIndex; ILToNativeMapTuple tuple;