Как правильно настроить контекст с потоками Threadpool с помощью log4net?

Я пытаюсь найти способ записи полезного контекста из кучи потоков. Проблема в том, что большое количество кода рассматривается в событиях, которые поступают через потоки threadpool (насколько я могу судить), поэтому их имена не относятся к какому-либо контексту. Проблема может быть продемонстрирована с помощью следующего кода:

Как вы можете видеть, последние две строки не имеют имен полезной информации, чтобы отличать 2 потока, кроме как вручную добавлять имя в сообщение (чего я хочу избежать). Как я могу получить имя/контекст в журнал для потоков threadpool, не добавляя его в сообщение при каждом вызове или не нуждаясь в том, чтобы снова установить свойство в каждом обратном вызове.

Ответы

Ответ 1

Контекстная информация в log4net соответствует потоку, поэтому каждый раз, когда вы начинаете новый поток, вы должны добавить к нему свою контекстную информацию. Вы можете использовать свойства, или вы можете использовать NDC. НДЦ тоже за потоком, поэтому в какой-то момент вам все равно придется добавлять его в каждый контекст потока, что может быть или не быть тем, что вы ищете. Это избавит вас от добавления его к самому сообщению. В вашем примере это будет примерно так:

ThreadPool.QueueUserWorkItem(x => NDC.Push("nameStr")); log.Debug("From threadpool Thread: " + nameStr));

Здесь ссылка на документация для NDC.

В целом эффект похож на использование свойств, как и то, что у вас есть в вашем примере. Единственное отличие состоит в том, что NDC может быть сложена так, что каждый раз, когда вы нажимаете значение в стеке, он будет конкатенироваться с сообщением. Он также поддерживает инструкцию using, которая обеспечивает более чистый код.

Ответ 2

UPDATE: 12/11/2014 - Посмотрите первую часть моего сообщения здесь:

В чем разница между log4net.ThreadContext и log4net.LogicalThreadContext?

для недавнего обновления. Log4Net LogicalThreadContext был обновлен несколько недавно (за последние пару лет), чтобы он работал правильно. Обновленный в связанном сообщении дает некоторые подробности.

END UPDATE.

Вот идея, которая может вам помочь. Отчасти проблема заключается в том, что объекты контекста log4net (ThreadContext и LogicalThreadContext) не "текут" их свойства в "дочерние" потоки. LogicalThreadContext дает ложное впечатление, что он это делает, но это не так. Внутри он использует CallContext.SetData для сохранения своих свойств. Набор данных через SetData присоединен к НИТИ, но он НЕ "унаследован" дочерними потоками. Итак, если вы установите свойство следующим образом:

log4net.LogicalThreadContext.Properties["myprop"] = "abc";

Это свойство будет регистрироваться через конвертер шаблонов свойств% и будет содержать значение при регистрации из того же потока, в котором вы задали свойство в первую очередь, но оно не будет содержать значения ни в каких дочерних потоках, которые порождены из этот поток.

Если вы можете сохранить свои свойства с помощью CallContext.LogicalSetData(см. ссылку выше), тогда свойства "текут" (или унаследованы) любыми дочерними потоками. Итак, если вы можете сделать что-то вроде этого:

CallContext.LogicalSetData("MyLogicalData", nameStr + Thread.CurrentThread.ManagedThreadId);

Тогда "MyLogicalData" будет доступен в потоке, где вы его устанавливаете, а также в любых дочерних потоках.

См. эту запись в блоге Джеффри Рихтера для получения дополнительной информации об использовании CallContext.LogicalSetData.

Вы можете легко хранить свою информацию через CallContext.LogicalSetData И иметь ее доступную для ведения журнала по log4net, написав собственный PatternLayoutConverter. Я приложил несколько примеров кода для двух новых PatternLayoutConverters.

Первый позволяет вам регистрировать информацию, хранящуюся в Trace.CorrelationManager LogicalOperationStack. Конвертер компоновки позволяет вам регистрировать вершину LogicalOperationStack или весь LogicalOperationStack.

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;

using log4net;
using log4net.Util;
using log4net.Layout.Pattern;

using log4net.Core;

using System.Diagnostics;

