LogicalOperationStack 是否与 .Net 4.5 中的异步不兼容 [英] Is LogicalOperationStack incompatible with async in .Net 4.5

问题描述

Trace.CorrelationManager.LogicalOperationStack 支持嵌套逻辑操作标识符，其中最常见的情况是日志记录 (NDC).它是否仍然适用于 async-await?

Trace.CorrelationManager.LogicalOperationStack enables having nested logical operation identifiers where the most common case is logging (NDC). Should it still work with async-await?

这是一个使用 LogicalFlow 的简单示例，它是我对 LogicalOperationStack 的简单包装:

Here's a simple example using LogicalFlow which is my simple wrapper over the LogicalOperationStack:

private static void Main() => OuterOperationAsync().GetAwaiter().GetResult();

private static async Task OuterOperationAsync()
{
    Console.WriteLine(LogicalFlow.CurrentOperationId);
    using (LogicalFlow.StartScope())
    {
        Console.WriteLine("	" + LogicalFlow.CurrentOperationId);
        await InnerOperationAsync();
        Console.WriteLine("	" + LogicalFlow.CurrentOperationId);
        await InnerOperationAsync();
        Console.WriteLine("	" + 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 值.

The specific values don't really matter, but as I understand it both the outer lines should show Guid.Empty (i.e. 00000000-0000-0000-0000-000000000000) and the inner lines should show the same Guid value.

您可能会说 LogicalOperationStack 使用了一个不是线程安全的 Stack，这就是输出错误的原因.但是，虽然这在一般情况下是正确的，但在这种情况下永远不会有超过一个线程同时访问 LogicalOperationStack(每个 async 操作都是调用时等待并且不使用组合子，例如 Task.WhenAll)

You might say that LogicalOperationStack is using a Stack which is not thread-safe and that's why the output is wrong. But while that's true in general, in this case there's never more than a single thread accessing the LogicalOperationStack at the same time (every async operation is awaited when called and no use of combinators such as Task.WhenAll)

问题在于 LogicalOperationStack 存储在具有写时复制行为的 CallContext 中.这意味着只要您没有在 CallContext 中显式设置某些内容(当您使用 StartLogicalOperation 添加到现有堆栈时也没有)，您正在使用父上下文而不是您自己的上下文.

The issue is that LogicalOperationStack is stored in the CallContext which has a copy-on-write behavior. That means that as long as you don't explicitly set something in the CallContext (and you don't when you add to an existing stack with StartLogicalOperation) you're using the parent context and not your own.

这可以通过在添加到现有堆栈之前简单地将 anything 设置到 CallContext 中来显示.例如，如果我们将 StartScope 更改为:

This can be shown by simply setting anything into the CallContext before adding to the existing stack. For example if we changed StartScope to this:

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 中.一个完整的实现可以作为这个问题的答案:跟踪 c#/.NET 任务流

Note: I'm not suggesting anyone actually do this. The real practical solution would be to use an ImmutableStack instead of the LogicalOperationStack as it's both thread-safe and since it's immutable when you call Pop you get back a new ImmutableStack that you then need to set back into the CallContext. A full implementation is available as an answer to this question: Tracking c#/.NET tasks flow

那么，LogicalOperationStack 是否应该与 async 一起使用，而这只是一个错误?LogicalOperationStack 难道不适合 async 世界吗?还是我遗漏了什么?

So, should LogicalOperationStack work with async and it's just a bug? Is LogicalOperationStack just not meant for the async world? Or am I missing something?

更新:使用 Task.Delay 显然令人困惑，因为它使用 System.Threading.Timer 其中 在内部捕获ExecutionContext.使用 await Task.Yield(); 而不是 await Task.Delay(100); 使示例更易于理解.

Update: Using Task.Delay is apparently confusing as it uses System.Threading.Timer which captures the ExecutionContext internally. Using await Task.Yield(); instead of await Task.Delay(100); makes the example easier to understand.

推荐答案

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

Yes, LogicalOperationStack should work with async-await and it is a bug that it doesn't.

我已经联系了 Microsoft 的相关开发人员，他的回复是这样的:

I've contacted the relevant developer at Microsoft and his response was this:

"我不知道这一点，但它看起来确实坏了.写时复制逻辑的行为应该与我们真正创建了 ExecutionContext 进入方法.但是，复制 ExecutionContext 会创建 CorrelationManager 上下文的深层副本，因为它在 CallContext.Clone().我们在写时复制逻辑中没有考虑到这一点."

"I wasn't aware of this, but it does seem broken. The copy-on-write logic is supposed to behave exactly as if we'd really created a copy of the ExecutionContext on entry into the method. However, copying the ExecutionContext would have created a deep copy of the CorrelationManager context, as it's special-cased in CallContext.Clone(). We don't take that into account in the copy-on-write logic."

此外，他建议使用新的System.Threading.AsyncLocal 在 .Net 4.6 中添加的类应该正确处理该问题.

Moreover, he recommended using the new System.Threading.AsyncLocal<T> class added in .Net 4.6 instead which should handle that issue correctly.

因此，我继续使用 VS2015 RC 和 .Net 4.6 在 AsyncLocal 而不是 LogicalOperationStack 之上实现了 LogicalFlow:

So, I went ahead and implemented LogicalFlow on top of an AsyncLocal instead of the LogicalOperationStack using VS2015 RC and .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();
}

同样测试的输出确实应该是这样的:

And the output for the same test is indeed as it should be:

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 是否与 .Net 4.5 中的异步不兼容的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！