diff --git a/src/TraceEvent/TraceEvent.Tests/Parsing/EventPipeParsing.cs b/src/TraceEvent/TraceEvent.Tests/Parsing/EventPipeParsing.cs index cb1620d9c..92d4abbc2 100644 --- a/src/TraceEvent/TraceEvent.Tests/Parsing/EventPipeParsing.cs +++ b/src/TraceEvent/TraceEvent.Tests/Parsing/EventPipeParsing.cs @@ -12,6 +12,7 @@ using System.IO; using System.Linq; using System.Text; +using System.Threading; using System.Threading.Tasks; using Xunit; using Xunit.Abstractions; @@ -217,6 +218,142 @@ public async Task SessionStreaming(bool initialRundown) } } +#if NETCOREAPP3_0_OR_GREATER + [Fact] +#else + [Fact(Skip = "EventPipeSession connection is only available to target apps on .NET Core 3.0 or later")] +#endif + public async Task ResetCallStacksDiscardsInternedStacksAndKeepsInterning() + { + // In a real time session the call stack interning tables grow for the lifetime of the + // session: every distinct stack observed is interned and nothing is released, so a long + // running session grows without bound. ResetCallStacks discards them. + // + // This verifies both halves of the contract: the tables are actually emptied, and stacks + // observed afterwards are still interned and still resolve to methods. + const int MinimumInternedStacks = 8; + + var client = new DiagnosticsClient(Process.GetCurrentProcess().Id); + var providers = new[] + { + new EventPipeProvider(SampleProfilerTraceEventParser.ProviderName, EventLevel.Informational), + }; + + using (var session = client.StartEventPipeSession(providers, requestRundown: false)) + { + using (var traceSource = CreateFromEventPipeSession(session, EventPipeRundownConfiguration.Enable(client))) + { + var traceLog = traceSource.TraceLog; + var sampleEventParser = new SampleProfilerTraceEventParser(traceSource); + + int stacksBeforeReset = 0; + int stacksAfterReset = -1; + // RunContinuationsAsynchronously so awaiting this cannot resume inline on the + // event processing thread - the continuation below stops the session and waits + // on the processing task, which would deadlock if it ran on that thread. + var stackAfterReset = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + + sampleEventParser.ThreadSample += delegate (ClrThreadSampleTraceData e) + { + // ResetCallStacks has to run on the thread that processes events, which is the + // thread this callback runs on. + if (stacksAfterReset < 0) + { + // Let enough distinct stacks accumulate for the 'before' value to be meaningful. + if (traceLog.CallStacks.Count < MinimumInternedStacks) + { + return; + } + + stacksBeforeReset = traceLog.CallStacks.Count; + traceLog.ResetCallStacks(); + stacksAfterReset = traceLog.CallStacks.Count; + return; + } + + // Anything interned after the reset must still be usable. + CallStackIndex callStackIndex = e.CallStackIndex(); + if (callStackIndex != CallStackIndex.Invalid) + { + stackAfterReset.TrySetResult(callStackIndex); + } + }; + + var processingTask = Task.Run(traceSource.Process); + + // Keep a little work running so the sampler sees a variety of stacks. + var workDone = new CancellationTokenSource(); + var workTask = Task.Run(() => + { + while (!workDone.IsCancellationRequested) + { + RecursiveWork(12); + } + }); + + try + { + Task completed = await Task.WhenAny(stackAfterReset.Task, Task.Delay(TimeSpan.FromSeconds(60))); + Assert.True(completed == stackAfterReset.Task, + $"Timed out waiting for a call stack after the reset (interned before reset: {stacksBeforeReset})."); + } + finally + { + workDone.Cancel(); + await workTask; + } + + Assert.True(stacksBeforeReset >= MinimumInternedStacks, + $"Expected at least {MinimumInternedStacks} interned call stacks before the reset, saw {stacksBeforeReset}."); + + // The interning tables were emptied. + Assert.Equal(0, stacksAfterReset); + + // ...and interning continued to work afterwards, all the way through to a method name. + CallStackIndex postResetStack = await stackAfterReset.Task; + CodeAddressIndex codeAddressIndex = traceLog.CallStacks.CodeAddressIndex(postResetStack); + Assert.NotEqual(CodeAddressIndex.Invalid, codeAddressIndex); + MethodIndex methodIndex = traceLog.CodeAddresses.MethodIndex(codeAddressIndex); + Assert.NotEqual(MethodIndex.Invalid, methodIndex); + Assert.NotEmpty(traceLog.CodeAddresses.Methods[methodIndex].FullMethodName); + Assert.True(traceLog.CallStacks.Count > 0, "Expected the interning tables to refill after the reset."); + + // Every index in a post-reset stack must refer to the *new* table. If any part of + // the interning state survived the reset (for example the per-thread roots), stale + // indexes from the old table leak back in here. Those do not throw - GrowableArray + // indexes its backing store without bounds checking against Count - so the stack + // would silently resolve to the wrong frames. Walking the whole chain and range + // checking each link is what actually catches that. + int stackCount = traceLog.CallStacks.Count; + int depth = 0; + for (CallStackIndex frame = postResetStack; frame != CallStackIndex.Invalid; frame = traceLog.CallStacks.Caller(frame)) + { + Assert.InRange((int)frame, 0, stackCount - 1); + Assert.True(++depth <= stackCount, + "Walking the post-reset call stack did not terminate; the interning tables are inconsistent."); + } + + session.Stop(); + await processingTask; + } + } + } + + private static long RecursiveWork(int depth) + { + if (depth <= 0) + { + double sink = 0; + for (int i = 1; i < 10000; i++) + { + sink += Math.Sqrt(i); + } + return (long)sink; + } + + return RecursiveWork(depth - 1) + depth; + } + [Fact] public void V1IsUnsupported() { diff --git a/src/TraceEvent/TraceLog.cs b/src/TraceEvent/TraceLog.cs index f1036b304..56c244262 100644 --- a/src/TraceEvent/TraceLog.cs +++ b/src/TraceEvent/TraceLog.cs @@ -975,6 +975,42 @@ private void FlushRealTimeEventsNoLock(int minimumAgeMs) } } + /// + /// Discards every call stack interned so far, releasing the memory held by the call stack + /// interning tables (see ). + /// + /// In a real time session those tables grow for the lifetime of the session: every distinct + /// call stack that is observed is interned and nothing is ever released. For a long running + /// process with diverse stacks that growth is unbounded. Trace files do not have this problem + /// because the session is finite, which is why this is restricted to real time sessions. + /// + /// + /// Every obtained before this call is invalidated and must not be + /// used afterwards, so only call this when no such index is still live. Call stacks observed + /// after the call are interned from scratch, so no information is lost going forward - only + /// the ability to resolve indexes handed out earlier. + /// + /// + /// Must be called from the thread that processes events (for example from within an event + /// callback). Calling it concurrently with event processing races with call stack interning. + /// + /// + /// The TraceLog is not a real time session. + public void ResetCallStacks() + { + if (!IsRealTime) + { + throw new InvalidOperationException("ResetCallStacks is only supported for real time sessions."); + } + + callStacks.Clear(); + + // These map events to the indexes we just invalidated, so also need clearing. + // A length reset is enough here - they hold structs, so nothing is retained. + eventsToStacks.Clear(); + cswitchBlockingEventsToStacks.Clear(); + } + /// /// Given a process's virtual address 'address' and an event which acts as a /// context (determines which process and what time in that process), return @@ -7821,6 +7857,19 @@ internal void SetSize(int origSize) callStacks.RemoveRange(origSize, callStacks.Count - origSize); } + /// + /// Discards every interned call stack, returning the interning tables to their initial state. + /// Only meaningful for a real time session, where these tables would otherwise grow for the + /// lifetime of the session. See . + /// + internal void Clear() + { + // GrowableArray.Clear() only resets the length so we have to assign fresh arrays + callStacks = new GrowableArray(); + callees = new GrowableArray>(); + threads = new GrowableArray>(); + } + /// /// Returns an index that represents the 'threads' of the stack. It encodes the thread which owns this stack into this. /// We encode this as -ThreadIndex - 2 (since -1 is the Invalid node)