在.NET 4.5中,LogicalOperationStack与异步不兼容吗?

内容来源于 Stack Overflow,并遵循CC BY-SA 3.0许可协议进行翻译与使用

  • 回答 (2)
  • 关注 (0)
  • 查看 (37)

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

所以,应该和它LogicalOperationStack一起工作,async这只是一个错误?LogicalOperationStack仅仅是不适合async世界?或者我错过了什么?

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

提问于
用户回答回答于

是的,LogicalOperationStack 应该async-await一起工作,它不是一个错误。

我已经联系了微软的相关开发人员,他的回复是:

我当时没有意识到这一点,但它似乎打破。在写入时复制逻辑应该表现得完全一样,如果我们真想创建的副本ExecutionContext在进入方法,但是,复制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();
}

同样的测试结果的确如它应该的那样:

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
用户回答回答于

如果仍然对此感兴趣,我认为这是它们流动的一个错误LogicalOperationStack,我认为报告它是个好主意。

他们给予特殊待遇LogicalOperationStack的堆栈在这里 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.PushStack.Pop操作(由StartLogicalOperation/ 调用StopLogicalOperation)在堆栈的不同的,不匹配的克隆上操作,从而使“逻辑”堆栈失去平衡。这就是错误所在的地方。

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

我也做了一些关于它如何表现同步调用的研究:

同意,不是骗局。你有没有检查它是否按预期在同一个线程上工作,例如,如果用Task.Delay(100).Wait()替换正在等待Task.Delay(100)? - 是的。它当然是有效的,因为只有一个线程(以及一个CallContext)。就好像该方法不是开始时的异步。

单线并不意味着单一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

扫码关注云+社区