namespace Log4NetTest
{
  class LogicalOperationStackPatternConverter : PatternLayoutConverter
  {
    protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
    {
      string los = "";

      if (String.IsNullOrWhiteSpace(Option) || String.Compare(Option.Substring(0, 1), "A", true) == 0)
      {
        //Log ALL of stack
        los = Trace.CorrelationManager.LogicalOperationStack.Count > 0 ? 
                string.Join(">>",Trace.CorrelationManager.LogicalOperationStack.ToArray()) :
                "";
      }
      else
      if (String.Compare(Option.Substring(0, 1), "T", true) == 0)
      {
        //Log TOP of stack
        los = Trace.CorrelationManager.LogicalOperationStack.Count > 0 ?
                Trace.CorrelationManager.LogicalOperationStack.Peek().ToString() : "";
      }

      writer.Write(los);
    }
  }
}

Второй способ позволяет регистрировать информацию, хранящуюся по CallContext.LogicalSetData. Как написано, он извлекает значение, используя CallContext.LogicalGetData, используя фиксированное имя. Его можно легко изменить, чтобы использовать свойство "Параметры" (как показано в конвертере LogicalOperationStack), чтобы указать конкретное значение, которое нужно вытащить, используя CallContext.LogicalGetData.

using log4net;
using log4net.Util;
using log4net.Layout.Pattern;

using log4net.Core;

using System.Runtime.Remoting.Messaging;

namespace Log4NetTest
{
  class LogicalCallContextPatternConverter : PatternLayoutConverter
  {
    protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
    {
      string output = "";
      object value = CallContext.LogicalGetData("MyLogicalData");
      if (value == null)
      {
        output = "";
      }
      else
      {
        output = value.ToString();
      }

      writer.Write(output);
    }
  }
}

Вот как настроить:

  <layout type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%d [%t] %logger %-5p [PROP = %property] [LOS.All = %LOS{a}] [LOS.Top = %LOS{t}] [LCC = %LCC] %m%n"/>
    <converter>
      <name value="LOS" />
      <type value="Log4NetTest.LogicalOperationStackPatternConverter" />
    </converter>
    <converter>
      <name value="LCC" />
      <type value="Log4NetTest.LogicalCallContextPatternConverter" />
    </converter>
  </layout>

Вот мой тестовый код:

  //Start the threads
  new Thread(TestThis).Start("ThreadA");
  new Thread(TestThis).Start("ThreadB");


  //Execute this code in the threads
private static void TestThis(object name)
{
  var nameStr = (string)name;
  Thread.CurrentThread.Name = nameStr;
  log4net.ThreadContext.Properties["ThreadContext"] = nameStr;
  log4net.LogicalThreadContext.Properties["LogicalThreadContext"] = nameStr;

  CallContext.LogicalSetData("MyLogicalData", nameStr + Thread.CurrentThread.ManagedThreadId);

  Trace.CorrelationManager.StartLogicalOperation(nameStr + Thread.CurrentThread.ManagedThreadId);

  logger.Debug("From Thread itself");
  ThreadPool.QueueUserWorkItem(x => 
    {
      logger.Debug("From threadpool Thread_1: " + nameStr);

      Trace.CorrelationManager.StartLogicalOperation(nameStr + Thread.CurrentThread.ManagedThreadId);
      CallContext.LogicalSetData("MyLogicalData", nameStr + Thread.CurrentThread.ManagedThreadId);

      logger.Debug("From threadpool Thread_2: " + nameStr);

      CallContext.FreeNamedDataSlot("MyLogicalData");
      Trace.CorrelationManager.StopLogicalOperation();

      logger.Debug("From threadpool Thread_3: " + nameStr);
    });
}

Вот результат:

Form1: 2011-01-14 09:18:53,145 [ThreadA] Form1 DEBUG [PROP = {LogicalThreadContext=ThreadA, log4net:HostName=WILLIE620, ThreadContext=ThreadA}] [LOS.All = ThreadA10] [LOS.Top = ThreadA10] [LCC = ThreadA10] From Thread itself
Form1: 2011-01-14 09:18:53,160 [ThreadB] Form1 DEBUG [PROP = {LogicalThreadContext=ThreadB, log4net:HostName=WILLIE620, ThreadContext=ThreadB}] [LOS.All = ThreadB11] [LOS.Top = ThreadB11] [LCC = ThreadB11] From Thread itself
Form1: 2011-01-14 09:18:53,192 [12] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadB11] [LOS.Top = ThreadB11] [LCC = ThreadB11] From threadpool Thread_1: ThreadB
Form1: 2011-01-14 09:18:53,207 [12] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadB12>>ThreadB11] [LOS.Top = ThreadB12] [LCC = ThreadB12] From threadpool Thread_2: ThreadB
Form1: 2011-01-14 09:18:53,207 [12] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadB11] [LOS.Top = ThreadB11] [LCC = ] From threadpool Thread_3: ThreadB
Form1: 2011-01-14 09:18:53,207 [13] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadA10] [LOS.Top = ThreadA10] [LCC = ThreadA10] From threadpool Thread_1: ThreadA
Form1: 2011-01-14 09:18:53,223 [13] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadA13>>ThreadA10] [LOS.Top = ThreadA13] [LCC = ThreadA13] From threadpool Thread_2: ThreadA
Form1: 2011-01-14 09:18:53,223 [13] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadA10] [LOS.Top = ThreadA10] [LCC = ] From threadpool Thread_3: ThreadA

