Ist LogicalOperationStack mit async in .Net kompatibel?

Question

Trace.CorrelationManager.LogicalOperationStack ermöglicht die Verwendung verschachtelter logischer Operationsbezeichner, bei denen der häufigste Fall die Protokollierung (NDC) ist. Sollte es noch mit async-await funktionieren?

Hier ist ein einfaches Beispiel LogicalFlow mit denen über die LogicalOperationStack meine einfache Wrapper ist:

private static void Main() => OuterOperationAsync().GetAwaiter().GetResult(); 

private static async Task OuterOperationAsync() 
{ 
    Console.WriteLine(LogicalFlow.CurrentOperationId); 
    using (LogicalFlow.StartScope()) 
    { 
     Console.WriteLine("\t" + LogicalFlow.CurrentOperationId); 
     await InnerOperationAsync(); 
     Console.WriteLine("\t" + LogicalFlow.CurrentOperationId); 
     await InnerOperationAsync(); 
     Console.WriteLine("\t" + LogicalFlow.CurrentOperationId); 
    } 
    Console.WriteLine(LogicalFlow.CurrentOperationId); 
} 

private static async Task InnerOperationAsync() 
{ 
    using (LogicalFlow.StartScope()) 
    { 
     await Task.Delay(100); 
    } 
} 

LogicalFlow:

public static class LogicalFlow 
{ 
    public static Guid CurrentOperationId => 
     Trace.CorrelationManager.LogicalOperationStack.Count > 0 
      ? (Guid) Trace.CorrelationManager.LogicalOperationStack.Peek() 
      : Guid.Empty; 

    public static IDisposable StartScope() 
    { 
     Trace.CorrelationManager.StartLogicalOperation(); 
     return new Stopper(); 
    } 

    private static void StopScope() => 
     Trace.CorrelationManager.StopLogicalOperation(); 

    private class Stopper : IDisposable 
    { 
     private bool _isDisposed; 
     public void Dispose() 
     { 
      if (!_isDisposed) 
      { 
       StopScope(); 
       _isDisposed = true; 
      } 
     } 
    } 
} 

Ausgang:

00000000-0000-0000-0000-000000000000 
    49985135-1e39-404c-834a-9f12026d9b65 
    54674452-e1c5-4b1b-91ed-6bd6ea725b98 
    c6ec00fd-bff8-4bde-bf70-e073b6714ae5 
54674452-e1c5-4b1b-91ed-6bd6ea725b98 

Die spezifischen Werte nicht wirklich wichtig, aber wie ich es verstehe, sowohl die äußere l inines sollte Guid.Empty (d. h. 00000000-0000-0000-0000-000000000000) und die inneren Linien sollten den gleichen Guid Wert zeigen.

Sie könnten sagen, dass LogicalOperationStack eine Stack verwendet, die nicht Thread-sicher ist und deshalb die Ausgabe falsch ist. Aber während das in der Regel stimmt, in diesem Fall es nie mehr als ein einzelner Thread die LogicalOperationStack zugleich Zugriff auf (jeder async Betrieb abgewartet, wenn sie aufgerufen und keine Verwendung von Kombinatoren wie Task.WhenAll)

Das Problem ist, dass LogicalOperationStack in der CallContext gespeichert ist, die ein Copy-on-Write-Verhalten aufweist. Das heißt, solange Sie nicht explizit etwas in CallContext setzen (und Sie nicht, wenn Sie zu einem vorhandenen Stapel mit StartLogicalOperation hinzufügen) verwenden Sie den übergeordneten Kontext und nicht Ihren eigenen.

Dies kann durch einfaches Setzen von alles in die CallContext vor dem Hinzufügen zu dem vorhandenen Stapel angezeigt werden. Zum Beispiel, wenn wir StartScope dazu geändert:

public static IDisposable StartScope() 
{ 
    CallContext.LogicalSetData("Bar", "Arnon"); 
    Trace.CorrelationManager.StartLogicalOperation(); 
    return new Stopper(); 
} 

