diff --git a/src/Sentry.Profiling/SampleProfileBuilder.cs b/src/Sentry.Profiling/SampleProfileBuilder.cs index 56927be4a9..3a90fe30a3 100644 --- a/src/Sentry.Profiling/SampleProfileBuilder.cs +++ b/src/Sentry.Profiling/SampleProfileBuilder.cs @@ -11,8 +11,12 @@ namespace Sentry.Profiling; internal class SampleProfileBuilder { private readonly SentryOptions _options; + private readonly SampleProfilerSession? _session; private readonly TraceLog _traceLog; + // The trim generation this builder's _stackIndexes cache was populated against. + private int _trimGeneration; + // Output profile being built. public readonly SampleProfile Profile = new(); @@ -32,14 +36,30 @@ internal class SampleProfileBuilder // TODO make downsampling conditional once this is available: https://github.com/dotnet/runtime/issues/82939 private readonly Downsampler _downsampler = new(); + // For a TraceLog read from a file, where nothing trims it and no generation tracking is needed. public SampleProfileBuilder(SentryOptions options, TraceLog traceLog) { _options = options; _traceLog = traceLog; } + public SampleProfileBuilder(SentryOptions options, SampleProfilerSession session) + : this(options, session.TraceLog) + { + _session = session; + _trimGeneration = session.TrimGeneration; + } + internal void AddSample(TraceEvent data, double timestampMs) { + // The interning tables have been discarded since we last looked so we have to + // invalidate the _stackIndexes cache (means stacks get walked again) + if (_session is { } session && _trimGeneration != session.TrimGeneration) + { + _trimGeneration = session.TrimGeneration; + _stackIndexes.Clear(); + } + var thread = data.Thread(); if (thread is null || thread.ThreadIndex == ThreadIndex.Invalid) { diff --git a/src/Sentry.Profiling/SampleProfilerSession.cs b/src/Sentry.Profiling/SampleProfilerSession.cs index 376ba85a1c..06e6149f74 100644 --- a/src/Sentry.Profiling/SampleProfilerSession.cs +++ b/src/Sentry.Profiling/SampleProfilerSession.cs @@ -57,12 +57,29 @@ private SampleProfilerSession(SentryStopwatch stopwatch, EventPipeSession sessio public TraceLog TraceLog => EventSource.TraceLog; + // Bumped every time the interning tables are discarded. Anything caching a + // CallStackIndex can invalidate it's cache whenever this changes + internal int TrimGeneration; + + /// + /// Discards TraceLog's call stack interning tables, invalidating CallStackIndexes. + /// Must be called from the event processing thread. + /// + internal void TrimLiveSessionState() + { + OnTrimForTests?.Invoke(); + TraceLog.TrimLiveSessionState(); + TrimGeneration++; + } + internal bool IsStopped => _stopped; internal static Action? BeforeStartupForTests; internal static Action? OnSessionCreatedForTests; + internal static Action? OnTrimForTests; + private static InterlockedBoolean _throwOnNextStartupForTests = false; internal static bool ThrowOnNextStartupForTests diff --git a/src/Sentry.Profiling/SamplingTransactionProfiler.cs b/src/Sentry.Profiling/SamplingTransactionProfiler.cs index 52d6ea193b..5436b29829 100644 --- a/src/Sentry.Profiling/SamplingTransactionProfiler.cs +++ b/src/Sentry.Profiling/SamplingTransactionProfiler.cs @@ -24,7 +24,7 @@ public SamplingTransactionProfiler(SentryOptions options, SampleProfilerSession _cancellationToken = cancellationToken; _startTimeMs = session.Elapsed.TotalMilliseconds; _endTimeMs = double.MaxValue; - _processor = new SampleProfileBuilder(options, session.TraceLog); + _processor = new SampleProfileBuilder(options, session); session.SampleEventParser.ThreadSample += OnThreadSample; cancellationToken.Register(() => { diff --git a/src/Sentry.Profiling/SamplingTransactionProfilerFactory.cs b/src/Sentry.Profiling/SamplingTransactionProfilerFactory.cs index 6afc75538b..95ce64cfee 100644 --- a/src/Sentry.Profiling/SamplingTransactionProfilerFactory.cs +++ b/src/Sentry.Profiling/SamplingTransactionProfilerFactory.cs @@ -16,6 +16,9 @@ internal class SamplingTransactionProfilerFactory : IDisposable, ITransactionPro private const int SHUTDOWN_TIMEOUT_MS = 2_000; + // Once the interning tables exceed this many entries we discard them ASAP + internal int MaxCallStackCount = 100_000; + private readonly SentryOptions _options; internal Task _sessionTask; @@ -31,6 +34,10 @@ internal bool IsDisposed get { lock (_sessionLock) { return _disposed; } } } + internal int TrimCount; + + private bool _trimFailed; + private bool _errorLogged = false; public SamplingTransactionProfilerFactory(SentryOptions options, TimeSpan startupTimeout) @@ -54,6 +61,8 @@ public SamplingTransactionProfilerFactory(SentryOptions options, TimeSpan startu // This can block indefinitely. await session.WaitForFirstEventAsync(shutdownToken).ConfigureAwait(false); + session.SampleEventParser.ThreadSample += _ => TrimSessionStateIfNeeded(session); + return session; }); @@ -137,6 +146,33 @@ private bool TryBeginShutdown(out SampleProfilerSession? sessionToStop) return null; } + /// + /// Must run on the event processing thread, which is the only thread allowed to trim - hence + /// hanging off ThreadSample rather than off profile completion. + /// + private void TrimSessionStateIfNeeded(SampleProfilerSession session) + { + if (_trimFailed || session.TraceLog.CallStacks.Count <= MaxCallStackCount) + { + return; + } + + try + { + _options.LogDebug("Trimming profiler session state, {0} interned call stacks.", session.TraceLog.CallStacks.Count); + // Costs the in-flight sample: its stack mapping goes with the tables, so AddSample skips it. + session.TrimLiveSessionState(); + TrimCount++; + } + catch (Exception e) + { + // Latch off rather than retrying on every subsequent sample, which would throw and log + // at sample rate on the event processing thread. + _trimFailed = true; + _options.LogError(e, "Failed to trim profiler session state. Profiling memory use is no longer bounded."); + } + } + public void Dispose() { if (!TryBeginShutdown(out var session)) diff --git a/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs b/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs index 03769e7057..1ba4e4f372 100644 --- a/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs +++ b/test/Sentry.Profiling.Tests/SamplingTransactionProfilerTests.cs @@ -537,6 +537,155 @@ public void ProfilerIntegration_WithProfilingEnabled_SetsFactory() Assert.NotNull(hub.Options.TransactionProfilerFactory); } + [SkippableFact] + public void Profiler_WhenNoProfileRunning_TrimsInternedCallStacks() + { + Skip.If(TestEnvironment.IsGitHubActions, "Flaky in CI."); + + // The interning tables grow whether or not a profile is running, so this deliberately never + // starts one - the trim has to happen off the back of ordinary samples. See #5469. + using var factory = new SamplingTransactionProfilerFactory(_testSentryOptions, TimeSpan.FromSeconds(30)); + factory.MaxCallStackCount = 100; + SkipIfFailsInCI(() => factory._sessionTask.Wait(60_000)); + var traceLog = factory._sessionTask.Result.TraceLog; + + // Produce a variety of stack shapes so the sampler has something to intern. Run for the + // full duration rather than stopping at the first trim, so we observe the steady state. + var stopwatch = Stopwatch.StartNew(); + var random = new Random(4242); + var highWaterMark = 0; + while (stopwatch.ElapsedMilliseconds < 3_000) + { + RecursiveWork(random.Next(8, 24), random); + highWaterMark = Math.Max(highWaterMark, traceLog.CallStacks.Count); + } + + SkipIfFailsInCI(() => + { + if (factory.TrimCount == 0) + { + throw new Exception($"No trim occurred; call stacks peaked at {highWaterMark}."); + } + }); + + Assert.True(factory.TrimCount > 0, $"Expected at least one trim, call stacks peaked at {highWaterMark}."); + + // The table refills immediately after each trim, so its size at any instant is noise. What + // matters is that it stays bounded - untrimmed this workload reaches thousands in 3s. + Assert.True(highWaterMark < factory.MaxCallStackCount * 20, + $"Expected the interning table to stay bounded, but it peaked at {highWaterMark}."); + } + + [SkippableFact] + public void Profiler_WhileProfileRunning_StillTrimsInternedCallStacks() + { + Skip.If(TestEnvironment.IsGitHubActions, "Flaky in CI."); + + // A profile is held open for the whole test. Trimming must still happen: profiles can run + // back to back under load, so gating the trim on "no profile running" would starve it + // exactly when the tables grow fastest. The profile is then collected to show that trimming + // mid-profile does not corrupt its output. + using var factory = new SamplingTransactionProfilerFactory(_testSentryOptions, TimeSpan.FromSeconds(30)); + factory.MaxCallStackCount = 100; + SkipIfFailsInCI(() => factory._sessionTask.Wait(60_000)); + + var clock = SentryStopwatch.StartNew(); + var transactionTracer = new TransactionTracer(Substitute.For(), "test", ""); + var sut = factory.Start(transactionTracer, CancellationToken.None) as SamplingTransactionProfiler; + SkipIfFailsInCI(() => ArgumentNullException.ThrowIfNull(sut)); + transactionTracer.TransactionProfiler = sut; + + // Discard trims from before the profile started - the tiny budget means the session + // startup alone can trigger one. From here every trim happens while _inProgress is true. + factory.TrimCount = 0; + + // Run for a fixed duration rather than stopping at the first trim: the profile needs to + // last long enough for samples to actually be dispatched to it, or there is nothing to + // validate at the end. + var stopwatch = Stopwatch.StartNew(); + var random = new Random(4242); + while (stopwatch.ElapsedMilliseconds < 3_000) + { + RecursiveWork(random.Next(8, 24), random); + } + + SkipIfFailsInCI(() => + { + if (factory.TrimCount == 0) + { + throw new Exception("No trim occurred while a profile was running."); + } + }); + Assert.True(factory.TrimCount > 0, "Expected trimming to happen even while a profile is running."); + + sut!.Finish(); + var elapsedNanoseconds = (ulong)((clock.CurrentDateTimeOffset - clock.StartDateTimeOffset).TotalMilliseconds * 1_000_000); + var collectTask = sut.CollectAsync(new SentryTransaction(transactionTracer)); + collectTask.Wait(); + ValidateProfile(collectTask.Result.Profile, elapsedNanoseconds); + } + + [SkippableFact] + public void Profiler_WhenTrimFails_StopsRetrying() + { + Skip.If(TestEnvironment.IsGitHubActions, "Flaky in CI."); + + var attempts = 0; + SampleProfilerSession.OnTrimForTests = () => + { + attempts++; + throw new InvalidOperationException("Test exception"); + }; + try + { + using var factory = new SamplingTransactionProfilerFactory(_testSentryOptions, TimeSpan.FromSeconds(30)); + factory.MaxCallStackCount = 100; + SkipIfFailsInCI(() => factory._sessionTask.Wait(60_000)); + + var stopwatch = Stopwatch.StartNew(); + var random = new Random(4242); + while (stopwatch.ElapsedMilliseconds < 3_000) + { + RecursiveWork(random.Next(8, 24), random); + } + + SkipIfFailsInCI(() => + { + if (attempts == 0) + { + throw new Exception("The trim was never attempted, so the latch was not exercised."); + } + }); + + // Without the latch this would be attempted on every sample for the rest of the session, + // throwing and logging each time on the event processing thread. + Assert.Equal(1, attempts); + Assert.Equal(0, factory.TrimCount); + } + finally + { + SampleProfilerSession.OnTrimForTests = null; + } + } + + private static long RecursiveWork(int depth, Random random) + { + if (depth <= 0) + { + double sink = 0; + for (var i = 1; i < 5_000; i++) + { + sink += Math.Sqrt(i); + } + return (long)sink; + } + + // Branch so that different calls produce different stack shapes. + return (random.Next(2) == 0) + ? RecursiveWork(depth - 1, random) + depth + : RecursiveWork(depth - 1, random) - depth; + } + [SkippableFact] public void Downsampler_ShouldSample_Works() {