LogicalOperationStack与.Net 4.5中的异步不兼容

Question

LogicalOperationStack与.Net 4.5中的异步不兼容

i3a*_*non 18 .net c# async-await .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);
    }
}

Run Code Online (Sandbox Code Playgroud)

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

Run Code Online (Sandbox Code Playgroud)

输出:

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

Run Code Online (Sandbox Code Playgroud)

具体值并不重要,但据我所知,外线应显示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();
}

Run Code Online (Sandbox Code Playgroud)

输出是:

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

Run Code Online (Sandbox Code Playgroud)

注意:我不是建议任何人真正这样做.真正实用的解决方案是使用一个ImmutableStack而不是LogicalOperationStack因为它既是线程安全的,因为它是不可变的,当你打电话给Pop你时ImmutableStack,你需要重新获得一个新的CallContext.完整的实现可以作为这个问题的答案:跟踪c#/ .NET任务流程

那么,应该LogicalOperationStack使用async它只是一个错误？难道LogicalOperationStack只是并不意味着对async世界吗？或者我错过了什么？

更新:使用Task.Delay显然混淆,因为它使用System.Threading.Timer其捕获ExecutionContext内部.使用await Task.Yield();而不是await Task.Delay(100);使示例更容易理解.

Answer 1

i3a*_*non 13

是的,LogicalOperationStack 应该使用它async-await,它是一个它没有的错误.

我已经联系了微软的相关开发人员,他的回答如下:

" 我没有意识到这一点,但它似乎确实破了.写入时复制逻辑应该表现得就像我们真正创建了ExecutionContexton方法的副本一样.但是,复制它ExecutionContext会有创建了一个深层的CorrelationManager上下文副本,因为它是特殊的CallContext.Clone().我们不会在写时复制逻辑中考虑到这一点."

此外,他建议使用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();
}

Run Code Online (Sandbox Code Playgroud)

并且相同测试的输出确实应该是:

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

Run Code Online (Sandbox Code Playgroud)

我很好奇,你是如何联系微软的相关开发人员的？[Connect中的错误](http://connect.microsoft.com/VisualStudio/feedback/details/1114703/logicaloperationstack-doesnt-work-with-async)尚未收到Microsoft的任何反馈. (2认同)

Answer 2

nos*_*tio 6

如果你仍然对此感兴趣,我相信它是如何流动的错误LogicalOperationStack,我认为报告它是一个好主意.

它们通过执行深度复制(与通过其存储的其他数据不同,仅执行浅拷贝)对此处 LogicalOperationStack的堆栈进行特殊处理.LogicalCallContext.CloneCallContext.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;
                }
            }
        }
    }
}

Run Code Online (Sandbox Code Playgroud)

结果非常令人惊讶.即使此异步工作流中只涉及两个线程,堆栈也会被克隆多达4次.问题是,匹配Stack.Push和Stack.Pop操作(由StartLogicalOperation/ 调用StopLogicalOperation)在堆栈的不同的,不匹配的克隆上运行,从而使"逻辑"堆栈失去平衡.这就是bug存在的地方.

这确实使LogicalOperationStack异步调用完全无法使用,即使没有并发的任务分支.

更新后,我还对同步调用的行为方式进行了一些研究,以解决这些问题:

同意,而不是欺骗.您是否在同一个线程上检查它是否按预期工作,例如,如果用Task.Delay(100)替换等待Task.Delay(100).Wait()？ - Noseratio 2月27日21:00

@Noseratio是的.它当然有效,因为只有一个线程(因此只有一个CallContext).这就好像该方法不是一开始就是异步的. - i3arnon 2月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"));

    // ...
}

Run Code Online (Sandbox Code Playgroud)

输出(注意我们输了"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

归档时间：	10 年，6 月前
查看次数：	3316 次
最近记录：	6 年，10 月前