From ea3a06a9369e2573ebf37d0d971e772b62d84edc Mon Sep 17 00:00:00 2001 From: "Ilya.Usov" Date: Thu, 11 Jan 2024 15:31:17 +0100 Subject: [PATCH] Add ability to provide additional diagnostic data for exception `ExecuteIfAlive after termination of {myDef} took too much time (>{terminationTimeoutMs}ms)` Add test --- .../Lifetimes/Lifetimes/LifetimeDefinition.cs | 138 ++++++++++++++++-- .../Test.Lifetimes/Lifetimes/LifetimeTest.cs | 61 +++++++- rd-net/Test.Lifetimes/Test.Lifetimes.csproj | 3 + 3 files changed, 184 insertions(+), 18 deletions(-) diff --git a/rd-net/Lifetimes/Lifetimes/LifetimeDefinition.cs b/rd-net/Lifetimes/Lifetimes/LifetimeDefinition.cs index fff67d87b..b2bb78f32 100644 --- a/rd-net/Lifetimes/Lifetimes/LifetimeDefinition.cs +++ b/rd-net/Lifetimes/Lifetimes/LifetimeDefinition.cs @@ -4,12 +4,11 @@ using System.Threading; using System.Threading.Tasks; using JetBrains.Annotations; -using JetBrains.Collections.Viewable; +using JetBrains.Collections; using JetBrains.Core; using JetBrains.Diagnostics; using JetBrains.Threading; using JetBrains.Util; -using JetBrains.Util.Internal; using JetBrains.Util.Util; namespace JetBrains.Lifetimes @@ -22,12 +21,11 @@ public class LifetimeDefinition : IDisposable { #pragma warning disable 420 #region Statics - - private static readonly Signal ourExecutionWasNotCancelledByTimeout = new(); - /// - /// Use this signal to improve diagnostics (e.g., to collect thread dumps etc.)) - /// - public static ISource ExecutionWasNotCancelledByTimeout => ourExecutionWasNotCancelledByTimeout; + +#if !NET35 + public static AdditionalDiagnosticsInfo? AdditionalDiagnostics { get; set; } + private static readonly AdditionalDiagnosticsInfoStorage ourAdditionalDiagnosticsStorage = new(); +#endif internal static readonly ILog Log = JetBrains.Diagnostics.Log.GetLog(); @@ -463,7 +461,15 @@ public void Terminate() + "This is also possible if the thread waiting for the termination wasn't able to receive execution time during the wait in SpinWait.spinUntil, so it has missed the fact that the lifetime was terminated in time."); ourLogErrorAfterExecution.InterlockedUpdate(ref myState, true); - ourExecutionWasNotCancelledByTimeout.Fire(Lifetime); +#if !NET35 + if (AdditionalDiagnostics is { } additionalDiagnostics) + { + Log.Catch(() => + { + ourAdditionalDiagnosticsStorage.AddData(this, additionalDiagnostics.GetAdditionalDiagnosticsIfExecutionWasNotCancelledByTimeoutAsync(Lifetime)); + }); + } +#endif } if (!IncrementStatusIfEqualsTo(LifetimeStatus.Canceling)) @@ -791,6 +797,9 @@ public void Dispose() { if (!Succeed) return; + + // must be called before the execution counter becomes 0 to ensure that additional diagnostic data is not cleared from AdditionalDiagnosticsInfoStorage + LogErrorIfCookieWasNotReleasedForTooLong(); Interlocked.Decrement(ref myDef.myState); @@ -799,12 +808,36 @@ public void Dispose() if (myAllowTerminationUnderExecuting) ourAllowTerminationUnderExecutionThreadStatic--; + } + private void LogErrorIfCookieWasNotReleasedForTooLong() + { if (ourLogErrorAfterExecution[myDef.myState]) { + string? additionalInfo = null; +#if !NET35 + if (AdditionalDiagnostics is { } additionalDiagnostics) + { + var diagnostics = ourAdditionalDiagnosticsStorage.TryGetDiagnostics(myDef); + if (diagnostics is not { IsCompleted: true }) + { + if (additionalDiagnostics.SuppressExecuteIfAliveTookTooMuchTimeErrorIfDiagnosticIsNotReadyWhenCookieIsReleased) + return; + } + else if (diagnostics is { Status: TaskStatus.RanToCompletion }) + { + additionalInfo = diagnostics.Result; + } + } +#endif + var terminationTimeoutMs = GetTerminationTimeoutMs(myDef.TerminationTimeoutKind); - Log.Error($"ExecuteIfAlive after termination of {myDef} took too much time (>{terminationTimeoutMs}ms)"); - } + var message = $"ExecuteIfAlive after termination of {myDef} took too much time (>{terminationTimeoutMs}ms)"; + if (additionalInfo != null) + message += $"\nAdditionalInfo:\n{additionalInfo}"; + + Log.Error(message); + } } } @@ -1077,6 +1110,89 @@ public void Dispose() #endregion + + +#if !NET35 + + public class AdditionalDiagnosticsInfo + { + /// + /// Set this property to provide additional diagnostic for exception: `ExecuteIfAlive after termination of {myDef} took too much time (>{terminationTimeoutMs}ms)` + /// + public Func> GetAdditionalDiagnosticsIfExecutionWasNotCancelledByTimeoutAsync { get; } + + public bool SuppressExecuteIfAliveTookTooMuchTimeErrorIfDiagnosticIsNotReadyWhenCookieIsReleased { get; } + + public AdditionalDiagnosticsInfo( + bool suppressExecuteIfAliveTookTooMuchTimeErrorIfDiagnosticIsNotReadyWhenCookieIsReleased, + Func> getAdditionalDiagnosticsIfExecutionWasNotCancelledByTimeout) + { + GetAdditionalDiagnosticsIfExecutionWasNotCancelledByTimeoutAsync = getAdditionalDiagnosticsIfExecutionWasNotCancelledByTimeout ?? throw new ArgumentNullException(nameof(getAdditionalDiagnosticsIfExecutionWasNotCancelledByTimeout)); + SuppressExecuteIfAliveTookTooMuchTimeErrorIfDiagnosticIsNotReadyWhenCookieIsReleased = suppressExecuteIfAliveTookTooMuchTimeErrorIfDiagnosticIsNotReadyWhenCookieIsReleased; + } + } + + // Naive key-value collection implementation with fixed capacity + private class AdditionalDiagnosticsInfoStorage + { + // we don't expect many simultaneously blocked lifetimes on termination, so 4 should be enough for many cases. If it won't be enough we introduce mo complicated collection + private const int MaxStorageSize = 4; + private int myCount; + // we don't need week reference because we have limited storage and terminated lifetime doesn't keep any references and we won't have any memory leaks + private readonly KeyValuePair>[] myList =new KeyValuePair>[MaxStorageSize]; + + public void AddData(LifetimeDefinition lifetime, Task task) + { + lock (myList) + { + if (TryEnsureCapacity()) + { + myList[myCount++] = new(lifetime, task); + } + } + } + + public Task? TryGetDiagnostics(LifetimeDefinition definition) + { + lock (myList) + { + foreach (var (key, value) in myList) + { + if (ReferenceEquals(key, definition)) + return value; + } + + return null; + } + } + + private bool TryEnsureCapacity() + { + lock (myList) + { + if (myCount < myList.Length) + return true; + + var index = 0; + for (var i = 0; i < myList.Length; i++) + { + var value = myList[i]; + if (value.Key is { } def && def.ExecutingCount != 0) + { + myList[index++] = value; + } + else + { + myList[i] = default; + } + } + + myCount = index; + return index < myList.Length; + } + } + } +#endif diff --git a/rd-net/Test.Lifetimes/Lifetimes/LifetimeTest.cs b/rd-net/Test.Lifetimes/Lifetimes/LifetimeTest.cs index be4f3dc9c..66667b9d0 100644 --- a/rd-net/Test.Lifetimes/Lifetimes/LifetimeTest.cs +++ b/rd-net/Test.Lifetimes/Lifetimes/LifetimeTest.cs @@ -1,6 +1,8 @@ using System; using System.Collections.Generic; using System.Linq; +using System.Runtime.CompilerServices; +using System.Text; using System.Threading; using System.Threading.Tasks; using JetBrains.Core; @@ -9,7 +11,9 @@ using JetBrains.Lifetimes; using NUnit.Framework; #if !NET35 +using System.Diagnostics; using JetBrains.Threading; +using Microsoft.Diagnostics.Runtime; #endif // ReSharper disable MethodSupportsCancellation @@ -217,8 +221,13 @@ public void TestLongTryExecute() { const string expectedWarningText = "can't wait for `ExecuteIfAlive` completed on other thread"; const string expectedExceptionText = "ExecuteIfAlive after termination of"; - bool warningReceived = false, exceptionReceived = false; + var warningReceived = false; + Exception? receivedException = null; + +#if !NET35 + const string stackTraceHeader = "CurrentProcessThreadDumps:"; var executionWasNotCancelledByTimeoutReceived = false; +#endif Lifetime.Using(lifetime => { @@ -237,22 +246,27 @@ void LoggerHandler(LeveledMessage message) var lifetimeDefinition = lifetime.CreateNested(); var def2 = lifetime.CreateNested(); - - LifetimeDefinition.ExecutionWasNotCancelledByTimeout.Advise(lifetime, lf => +#if !NET35 + LifetimeDefinition.AdditionalDiagnostics = new LifetimeDefinition.AdditionalDiagnosticsInfo(false, async (lf) => { + var stacks = GetCurrentProcessThreadDumps(); Assert.AreEqual(lifetimeDefinition.Lifetime, lf); executionWasNotCancelledByTimeoutReceived = true; + return $"{stackTraceHeader}\n{stacks}"; }); +#endif def2.Terminate(); +#if !NET35 Assert.IsFalse(executionWasNotCancelledByTimeoutReceived); +#endif var lifetimeTerminatedEvent = new ManualResetEvent(false); var backgroundThreadIsInTryExecuteEvent = new ManualResetEvent(false); var thread = new Thread(() => lifetimeDefinition.Lifetime.TryExecute(() => { backgroundThreadIsInTryExecuteEvent.Set(); - lifetimeTerminatedEvent.WaitOne(); + WaitForLifetimeTerminatedEvent(lifetimeTerminatedEvent); })); thread.Start(); backgroundThreadIsInTryExecuteEvent.WaitOne(); @@ -268,15 +282,48 @@ void LoggerHandler(LeveledMessage message) if (!e.Message.Contains(expectedExceptionText)) throw; - exceptionReceived = true; + receivedException = e; } }); Assert.IsTrue(warningReceived, "Warning `{0}` must have been logged", expectedWarningText); - Assert.IsTrue(exceptionReceived, "Exception `{0}` must have been logged", expectedExceptionText); + Assert.IsNotNull(receivedException, "Exception `{0}` must have been logged", expectedExceptionText); + +#if !NET35 Assert.IsTrue(executionWasNotCancelledByTimeoutReceived); + Assert.IsTrue(receivedException.Message.Contains(stackTraceHeader), $"Exception `{expectedExceptionText}` doesn't contain {stackTraceHeader}"); + Assert.IsTrue(receivedException.Message.Contains(nameof(WaitForLifetimeTerminatedEvent)), $"Exception `{expectedExceptionText}` doesn't contain {nameof(WaitForLifetimeTerminatedEvent)} method"); +#endif } - + + [MethodImpl(MethodImplOptions.NoInlining | MethodImplOptions.NoOptimization)] + private static void WaitForLifetimeTerminatedEvent(ManualResetEvent lifetimeTerminatedEvent) + { + lifetimeTerminatedEvent.WaitOne(); + } + +#if !NET35 + private static string GetCurrentProcessThreadDumps() + { + using var dataTarget = DataTarget.AttachToProcess(Process.GetCurrentProcess().Id, suspend:false); + var clrVersion = dataTarget.ClrVersions.SingleOrDefault() ?? throw new Exception("Failed to get single clr from current process"); + + using var runtime = clrVersion.CreateRuntime(); + var output = new StringBuilder(); + foreach (var clrThread in runtime.Threads) + { + if (!clrThread.IsAlive) + continue; + output.AppendLine($"Thread #{clrThread.ManagedThreadId}:"); + + foreach (var frame in clrThread.EnumerateStackTrace()) + output.AppendLine($"\tat {frame}"); + } + + return output.ToString(); + } +#endif + [Test] public void TestBracketGood() { diff --git a/rd-net/Test.Lifetimes/Test.Lifetimes.csproj b/rd-net/Test.Lifetimes/Test.Lifetimes.csproj index 54dcf5dfb..da72cbcc3 100644 --- a/rd-net/Test.Lifetimes/Test.Lifetimes.csproj +++ b/rd-net/Test.Lifetimes/Test.Lifetimes.csproj @@ -27,5 +27,8 @@ 0.12.1 + + +