logo标签列表

在.NET 4.5中，LogicalOperationStack与异步操作不兼容吗？

c#.netasync-await.net-4.5
19

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 操作都在调用时使用了 await，并且没有使用诸如 Task.WhenAll 的组合器）。
问题在于 LogicalOperationStack 存储在 CallContext 中，后者具有写时复制（copy-on-write）的行为。这意味着只要你不在 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中。完整的实现作为对此问题的答案提供：Tracking c#/.NET tasks flow 那么，LogicalOperationStack是否应该与async一起工作，这只是一个错误吗？LogicalOperationStack是否只适用于非async的环境？还是我漏掉了什么？

更新：使用Task.Delay似乎会引起混淆，因为它使用System.Threading.Timer，在内部捕获ExecutionContext。改用await Task.Yield();而不是await Task.Delay(100);可以使示例更易于理解。

1
可能是重复的问题：CorrelationManager.LogicalOperationStack与Parallel.For、Tasks、Threads等兼容吗？ - noseratio - open to work
同意，不是重复问题。你是否检查了在同一线程上它是否按预期工作，例如将 await Task.Delay(100) 替换为 Task.Delay(100).Wait()？ - noseratio - open to work
1
@downvoter，有什么问题吗？ - i3arnon
1
这是一个非常好的技术问题。也许，那个点踩者只是不理解这是关于什么的。 - noseratio - open to work
Stephen Cleary的相关博客文章，解释了逻辑调用上下文中可变数据的问题：https://blog.stephencleary.com/2013/04/implicit-async-context-asynclocal.html - Ohad Schneider
显示剩余6条评论
3个回答
13

是的，LogicalOperationStack 应该 能够与async-await一起使用，但它不支持是一个错误。

我已经联系了微软相关开发人员，并且他的回应如下:

"我对此并不知情，但似乎确实存在问题。拷贝写逻辑应该与我们真正进入方法时创建一个ExecutionContext 副本完全一致。然而，如果拷贝ExecutionContext，将会在CallContext.Clone()中特别处理的CorrelationManager上创建深层副本。我们没有考虑到这个问题。"

此外，他建议使用在.Net 4.6中新增的System.Threading.AsyncLocal<T>类，它可以正确地处理该问题。

因此，我使用VS2015 RC和.Net 4.6基于AsyncLocal而不是LogicalOperationStack实现了LogicalFlow：

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
我很好奇，你是如何联系到微软的相关开发人员的？Connect上的错误目前还没有得到微软的任何反馈。 - drowa
在.NET 4.5中是否有任何方法可以实现AsyncLocal行为？ - Filip Stas
1
@taras.roshko 是正确的，因为我创建了 AsyncLocal 一次，并在需要为每个异步流单独设置它的值时仅设置了一次。我已相应地更新了答案。 - i3arnon
1
@i3arnon，当在子操作中启动多个并行任务并创建它们自己的子操作时，您的LogicalFlow类是否能够正常运行？换句话说，这个类是线程安全的吗？ - Gebb
1
我不认为这个解决方案足够好。就像你在下面的评论中所说，需要进行深度克隆，否则几个线程最终会使用相同的（非线程安全的）堆栈。如果我做类似于 using (LogicalFlow.StartScope()) { Task.WaitAll(Task.Run(InnerOperationAsync), Task.Run(InnerOperationAsync)) } 这样的事情，所有3个线程（父线程和两个子线程）将具有相同的 Stack 实例（如我用 Object.ReferenceEquals 验证的那样）。然而，你在这里所做的应该可以很好地工作，因为它利用了深度复制：https://dev59.com/3WAf5IYBdhLWcg3wmzpL#24468972。 - Ohad Schneider
显示剩余3条评论
6
如果您仍然对此感兴趣，我认为这是他们在流动“LogicalOperationStack”时出现的错误，并且我认为报告它是一个好主意。
他们特别处理“LogicalOperationStack”的堆栈此处在“LogicalCallContext.Clone”中, 通过进行深度复制（与通过“CallContext.LogicalSetData / LogicalGetData”存储的其他数据不同，只执行浅层复制）。
每次调用“ExecutionContext.CreateCopy”或“ExecutionContext.CreateMutableCopy”来流动“ExecutionContext”时，都会调用此“LogicalCallContext.Clone”。
根据您的代码，我进行了一些实验，为“LogicalCallContext”中的“System.Diagnostics.Trace.CorrelationManagerSlot”插槽提供了自己的可变堆栈，以查看它何时以及被克隆了多少次。
代码：
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次。问题在于，由StartLogicalOperation/StopLogicalOperation调用的匹配Stack.Push和Stack.Pop操作在堆栈的不同、不匹配的克隆上操作，从而使“逻辑”堆栈失衡。这就是bug所在之处。

即使没有任务的并发分支，这确实使得LogicalOperationStack在异步调用中完全无法使用。

更新，我还进行了一些关于它在同步调用中可能如何行为的研究，以回应这些评论:

同意，不是重复的。你是否检查了它在同一线程上是否按预期工作，例如，如果你用Task.Delay(100).Wait()替换await Task.Delay(100)? - 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"));

    // ...
}

输出（注意我们失去了"value2"）：

0.1：MyStack Id=0，Count=0，在线程9上，顶部：
value1
将MyStack Id=0克隆到线程9中的1
0.2：MyStack Id=1，Count=0，在线程9上，顶部：
value2
0.3：MyStack Id=0，Count=0，在线程9上，顶部：
value1
Task.Delay 内部捕获了 ExecutionContext，所以你有 4 个克隆体并不奇怪。你可以使用 Task.Yield 来使它更容易理解。使用 Task.Yield，你只会得到预期的 2 个克隆体。正如我所描述的那样，问题在于由于“写时复制”的行为，你在不应该使用父上下文的情况下使用了它。在你的示例中，它表现为 2 个克隆体从同一个原始堆栈克隆而来。 - i3arnon
此外，你的 MyStack.Clone 没有正确地克隆栈，因为它每次都会反转。 - i3arnon
@i3arnon，确实存在一个错误，可以通过foreach(var item in this.ToArray().Reverse())进行修复。我认为这并不改变“Push”/“Pop”在此处操作不同堆栈副本的主要思想。我稍后会验证一下。 - noseratio - open to work
@i3arnon，我会说，首先它发生是因为他们在LogicalCallContext.Clone中特别对待“System.Diagnostics.Trace.CorrelationManagerSlot”数据槽进行深度克隆，而不像其他槽那样。我想他们这样做是为了支持任务分叉和多线程，但无论如何都不起作用。 - noseratio - open to work
不，如果没有进行深度克隆，只有堆栈的引用会被克隆，这将导致多个线程操作同一个非线程安全的“Stack”实例。即使只有一个线程，它在fork/join场景下仍然无法工作。在这种情况下，深度克隆比浅层克隆更好，而复制推送比写时复制更好。 - i3arnon
显示剩余2条评论
0

这里和网上提到的解决方案之一是在上下文中调用LogicalSetData：

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

但实际上，仅仅读取当前执行上下文就足够了：

var context = Thread.CurrentThread.ExecutionContext;
Trace.CorrelationManager.StartLogicalOperation();
网页内容由stack overflow 提供, 点击上面的
可以查看英文原文，
原文链接