Die Ausgabe lautet:

00000000-0000-0000-0000-000000000000 
    fdc22318-53ef-4ae5-83ff-6c3e3864e37a 
    fdc22318-53ef-4ae5-83ff-6c3e3864e37a 
    fdc22318-53ef-4ae5-83ff-6c3e3864e37a 
00000000-0000-0000-0000-000000000000 

Hinweis: Ich bin nicht jemand darauf hindeutet, dies tatsächlich tun. Die wirkliche praktische Lösung wäre, eine ImmutableStack anstelle der LogicalOperationStack zu verwenden, da es sowohl threadsicher als auch unveränderlich ist, wenn Sie Pop anrufen, erhalten Sie eine neue ImmutableStack zurück, die Sie dann wieder in die CallContext setzen müssen. Eine vollständige Umsetzung ist als Antwort auf diese Frage zur Verfügung: Tracking c#/.NET tasks flow

So sollte LogicalOperationStack Arbeit mit async und es ist nur ein Fehler? Ist LogicalOperationStack einfach nicht für die async Welt gedacht? Oder fehlt mir etwas?

---

aktualisieren: Task.Delay Verwendung ist offenbar verwirrend, da es System.Threading.Timer welche captures the ExecutionContext internally verwendet. Die Verwendung von await Task.Yield(); anstelle von await Task.Delay(100); macht das Beispiel leichter verständlich.

Answer 1

Ja, LogicalOperationStacksollte Arbeit mit async-await und es ist ein Fehler, dass es doesn‘ t.

Ich habe die entsprechenden Entwickler bei Microsoft in Kontakt gebracht und seine Antwort war:

"ich nicht bewusst war, aber es scheint gebrochen.Die Copy-on-Write-Logik soll sich genau so verhalten, als hätten wir beim Eintritt in die Methode wirklich eine Kopie des ExecutionContext erstellt. Das Kopieren des ExecutionContext hätte jedoch eine tiefe Kopie des CorrelationManager-Kontextes erstellt, da es in CallContext.Clone() übergeordnet ist. Wir nehmen nicht, dass die Berücksichtigung in der Copy-on-Write-Logik.“

Außerdem empfahl er die neue System.Threading.AsyncLocal<T>-Klasse hinzugefügt in .Net 4.6 statt, die richtig diese Frage behandeln soll.

Also ging ich weiter und implementiert LogicalFlow auf der Oberseite eines AsyncLocal anstelle des LogicalOperationStack mit VS2015 RC und .Net 4.6:

public static class LogicalFlow 
{ 
    private static AsyncLocal<Stack> _asyncLogicalOperationStack = new AsyncLocal<Stack>(); 

    private static Stack AsyncLogicalOperationStack 
    { 
     get 
     { 
      if (_asyncLogicalOperationStack.Value == null) 
      { 
       _asyncLogicalOperationStack.Value = new Stack(); 
      } 

      return _asyncLogicalOperationStack.Value; 
     } 
    } 

    public static Guid CurrentOperationId => 
     AsyncLogicalOperationStack.Count > 0 
      ? (Guid)AsyncLogicalOperationStack.Peek() 
      : Guid.Empty; 

    public static IDisposable StartScope() 
    { 
     AsyncLogicalOperationStack.Push(Guid.NewGuid()); 
     return new Stopper(); 
    } 

    private static void StopScope() => 
     AsyncLogicalOperationStack.Pop(); 
} 

und die Ausgabe für den gleichen Test ist in der Tat, wie es sein sollte:

00000000-0000-0000-0000-000000000000 
    ae90c3e3-c801-4bc8-bc34-9bccfc2b692a 
    ae90c3e3-c801-4bc8-bc34-9bccfc2b692a 
    ae90c3e3-c801-4bc8-bc34-9bccfc2b692a 
00000000-0000-0000-0000-000000000000 

Answer 2