Когда я выполнил этот тест (и некоторое другое тестирование, над которым я работал), я создал свой собственный объект стека контекста (аналогичный реализации стека log4net), сохранив мой стек через CallContext.LogicalSetData, а не через CallContext.SetData(это то, как log4net хранит его). Я обнаружил, что мой стек перепутался, когда у меня было несколько потоков ThreadPool. Возможно, это было из объединения данных обратно в родительский контекст, когда дочерний контекст вышел. Я бы не подумал, что это будет так, как в моем тесте я явно ввел новое значение при входе в поток ThreadPool и вытащил его при выходе. Подобный тест с реализацией Trace.CorrelationManager.LogicalOperationStack(я написал абстракцию над ним), похоже, правильно себя ведет. Я полагаю, что, возможно, автоматическая потоковая логика (вниз и назад) учитывает CorrelationManager, поскольку она является "известным" объектом в системе.

Некоторые примечания в выводе:

Информационная информация Trace.CorrelationManager хранится через CallContext.LogicalSetData, поэтому она "текут" к дочерним потокам. TestThis использует Trace.CorrelationManager.StartLogicalOperation, чтобы "нажать" логическую операцию (названную для переданного имени) на LogicalOperationStack. Первый оператор logger.Debug в потоке ThreadPool показывает, что поток ThreadPool наследовал тот же LogicalOperationStack, что и родительский поток. Внутри потока ThreadPool я запускаю новую логическую операцию, которая укладывается в унаследованный LogicalOperationStack. Вы можете увидеть результат этого во втором выходе logger.Debug. Наконец, перед отъездом я прекращаю логическую операцию. Третий вывод logger.Debug показывает, что.
Как видно из вывода, CallContext.LogicalSetData также "текут" к дочерним потокам. В моем тестовом коде я решил установить новое значение в LogicalSetData внутри потока ThreadPool, а затем очистить его перед отъездом (FreeNamedDataSlot).

Не стесняйтесь попробовать эти шаблонные конвертеры шаблонов и посмотреть, сможете ли вы достичь результатов, которые вы ищете. Как я уже продемонстрировал, вы должны, по крайней мере, иметь возможность отразить в своем выходе журнала, какие потоки ThreadPool были запущены/использованы другими потоками (родительскими?).

Заметьте, что есть некоторые проблемы даже с CallContext.LogicalSetData в определенных средах:

"Ребенок" логические данные снова объединяются в "Родительские" логические данные: EndInvoke меняет текущий CallContext - почему?

Трассировка вложенных многопоточных операций

(Не проблема, но хорошая статья о Trace.CorrelationManager.ActivityId и параллельной библиотеке задач):

Как задачи в параллельной библиотеке задач влияют на ActivityID?

Связанная с блогами публикация сообщений о проблемах с различными "контекстными" механизмами хранения в контексте ASP.Net.

http://piers7.blogspot.com/2005/11/threadstatic-callcontext-and_02.html

[EDIT]

Я обнаружил, что поддерживая правильный контекст в значительной степени (или, может быть, даже не так сильно), мой тест выполняет DoLongRunningWork с использованием различных методов Thread/Task/Parallel), используя потоки, может бросать некоторые данные с CallContext.LogicalSetData из-под удара.

Смотрите этот вопрос об использовании Trace.CorrelationManager.ActivityId здесь, в StackOverflow. Я отправил ответ об использовании Trace.CorrelationManager.LogicalOperationStack и некоторых моих замечаний.

Позже я использовал свой ответ на этот вопрос в качестве основы для моего собственного вопроса об использовании Trace.CorrelationManager.LogicalOperationStack в контексте Threads/Tasks/Parallel.

