c# - Es LogicalOperationStack incompatible con async en.Net 4.5

async-await .net-4.5

Question

Trace.CorrelationManager.LogicalOperationStack permite tener identificadores de operaciones lógicas anidadas donde el caso más común es el registro (NDC). ¿Debería seguir funcionando con async-await ?

Aquí hay un ejemplo simple utilizando LogicalFlow que es mi envoltorio simple sobre LogicalOperationStack :

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;
            }
        }
    }
}

Salida:

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

Los valores específicos realmente no importan, pero como lo entiendo, tanto las líneas externas deben mostrar Guid.Empty (es decir, 00000000-0000-0000-0000-000000000000 ) y las líneas internas deben mostrar el mismo valor de Guid .

Podría decir que LogicalOperationStack está utilizando una Stack que no es segura para subprocesos y es por eso que la salida es incorrecta. Pero aunque eso es cierto en general, en este caso , nunca hay más de un solo hilo que accede a LogicalOperationStack al mismo tiempo (se espera cada operación async cuando se llama y no se utilizan combinadores como Task.WhenAll )

El problema es que LogicalOperationStack se almacena en el CallContext que tiene un comportamiento de copia en escritura. Eso significa que siempre y cuando no establezcas explícitamente algo en el CallContext (y no lo hagas cuando agregas a una pila existente con StartLogicalOperation ) estás usando el contexto principal y no el tuyo.

Esto se puede mostrar simplemente configurando cualquier cosa en el CallContext antes de agregarlo a la pila existente. Por ejemplo, si cambiamos StartScope a esto:

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

La salida es:

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

Nota: no estoy sugiriendo que alguien realmente haga esto. La solución práctica real sería usar un ImmutableStack lugar del LogicalOperationStack ya que es seguro para subprocesos y, dado que es inmutable, cuando llamas a Pop , recibes un nuevo ImmutableStack que luego debes volver a establecer en CallContext . Una implementación completa está disponible como respuesta a esta pregunta: Seguimiento de flujo de tareas c # / .NET

Entonces, ¿debería funcionar LogicalOperationStack con async y es solo un error? ¿ LogicalOperationStack no está destinado al mundo async ? ¿O me estoy perdiendo algo?

Actualización : el uso de Task.Delay es aparentemente confuso ya que usa System.Threading.Timer que captura el ExecutionContext internamente . Utilizando await Task.Yield(); En lugar de await Task.Delay(100); hace que el ejemplo sea más fácil de entender.

Answer 1

Sí, LogicalOperationStack debería funcionar con async-await y es un error que no funciona.

Me puse en contacto con el desarrollador relevante de Microsoft y su respuesta fue la siguiente:

" No estaba al tanto de esto, pero parece estar roto . Se supone que la lógica de copia en escritura se comporta exactamente como si realmente hubiéramos creado una copia de ExecutionContext al ingresar al método. Sin embargo, copiando el ExecutionContext habría creado una copia en profundidad del contexto de CorrelationManager , ya que está especial en el contexto de CallContext.Clone() . No tenemos eso en cuenta en la lógica de copia en escritura ".

Además, recomendó usar la nueva clase System.Threading.AsyncLocal<T> agregada en .Net 4.6 en lugar de eso, que debería manejar ese problema correctamente.

Entonces, seguí adelante e implementé LogicalFlow sobre LogicalFlow en lugar de LogicalOperationStack usando VS2015 RC y .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();
}

Y la salida para la misma prueba es, en efecto, como debería ser:

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

Si aún estás interesado en esto, creo que es un error en la forma en que fluyen LogicalOperationStack y creo que es una buena idea reportarlo.

Le dan un tratamiento especial a la pila de LogicalCallContext.Clone aquí en LogicalCallContext.Clone , haciendo una copia profunda (a diferencia de otros datos almacenados a través de CallContext.LogicalSetData/LogicalGetData , en la que solo se realiza una copia superficial).

Este LogicalCallContext.Clone se llama cada vez que se llama a ExecutionContext.CreateCopy o ExecutionContext.CreateMutableCopy para fluir el ExecutionContext .

Basado en su código, hice un pequeño experimento al proporcionar mi propia pila mutable para la ranura "System.Diagnostics.Trace.CorrelationManagerSlot" en LogicalCallContext , para ver cuándo y cuántas veces realmente se clona.

El código:

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;
                }
            }
        }
    }
}

El resultado es bastante sorprendente. Aunque solo hay dos subprocesos involucrados en este flujo de trabajo asíncrono, la pila se clona hasta 4 veces. Y el problema es que las operaciones Stack.Push y Stack.Pop (llamadas por StartLogicalOperation / StopLogicalOperation ) operan en los diferentes clones no coincidentes de la pila, lo que desestabiliza la pila "lógica". Ahí es donde se encuentra el error.

De hecho, esto hace que LogicalOperationStack sea ​​totalmente inutilizable en las llamadas asíncronas, aunque no haya forks concurrentes de tareas.

Actualizado , también hice una pequeña investigación sobre cómo puede comportarse en las llamadas sincrónicas, para abordar estos comentarios :

De acuerdo, no un dupe. ¿Comprobó si funciona como se esperaba en el mismo hilo, por ejemplo, si reemplaza a esperar Task.Delay (100) con Task.Delay (100) .Wait ()? - Noseratio 27 de febrero a las 21:00.

@Noseratio si. Funciona, por supuesto, porque solo hay un solo hilo (y por lo tanto un solo CallContext). Es como si el método no fuera asincrónico para empezar. - i3arnon 27 de febrero a las 21:01

Un solo hilo no significa solo CallContext . Incluso para las continuaciones síncronas en el mismo subproceso, el contexto de ejecución (y su LogicalCallContext interno) se puede clonar. Ejemplo, usando el código anterior:

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"));

    // ...
}

Salida (note como perdemos "value2" ):

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

Answer 3

Una de las soluciones mencionadas aquí y en la web es llamar a LogicalSetData en contexto:

CallContext.LogicalSetData("one", null);
Trace.CorrelationManager.StartLogicalOperation();

Pero de hecho, basta con leer el contexto de ejecución actual:

var context = Thread.CurrentThread.ExecutionContext;
Trace.CorrelationManager.StartLogicalOperation();