Wenn Sie immer noch daran interessiert sind, glaube ich, es ist ein Bug in, wie sie fließen LogicalOperationStack und ich denke, es ist eine gute Idee, es zu melden.

Sie geben spezielle Behandlung LogicalOperationStack 's Stapel here in LogicalCallContext.Clone, indem Sie eine tiefe Kopie (im Gegensatz zu anderen Daten über CallContext.LogicalSetData/LogicalGetData gespeichert, auf denen nur eine flache Kopie durchgeführt wird).

Diese LogicalCallContext.Clone wird jedes Mal aufgerufen ExecutionContext.CreateCopy oder ExecutionContext.CreateMutableCopy wird aufgerufen, um die ExecutionContext fließen.

Basierend auf Ihrem Code, habe ich ein kleines Experiment gemacht, indem ich meinen eigenen veränderbaren Stapel für "System.Diagnostics.Trace.CorrelationManagerSlot" Slot in LogicalCallContext, um zu sehen, wann und wie oft es tatsächlich geklont wird.

Der Code:

using System; 
using System.Collections; 
using System.Diagnostics; 
using System.Linq; 
using System.Runtime.Remoting.Messaging; 
using System.Threading; 
using System.Threading.Tasks; 

namespace ConsoleApplication 
{ 
    class Program 
    { 
     static readonly string CorrelationManagerSlot = "System.Diagnostics.Trace.CorrelationManagerSlot"; 

     public static void ShowCorrelationManagerStack(object where) 
     { 
      object top = "null"; 
      var stack = (MyStack)CallContext.LogicalGetData(CorrelationManagerSlot); 
      if (stack.Count > 0) 
       top = stack.Peek(); 

      Console.WriteLine("{0}: MyStack Id={1}, Count={2}, on thread {3}, top: {4}", 
       where, stack.Id, stack.Count, Environment.CurrentManagedThreadId, top); 
     } 

     private static void Main() 
     { 
      CallContext.LogicalSetData(CorrelationManagerSlot, new MyStack()); 

      OuterOperationAsync().Wait(); 
      Console.ReadLine(); 
     } 

     private static async Task OuterOperationAsync() 
     { 
      ShowCorrelationManagerStack(1.1); 

      using (LogicalFlow.StartScope()) 
      { 
       ShowCorrelationManagerStack(1.2); 
       Console.WriteLine("\t" + LogicalFlow.CurrentOperationId); 
       await InnerOperationAsync(); 
       ShowCorrelationManagerStack(1.3); 
       Console.WriteLine("\t" + LogicalFlow.CurrentOperationId); 
       await InnerOperationAsync(); 
       ShowCorrelationManagerStack(1.4); 
       Console.WriteLine("\t" + LogicalFlow.CurrentOperationId); 
      } 

      ShowCorrelationManagerStack(1.5); 
     } 

     private static async Task InnerOperationAsync() 
     { 
      ShowCorrelationManagerStack(2.1); 
      using (LogicalFlow.StartScope()) 
      { 
       ShowCorrelationManagerStack(2.2); 
       await Task.Delay(100); 
       ShowCorrelationManagerStack(2.3); 
      } 
      ShowCorrelationManagerStack(2.4); 
     } 
    } 

    public class MyStack : Stack, ICloneable 
    { 
     public static int s_Id = 0; 

     public int Id { get; private set; } 

     object ICloneable.Clone() 
     { 
      var cloneId = Interlocked.Increment(ref s_Id); ; 
      Console.WriteLine("Cloning MyStack Id={0} into {1} on thread {2}", this.Id, cloneId, Environment.CurrentManagedThreadId); 

      var clone = new MyStack(); 
      clone.Id = cloneId; 

      foreach (var item in this.ToArray().Reverse()) 
       clone.Push(item); 

      return clone; 
     } 
    } 

