Является LogicalOperationStack несовместимым с async в .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);
}
}
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
. В качестве ответа на этот вопрос доступна полная реализация: Отслеживание потока С#/.NET задач
Итак, должен ли LogicalOperationStack
работать с async
и это просто ошибка? Является ли LogicalOperationStack
просто не для мира async
? Или я что-то упускаю?
Обновление. Использование Task.Delay
, по-видимому, запутывается, поскольку использует System.Threading.Timer
, который захватывает ExecutionContext
внутренне. Использование await Task.Yield();
вместо await Task.Delay(100);
упрощает понимание примера.
Ответы
Ответ 1
Да, LogicalOperationStack
должен работать с async-await
, и это ошибка, которой это не делает.
Я связался с соответствующим разработчиком в Microsoft, и его ответ был следующим:
" Я не знал об этом, но он выглядит сломанным. Логика copy-on-write должна вести себя точно так, как если бы мы действительно создали копию ExecutionContext
при входе в метод. Однако копирование ExecutionContext
создало бы глубокую копию контекста CorrelationManager
, как это было в специальном обложке в CallContext.Clone()
. Мы не учитываем это при копировании -write logic."
Кроме того, он рекомендовал использовать новый класс 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
Ответ 2
Если вы все еще заинтересованы в этом, я считаю, что это ошибка в том, как они текут LogicalOperationStack
, и я думаю, что это хорошая идея сообщить об этом.
Они предоставляют специальную обработку LogicalOperationStack
stack здесь, в 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.Push
и Stack.Pop
(называемые StartLogicalOperation
/StopLogicalOperation
) работают с разными несогласованными клонами стека, что приводит к дисбалансу "логического" стека. То, где лежит ошибка.
Это действительно делает LogicalOperationStack
полностью непригодным для использования в асинхронных вызовах, даже если нет параллельных вилок задач.
Обновлено, я также немного исследовал, как он может вести себя для синхронных вызовов, адресовать эти комментарии:
Согласовано, а не обман. Вы проверяли, работает ли он так же, как и на том же нить, например. если вы замените задачу Task.Delay(100) на Task.Delay(100).Wait()? - Noseratio 27 февраля в 21:00
@Noseratio да. Это работает, конечно, потому что существует только один поток (и, следовательно, один CallContext). Как будто этот метод не был асинк для начала. - i3arnon 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, 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