Я также разместил очень похожий вопрос на форуме Microsoft Parallel Extensions.

Вы можете прочитать эти сообщения в моих наблюдениях. Кратко кратко:

С таким шаблоном кода:

DoLongRunningWork //Kicked off as a Thread/Task/Parallel(.For or .Invoke)
  StartLogicalOperation
  Sleep(3000) //Or do actual work
  StopLogicalOperation

Содержимое LogicalOperationStack остается неизменным, если DoLongRunningWork запускается явным потоком Thread/ThreadPool/Tasks/Parallel (.For или .Invoke).

С таким шаблоном кода:

StartLogicalOperation //In Main thread (or parent thread)
  DoLongRunningWork   //Kicked off as a Thread/Task/Parallel(.For or .Invoke)
    StartLogicalOperation
    Sleep(3000) //Or do actual work
    StopLogicalOperation
StopLogicalOperation

Содержимое LogicalOperationStack остается неизменным ИСКЛЮЧЕНИЕ, когда DoLongRunningWork запускается Parallel.For или Parallel.Invoke. Причина, по-видимому, связана с тем, что Parallel.For и Parallel.Invoke используют основной поток как один из потоков для выполнения параллельных операций.

Это означает, что если вы хотите заключить всю параллельную (или поточную) операцию как единую логическую операцию и каждую итерацию (т.е. каждый вызов делегата) в качестве логической операции, вложенной в внешнюю операцию, большинство техник, которые я тестировал (Thread/ThreadPool/Task) работают правильно. На каждой итерации LogicalOperationStack отражает, что есть внешняя задача (для основного потока) и внутренняя задача (делегат).

Если вы используете Parallel.For или Parallel.Invoke, LogicalOperationStack работает некорректно. В примере кода в сообщениях, которые были связаны выше, LogicalOperationStack никогда не должен иметь более двух записей. Один для основного потока и один для делегата. При использовании Parallel.For или Parallel.Invoke в LogicalOperationStack в конечном итоге будет добавлено более 2 записей.

Использование CallContext.LogicalSetData еще хуже (по крайней мере, при попытке эмуляции LogicalOperationStack путем хранения стека с помощью LogicalSetData). С аналогичным шаблоном вызова, как указано выше (с включенной логической операцией, а также с логической операцией делегата), Stack, хранящийся в LogicalSetData и поддерживаемый одинаково (насколько я могу судить), будет поврежден почти во всех случаях.

CallContext.LogicalSetData может работать лучше для более простых типов или для типов, которые не изменяются в "логическом потоке". Если бы я должен был хранить словарь значений с помощью LogicalSetData (аналогично log4net.LogicalThreadContext.Properties), он, вероятно, был бы унаследован дочерними потоками/Задачами и т.д.

У меня нет никаких больших объяснений, почему именно это происходит или лучший способ обойти его. Возможно, способ, которым я тестировал "контекст", немного завышен, или это может быть не так.

Если вы посмотрите на это еще немного, вы можете попробовать тестовые программы, которые я опубликовал в ссылках выше. Тест-программы проверяют только LogicalOperationStack. Я выполнил аналогичные тесты с более сложным кодом, создав абстракцию контекста, поддерживающую интерфейс, такой как IContextStack. Одна реализация использует стек, хранящийся через CallContext.LogicalSetData(аналогично тому, как log4net LogicalThreadContext.Stacks хранится, за исключением того, что я использовал LogicalSetData, а не SetData). Другая реализация реализует этот интерфейс через Trace.CorrelationManager.LogicalOperationStack. Это позволяет мне запускать те же тесты с различными реализациями контекста.

Вот мой интерфейс IContextStack:

  public interface IContextStack
  {
    IDisposable Push(object item);
    object Pop();
    object Peek();
    void Clear();
    int Count { get; }
    IEnumerable<object> Items { get; }
  }

