diff --git a/CHANGELOG.md b/CHANGELOG.md index c685603f23..0b159a4c5d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,7 @@ - Experimental _Structured Logs_: - Remove `IDisposable` from `SentryStructuredLogger`. Disposal is intended through the owning `IHub` instance. ([#4424](https://github.com/getsentry/sentry-dotnet/pull/4424)) - Ensure all buffered logs are sent to Sentry when the application terminates unexpectedly. ([#4425](https://github.com/getsentry/sentry-dotnet/pull/4425)) + - `InvalidOperationException` potentially thrown during a race condition, especially in concurrent high-volume logging scenarios ([#4428](https://github.com/getsentry/sentry-dotnet/pull/4428)) ## 5.14.1 diff --git a/benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.StructuredLogBatchProcessorBenchmarks-report-github.md b/benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.StructuredLogBatchProcessorBenchmarks-report-github.md index befa791365..8461170b2c 100644 --- a/benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.StructuredLogBatchProcessorBenchmarks-report-github.md +++ b/benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.StructuredLogBatchProcessorBenchmarks-report-github.md @@ -1,6 +1,6 @@ ``` -BenchmarkDotNet v0.13.12, macOS 15.5 (24F74) [Darwin 24.5.0] +BenchmarkDotNet v0.13.12, macOS 15.6 (24G84) [Darwin 24.6.0] Apple M3 Pro, 1 CPU, 12 logical and 12 physical cores .NET SDK 9.0.301 [Host] : .NET 8.0.14 (8.0.1425.11118), Arm64 RyuJIT AdvSIMD @@ -8,11 +8,17 @@ Apple M3 Pro, 1 CPU, 12 logical and 12 physical cores ``` -| Method | BatchCount | OperationsPerInvoke | Mean | Error | StdDev | Gen0 | Allocated | -|---------------- |----------- |-------------------- |------------:|---------:|---------:|-------:|----------:| -| **EnqueueAndFlush** | **10** | **100** | **1,774.5 ns** | **7.57 ns** | **6.71 ns** | **0.6104** | **5 KB** | -| **EnqueueAndFlush** | **10** | **200** | **3,468.5 ns** | **11.16 ns** | **10.44 ns** | **1.2207** | **10 KB** | -| **EnqueueAndFlush** | **10** | **1000** | **17,259.7 ns** | **51.92 ns** | **46.02 ns** | **6.1035** | **50 KB** | -| **EnqueueAndFlush** | **100** | **100** | **857.5 ns** | **4.21 ns** | **3.73 ns** | **0.1469** | **1.2 KB** | -| **EnqueueAndFlush** | **100** | **200** | **1,681.4 ns** | **1.74 ns** | **1.63 ns** | **0.2937** | **2.41 KB** | -| **EnqueueAndFlush** | **100** | **1000** | **8,302.2 ns** | **12.00 ns** | **10.64 ns** | **1.4648** | **12.03 KB** | +| Method | BatchCount | OperationsPerInvoke | Mean | Error | StdDev | Gen0 | Allocated | +|------------------------- |----------- |-------------------- |-------------:|------------:|------------:|-------:|----------:| +| **EnqueueAndFlush** | **10** | **100** | **1,793.4 ns** | **13.75 ns** | **12.86 ns** | **0.6104** | **5 KB** | +| EnqueueAndFlush_Parallel | 10 | 100 | 18,550.8 ns | 368.24 ns | 889.34 ns | 1.1292 | 9.16 KB | +| **EnqueueAndFlush** | **10** | **200** | **3,679.8 ns** | **18.65 ns** | **16.53 ns** | **1.2207** | **10 KB** | +| EnqueueAndFlush_Parallel | 10 | 200 | 41,246.4 ns | 508.07 ns | 475.25 ns | 1.7090 | 14.04 KB | +| **EnqueueAndFlush** | **10** | **1000** | **17,239.1 ns** | **62.50 ns** | **58.46 ns** | **6.1035** | **50 KB** | +| EnqueueAndFlush_Parallel | 10 | 1000 | 192,059.3 ns | 956.92 ns | 895.11 ns | 4.3945 | 37.52 KB | +| **EnqueueAndFlush** | **100** | **100** | **866.7 ns** | **1.99 ns** | **1.77 ns** | **0.1469** | **1.2 KB** | +| EnqueueAndFlush_Parallel | 100 | 100 | 6,714.8 ns | 100.75 ns | 94.24 ns | 0.5569 | 4.52 KB | +| **EnqueueAndFlush** | **100** | **200** | **1,714.5 ns** | **3.20 ns** | **3.00 ns** | **0.2937** | **2.41 KB** | +| EnqueueAndFlush_Parallel | 100 | 200 | 43,842.8 ns | 860.74 ns | 1,718.99 ns | 0.9155 | 7.51 KB | +| **EnqueueAndFlush** | **100** | **1000** | **8,537.8 ns** | **9.80 ns** | **9.17 ns** | **1.4648** | **12.03 KB** | +| EnqueueAndFlush_Parallel | 100 | 1000 | 313,421.4 ns | 6,159.27 ns | 6,846.01 ns | 1.9531 | 18.37 KB | diff --git a/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs b/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs index 336d726926..9085068cce 100644 --- a/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs +++ b/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs @@ -1,5 +1,4 @@ using BenchmarkDotNet.Attributes; -using NSubstitute; using Sentry.Extensibility; using Sentry.Internal; @@ -30,22 +29,10 @@ public void Setup() }; var batchInterval = Timeout.InfiniteTimeSpan; - - var clientReportRecorder = Substitute.For(); - clientReportRecorder - .When(static recorder => recorder.RecordDiscardedEvent(Arg.Any(), Arg.Any(), Arg.Any())) - .Throw(); - - var diagnosticLogger = Substitute.For(); - diagnosticLogger - .When(static logger => logger.IsEnabled(Arg.Any())) - .Throw(); - diagnosticLogger - .When(static logger => logger.Log(Arg.Any(), Arg.Any(), Arg.Any(), Arg.Any())) - .Throw(); + var clientReportRecorder = new NullClientReportRecorder(); _hub = new Hub(options, DisabledHub.Instance); - _batchProcessor = new StructuredLogBatchProcessor(_hub, BatchCount, batchInterval, clientReportRecorder, diagnosticLogger); + _batchProcessor = new StructuredLogBatchProcessor(_hub, BatchCount, batchInterval, clientReportRecorder, null); _log = new SentryLog(DateTimeOffset.Now, SentryId.Empty, SentryLogLevel.Trace, "message"); } @@ -59,6 +46,16 @@ public void EnqueueAndFlush() _batchProcessor.Flush(); } + [Benchmark] + public void EnqueueAndFlush_Parallel() + { + _ = Parallel.For(0, OperationsPerInvoke, (int i) => + { + _batchProcessor.Enqueue(_log); + }); + _batchProcessor.Flush(); + } + [GlobalCleanup] public void Cleanup() { @@ -66,3 +63,21 @@ public void Cleanup() _hub.Dispose(); } } + +file sealed class NullClientReportRecorder : IClientReportRecorder +{ + public void RecordDiscardedEvent(DiscardReason reason, DataCategory category, int quantity = 1) + { + // no-op + } + + public ClientReport GenerateClientReport() + { + throw new UnreachableException(); + } + + public void Load(ClientReport report) + { + throw new UnreachableException(); + } +} diff --git a/src/Sentry/Internal/StructuredLogBatchBuffer.cs b/src/Sentry/Internal/StructuredLogBatchBuffer.cs index 7e518253a6..a9f49216b7 100644 --- a/src/Sentry/Internal/StructuredLogBatchBuffer.cs +++ b/src/Sentry/Internal/StructuredLogBatchBuffer.cs @@ -8,6 +8,8 @@ namespace Sentry.Internal; /// /// Must be attempted to flush via when either the is reached, /// or when the is exceeded. +/// Utilizes a , basically used as an inverse , +/// allowing multiple threads for or exclusive access for . /// [DebuggerDisplay("Name = {Name}, Capacity = {Capacity}, Additions = {_additions}, AddCount = {AddCount}, IsDisposed = {_disposed}")] internal sealed class StructuredLogBatchBuffer : IDisposable diff --git a/src/Sentry/Threading/ScopedCountdownLock.cs b/src/Sentry/Threading/ScopedCountdownLock.cs index bc3725f1a9..f3d992f893 100644 --- a/src/Sentry/Threading/ScopedCountdownLock.cs +++ b/src/Sentry/Threading/ScopedCountdownLock.cs @@ -40,7 +40,7 @@ internal ScopedCountdownLock() internal bool IsEngaged => _isEngaged == 1; /// - /// No will be entered when the has reached while the lock is engaged via an active . + /// No will be entered when the has reached , or while the lock is engaged via an active . /// Check via whether the underlying has not been set/signaled yet. /// To signal the underlying , ensure is called. /// @@ -49,6 +49,11 @@ internal ScopedCountdownLock() /// internal CounterScope TryEnterCounterScope() { + if (IsEngaged) + { + return new CounterScope(); + } + if (_event.TryAddCount(1)) { return new CounterScope(this); @@ -59,6 +64,7 @@ internal CounterScope TryEnterCounterScope() private void ExitCounterScope() { + Debug.Assert(_event.CurrentCount >= 1); _ = _event.Signal(); } @@ -75,7 +81,8 @@ internal LockScope TryEnterLockScope() { if (Interlocked.CompareExchange(ref _isEngaged, 1, 0) == 0) { - _ = _event.Signal(); // decrement the initial count of 1, so that the event can be set with the count reaching 0 when all 'CounterScope's have exited + Debug.Assert(_event.CurrentCount >= 1); + _ = _event.Signal(); // decrement the initial count of 1, so that the event can be set with the count reaching 0 when all entered 'CounterScope' instances have exited return new LockScope(this); } @@ -84,13 +91,13 @@ internal LockScope TryEnterLockScope() private void ExitLockScope() { - if (Interlocked.CompareExchange(ref _isEngaged, 0, 1) == 1) + Debug.Assert(_event.IsSet); + _event.Reset(); // reset the signaled event to the initial count of 1, so that new 'CounterScope' instances can be entered again + + if (Interlocked.CompareExchange(ref _isEngaged, 0, 1) != 1) { - _event.Reset(); // reset the signaled event to the initial count of 1, so that new `CounterScope`s can be entered again - return; + Debug.Fail("The Lock should have not been disengaged without being engaged first."); } - - Debug.Fail("The Lock should have not been disengaged without being engaged first."); } /// @@ -139,7 +146,7 @@ internal LockScope(ScopedCountdownLock lockObj) internal void Wait() { var lockObj = _lockObj; - lockObj?._event.Wait(); + lockObj?._event.Wait(Timeout.Infinite, CancellationToken.None); } public void Dispose() diff --git a/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs b/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs index dad07e1e23..d6bafc79a7 100644 --- a/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs +++ b/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs @@ -79,12 +79,12 @@ public void TryEnterLockScope_IsEngaged_IsSet() lockTwo.Dispose(); AssertEngaged(false, 1); - // successfully enter another CounterScope ... lock is engaged but not yet set + // cannot enter another CounterScope as long as the lock is already engaged by a LockScope var counterTwo = _lock.TryEnterCounterScope(); - counterTwo.IsEntered.Should().BeTrue(); - AssertEngaged(false, 2); + counterTwo.IsEntered.Should().BeFalse(); + AssertEngaged(false, 1); - // exit a CounterScope ... decrement the count + // no-op ... CounterScope is not entered counterTwo.Dispose(); AssertEngaged(false, 1); @@ -92,7 +92,7 @@ public void TryEnterLockScope_IsEngaged_IsSet() counterOne.Dispose(); AssertEngaged(true, 0); - // cannot enter another CounterScope as long as the engaged lock is set + // cannot enter another CounterScope as long as the lock is engaged and set var counterThree = _lock.TryEnterCounterScope(); counterThree.IsEntered.Should().BeFalse(); AssertEngaged(true, 0); @@ -102,11 +102,11 @@ public void TryEnterLockScope_IsEngaged_IsSet() // would block if the count of the engaged lock was not zero lockOne.Wait(); - // exit the LockScope ... reset the lock + // exit the LockScope ... reset and disengage the lock lockOne.Dispose(); AssertDisengaged(false, 0); - // can enter a CounterScope again ... the lock not set + // can enter a CounterScope again ... the lock is no longer set and no longer engaged var counterFour = _lock.TryEnterCounterScope(); counterFour.IsEntered.Should().BeTrue(); AssertDisengaged(false, 1);