Как записать правильный контекст с потоками Threadpool, используя log4net? - PullRequest
Новая
       22

Как записать правильный контекст с потоками Threadpool, используя log4net?

11 голосов
/ 21 мая 2010

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

class Program
{
    private static readonly log4net.ILog log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);
    static void Main(string[] args)
    {
        new Thread(TestThis).Start("ThreadA");
        new Thread(TestThis).Start("ThreadB");
        Console.ReadLine();
    }

    private static void TestThis(object name)
    {
        var nameStr = (string)name;
        Thread.CurrentThread.Name = nameStr;
        log4net.ThreadContext.Properties["ThreadContext"] = nameStr;
        log4net.LogicalThreadContext.Properties["LogicalThreadContext"] = nameStr;
        log.Debug("From Thread itself");
        ThreadPool.QueueUserWorkItem(x => log.Debug("From threadpool Thread: " + nameStr));
    }
}

Шаблон преобразования: 

%date [%thread] %-5level %logger [%property] - %message%newline

Вывод выглядит так: 

2010-05-21 15:08:02,357 [ThreadA] DEBUG LogicalContextTest.Program [{LogicalThreadContext=ThreadA, log4net:HostName=xxx, ThreadContext=ThreadA}] - From Thread itself
2010-05-21 15:08:02,357 [ThreadB] DEBUG LogicalContextTest.Program [{LogicalThreadContext=ThreadB, log4net:HostName=xxx, ThreadContext=ThreadB}] - From Thread itself
2010-05-21 15:08:02,404 [7] DEBUG LogicalContextTest.Program [{log4net:HostName=xxx}] - From threadpool Thread: ThreadA
2010-05-21 15:08:02,420 [16] DEBUG LogicalContextTest.Program [{log4net:HostName=xxx}] - From threadpool Thread: ThreadB

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

Ответы [ 4 ]

15 голосов
/ 14 января 2011

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

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

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

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, используя фиксированное имя. Его можно легко изменить, используя свойство Options (как показано в конвертере 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

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

Некоторые вещи, которые нужно отметить в выводе:

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

  2. Как видно из выходных данных, CallContext.LogicalSetData также «передается» дочерним потокам. В своем тестовом коде я решил установить новое значение в LogicalSetData внутри потока ThreadPool, а затем очистить его перед выходом (FreeNamedDataSlot).

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

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

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

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

(Не проблема, но хороший пост о Trace.CorrelationManager.ActivityId и Task Parallel Library):

Как задачи в параллельной библиотеке задач влияют на 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 никогда не должно быть более 2 записей. Один для основного потока и один для делегата. При использовании Parallel.For или Parallel.Invoke LogicalOperationStack в конечном итоге получит намного больше 2 записей.

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

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

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

Если вы посмотрите подробнее, вы можете попробовать тестовые программы, которые я разместил по ссылкам выше. Тестовые программы проверяют только LogicalOperationStack. Я выполнил аналогичные тесты с более сложным кодом, создав абстракцию контекста, которая поддерживает такой интерфейс, как IContextStack. В одной реализации используется стек, сохраненный с помощью CallContext.LogicalSetData (аналогично тому, как хранится LogicalThreadContext.Stacks в log4net, за исключением того, что я использовал 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
  }

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

2 голосов
/ 22 мая 2010

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

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

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

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

0 голосов
/ 27 мая 2010

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

[ThreadStatic]
static readonly log4net.ILog _log;

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

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

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

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

0 голосов
/ 27 мая 2010

Из моего pov единственной возможностью было бы изменить создание потоков внутри модулей, так как в противном случае вы не можете добавить какой-либо соответствующий контекст.
Если вы можете изменить код, то вы создадите класс, который унаследует от используемого класса System.Threading (например, Thread в вашем примере) и вызовет суперкласс и добавит соответствующий контекст ведения журнала.
Возможны и другие приемы, но это будет чистый подход без каких-либо грязных приемов.

...