Вот пример реализации на основе LogicalOperationStack:

  class CorrelationManagerStack : IContextStack, IEnumerable<object>
  {
    #region IContextStack Members

    public IDisposable Push(object item)
    {
      Trace.CorrelationManager.StartLogicalOperation(item);

      return new StackPopper(Count - 1, this);
    }

    public object Pop()
    {
      object operation = null;

      if (Count > 0)
      {
        operation = Peek();
        Trace.CorrelationManager.StopLogicalOperation();
      }

      return operation;
    }

    public object Peek()
    {
      object operation = null;

      if (Count > 0)
      {
        operation = Trace.CorrelationManager.LogicalOperationStack.Peek();
      }

      return operation;
    }

    public void Clear()
    {
      Trace.CorrelationManager.LogicalOperationStack.Clear();
    }

    public int Count
    {
      get { return Trace.CorrelationManager.LogicalOperationStack.Count; }
    }

    public IEnumerable<object> Items
    {
      get { return Trace.CorrelationManager.LogicalOperationStack.ToArray(); }
    }

    #endregion

    #region IEnumerable<object> Members

    public IEnumerator<object> GetEnumerator()
    {
      return (IEnumerator<object>)(Trace.CorrelationManager.LogicalOperationStack.ToArray().GetEnumerator());
    }

    #endregion

    #region IEnumerable Members

    System.Collections.IEnumerator System.Collections.IEnumerable.GetEnumerator()
    {
      return Trace.CorrelationManager.LogicalOperationStack.ToArray().GetEnumerator();
    }

    #endregion

  }

Вот реализация на основе CallContext.LogicalSetData:

  class ThreadStack : IContextStack, IEnumerable<object>
  {
    const string slot = "EGFContext.ThreadContextStack";

    private static Stack<object> GetThreadStack
    {
      get
      {
        Stack<object> stack = CallContext.LogicalGetData(slot) as Stack<object>;
        if (stack == null)
        {
          stack = new Stack<object>();
          CallContext.LogicalSetData(slot, stack);
        }
        return stack;
      }
    }

    #region IContextStack Members

    public IDisposable Push(object item)
    {
      Stack<object> s = GetThreadStack;
      int prevCount = s.Count;
      GetThreadStack.Push(item);

      return new StackPopper(prevCount, this);
    }

    public object Pop()
    {
      object top = GetThreadStack.Pop();

      if (GetThreadStack.Count == 0)
      {
        CallContext.FreeNamedDataSlot(slot);
      }

      return top;
    }

    public object Peek()
    {
      return Count > 0 ? GetThreadStack.Peek() : null;
    }

    public void Clear()
    {
      GetThreadStack.Clear();

      CallContext.FreeNamedDataSlot(slot);
    }

    public int Count { get { return GetThreadStack.Count; } }

    public IEnumerable<object> Items 
    { 
      get
      {
        return GetThreadStack;
      }
    }

    #endregion

    #region IEnumerable<object> Members

    public IEnumerator<object> GetEnumerator()
    {
      return GetThreadStack.GetEnumerator();
    }

    #endregion

    #region IEnumerable Members

    System.Collections.IEnumerator System.Collections.IEnumerable.GetEnumerator()
    {
      return GetThreadStack.GetEnumerator();
    }

    #endregion
  }

Вот StackPopper, используемый обоими:

  internal class StackPopper : IDisposable
  {
    int pc;
    IContextStack st;

    public StackPopper(int prevCount, IContextStack stack)
    {
      pc = prevCount;
      st = stack;
    }

    #region IDisposable Members

    public void Dispose()
    {
      while (st.Count > pc)
      {
        st.Pop();
      }
    }

    #endregion
  }

Это много, чтобы переварить, но, может быть, вы найдете некоторые из этих полезных!

Ответ 4

Один вариант вместо одного статического экземпляра журнала, вы можете создать его для каждого потока, пометив его атрибутом ThreadStatic и инициализации в getter. Затем вы можете добавить свой контекст в журнал, и он будет применен к каждой записи журнала после установки контекста.

[ThreadStatic]
static readonly log4net.ILog _log;

static string log {
   get {
     if (null == _log) {
         _log = log4net.LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
     }
     return _log;
   }
}

Тем не менее, вам все равно придется задавать контекст в каждом потоке. Для этого я рекомендую абстрагировать создание ваших регистраторов. Используйте метод factory и требуйте вызова CreateLogger() для извлечения экземпляра регистратора. Внутри factory используйте ThreadStatic и установите свойство ThreadContext при инициализации регистратора.

Для этого требуется небольшая модификация кода, но не тонна.

Более сложным вариантом является использование инфраструктуры AOP (Aspect Oriented Programming), такой как LinFu, чтобы ввести желаемое поведение ведения журнала извне.

Как правильно настроить контекст с потоками Threadpool с помощью log4net?

Ответы

Ответ 1

Ответ 2

Ответ 3

Ответ 4