    public static class LogicalFlow 
    { 
     public static Guid CurrentOperationId 
     { 
      get 
      { 
       return Trace.CorrelationManager.LogicalOperationStack.Count > 0 
        ? (Guid)Trace.CorrelationManager.LogicalOperationStack.Peek() 
        : Guid.Empty; 
      } 
     } 

     public static IDisposable StartScope() 
     { 
      Program.ShowCorrelationManagerStack("Before StartLogicalOperation"); 
      Trace.CorrelationManager.StartLogicalOperation(); 
      Program.ShowCorrelationManagerStack("After StartLogicalOperation"); 
      return new Stopper(); 
     } 

     private static void StopScope() 
     { 
      Program.ShowCorrelationManagerStack("Before StopLogicalOperation"); 
      Trace.CorrelationManager.StopLogicalOperation(); 
      Program.ShowCorrelationManagerStack("After StopLogicalOperation"); 
     } 

     private class Stopper : IDisposable 
     { 
      private bool _isDisposed; 
      public void Dispose() 
      { 
       if (!_isDisposed) 
       { 
        StopScope(); 
        _isDisposed = true; 
       } 
      } 
     } 
    } 
} 

Das Ergebnis ist ziemlich überraschend. Obwohl in diesem asynchronen Arbeitsablauf nur zwei Threads beteiligt sind, wird der Stack viermal geklont. Und das Problem ist, dass die übereinstimmenden Operationen Stack.Push und Stack.Pop (aufgerufen durch StartLogicalOperation/StopLogicalOperation) auf den verschiedenen, nicht übereinstimmenden Klonen des Stapels arbeiten und somit den "logischen" Stapel aus dem Gleichgewicht bringen. Das ist, wo der Fehler liegt.

Dies macht tatsächlich LogicalOperationStack völlig unbenutzbar über Async-Aufrufe, obwohl es keine gleichzeitige Gabeln von Aufgaben gibt.

aktualisiert, ich habe auch ein wenig Forschung darüber, wie es für synchrone Aufrufe verhalten, these comments Adresse:

Zugegeben, kein narren. Haben Sie überprüft, ob es auf demselben Thread wie erwartet funktioniert, z. Wenn Sie ersetzen, warten Task.Delay (100) mit Task.Delay (100) .Wait()? - Naseratio 27. Februar um 21:00

@Noseratio ja. Es funktioniert natürlich, weil es nur einen einzigen Thread (und damit einen einzelnen CallContext) gibt. Es ist, als wäre die Methode nicht async, um damit zu beginnen. - i3arnon 27. Februar um 21:01

Ein einzelner Thread bedeutet nicht einfach CallContext. Selbst für synchrone Fortsetzungen auf demselben einzelnen Thread kann der Ausführungskontext (und seine innere LogicalCallContext) geklont werden. Ein Beispiel mit dem oben genannten Code:

private static void Main() 
{ 
    CallContext.LogicalSetData(CorrelationManagerSlot, new MyStack()); 

    ShowCorrelationManagerStack(0.1); 

    CallContext.LogicalSetData("slot1", "value1"); 
    Console.WriteLine(CallContext.LogicalGetData("slot1")); 

    Task.FromResult(0).ContinueWith(t => 
     { 
      ShowCorrelationManagerStack(0.2); 

      CallContext.LogicalSetData("slot1", "value2"); 
      Console.WriteLine(CallContext.LogicalGetData("slot1")); 
     }, 
     CancellationToken.None, 
     TaskContinuationOptions.ExecuteSynchronously, 
     TaskScheduler.Default); 

    ShowCorrelationManagerStack(0.3); 
    Console.WriteLine(CallContext.LogicalGetData("slot1")); 

    // ... 
} 

Ausgang (beachten Sie, wie wir "value2" verlieren):

 
0.1: MyStack Id=0, Count=0, on thread 9, top: 
value1 
Cloning MyStack Id=0 into 1 on thread 9 
0.2: MyStack Id=1, Count=0, on thread 9, top: 
value2 
0.3: MyStack Id=0, Count=0, on thread 9, top: 
value1