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);
可以使示例更易于理解。
await Task.Delay(100)
替换为Task.Delay(100).Wait()
? - noseratio - open to work