Является LogicalOperationStack несовместимым с async в .Net 4.5

Trace.CorrelationManager.LogicalOperationStack позволяет иметь вложенные идентификаторы логической операции, где наиболее распространенным случаем является регистрация (NDC). Должна ли она работать с async-await?

Вот простой пример с использованием LogicalFlow, который является моей простой оболочкой над 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;
            }
        }
    }
}

Вывод:

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

Конкретные значения на самом деле не имеют значения, но, как я понимаю, обе внешние линии должны показывать Guid.Empty (т.е. 00000000-0000-0000-0000-000000000000), а внутренние строки должны показывать то же значение Guid.

Вы могли бы сказать, что LogicalOperationStack использует Stack, который не является потокобезопасным и почему результат неправильный. Но в то время как это верно в общем случае, в этом случае не более одного потока, обращающегося к LogicalOperationStack в то же время (каждая операция async ожидается при вызове и без использования комбинаторов, таких как Task.WhenAll)

Проблема заключается в том, что LogicalOperationStack хранится в CallContext, который имеет поведение копирования на запись. Это означает, что до тех пор, пока вы явно не установите что-то в CallContext (а вы не добавляете в существующий стек с StartLogicalOperation), вы используете родительский контекст, а не свой собственный.

Это можно показать, просто установив что-либо в CallContext перед добавлением в существующий стек. Например, если мы изменили StartScope на это:

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

Вывод:

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

Примечание. Я не предлагаю, чтобы кто-то на самом деле это делал. Реальное практическое решение состояло бы в том, чтобы использовать ImmutableStack вместо LogicalOperationStack, поскольку он и поточно-безопасный, и поскольку он неизменен, когда вы вызываете Pop, вы возвращаете новый ImmutableStack, который затем вам нужно вернуть обратно CallContext. В качестве ответа на этот вопрос доступна полная реализация: Отслеживание потока С#/.NET задач

Итак, должен ли LogicalOperationStack работать с async и это просто ошибка? Является ли LogicalOperationStack просто не для мира async? Или я что-то упускаю?


Обновление. Использование Task.Delay, по-видимому, запутывается, поскольку использует System.Threading.Timer, который захватывает ExecutionContext внутренне. Использование await Task.Yield(); вместо await Task.Delay(100); упрощает понимание примера.

Ответы

Ответ 1

Да, LogicalOperationStack должен работать с async-await, и это ошибка, которой это не делает.

Я связался с соответствующим разработчиком в Microsoft, и его ответ был следующим:

" Я не знал об этом, но он выглядит сломанным. Логика copy-on-write должна вести себя точно так, как если бы мы действительно создали копию ExecutionContext при входе в метод. Однако копирование ExecutionContext создало бы глубокую копию контекста CorrelationManager, как это было в специальном обложке в CallContext.Clone(). Мы не учитываем это при копировании -write logic."

Кроме того, он рекомендовал использовать новый класс System.Threading.AsyncLocal<T>, добавленный в .Net 4.6, который должен правильно обрабатывать эту проблему.

Итак, я пошел вперед и реализовал LogicalFlow поверх AsyncLocal вместо LogicalOperationStack с помощью VS2015 RC и .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();
}

И вывод для того же теста действительно так и должен быть:

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

Ответ 2

Если вы все еще заинтересованы в этом, я считаю, что это ошибка в том, как они текут LogicalOperationStack, и я думаю, что это хорошая идея сообщить об этом.

Они предоставляют специальную обработку LogicalOperationStack stack здесь, в LogicalCallContext.Clone, делая глубокую копию (в отличие от других данных, хранящихся через CallContext.LogicalSetData/LogicalGetData, на котором выполняется только мелкая копия).

Этот LogicalCallContext.Clone вызывается каждый раз, когда ExecutionContext.CreateCopy или ExecutionContext.CreateMutableCopy вызывается для потока ExecutionContext.

На основе вашего кода я сделал небольшой эксперимент, предоставив свой собственный изменяемый стек для "System.Diagnostics.Trace.CorrelationManagerSlot" слота в LogicalCallContext, чтобы узнать, когда и сколько раз он фактически клонируется.

Код:

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

Результат довольно удивителен. Несмотря на то, что в этом асинхронном рабочем процессе задействованы только два потока, стек клонируется целых 4 раза. И проблема в том, что соответствующие операции Stack.Push и Stack.Pop (называемые StartLogicalOperation/StopLogicalOperation) работают с разными несогласованными клонами стека, что приводит к дисбалансу "логического" стека. То, где лежит ошибка.

Это действительно делает LogicalOperationStack полностью непригодным для использования в асинхронных вызовах, даже если нет параллельных вилок задач.

Обновлено, я также немного исследовал, как он может вести себя для синхронных вызовов, адресовать эти комментарии:

Согласовано, а не обман. Вы проверяли, работает ли он так же, как и на том же нить, например. если вы замените задачу Task.Delay(100) на Task.Delay(100).Wait()? - Noseratio 27 февраля в 21:00

@Noseratio да. Это работает, конечно, потому что существует только один поток (и, следовательно, один CallContext). Как будто этот метод не был асинк для начала. - i3arnon 27 февраля в 21:01

Один поток не означает одиночный CallContext. Даже для синхронных продолжений в одном и том же потоке контекст выполнения (и его внутренний LogicalCallContext) может быть клонирован. Пример, используя приведенный выше код:

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

    // ...
}

Выход (обратите внимание, как мы теряем "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