My *_* Me 11 c# log4net multithreading threadpool
我试图找到一种从一堆线程中记录有用上下文的方法.问题是很多代码都是通过线程池线程到达的事件处理的(据我所知),因此它们的名称与任何上下文无关.可以使用以下代码演示此问题:
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个线程的有用信息的名称,除了手动将名称添加到消息(我想避免).如何在线程池线程的日志中获取名称/上下文,而无需在每次调用时将其添加到消息中,或者需要在每次回调中再次设置属性.
wag*_*ghe 15
更新:12/11/2014 - 请在此处查看我帖子的第一部分:
log4net.ThreadContext和log4net.LogicalThreadContext有什么区别？
最近的更新.Log4Net的LogicalThreadContext最近有所更新(在过去的几年里),现在它可以正常工作.链接帖子中的更新提供了一些细节.
结束更新.
Here is an idea that might help you. Part of the problem is that the log4net context objects (ThreadContext and LogicalThreadContext) do not "flow" their properties to "child" threads. LogicalThreadContext gives the false impression that it does, but it doesn't. Internally it uses CallContext.SetData to store its properties. Data set via SetData is attached TO THE THREAD, but it is NOT "inherited" by child threads. So, if you set a property via like this:
log4net.LogicalThreadContext.Properties["myprop"] = "abc";
That property will be loggable via the %property pattern converter and will contain a value when logging from the same thread where you set the property in the first place, but it will not contain a value in any child threads that are spawned from that thread.
如果您可以通过CallContext.LogicalSetData保存属性(请参阅上面的链接),那么属性将"流"到任何子线程(或由其继承).所以,如果你能做到这样的事情:
CallContext.LogicalSetData("MyLogicalData", nameStr + Thread.CurrentThread.ManagedThreadId);
然后,"MyLogicalData"将在您设置它的线程以及任何子线程中可用.
有关使用CallContext.LogicalSetData的更多信息,请参阅Jeffrey Richter撰写的此博客文章.
您可以通过CallContext.LogicalSetData轻松存储您自己的信息,并通过编写自己的PatternLayoutConverter使其可以通过log4net进行记录.我已经为两个新的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
When I did this test (and some other testing I have been working on), I created my own "context" stack object (similar to log4net's "stack" implementation) by storing my Stack via CallContext.LogicalSetData rather than via CallContext.SetData (which is how log4net stores it). I found that my stack got jumbled up when I had several ThreadPool threads. Maybe it was from merging the data back to the parent context when the child context exited. I would not have thought that would be the case as in my test I explicitly pushed the new value on entry to the ThreadPool thread and popped it on exit. A similar test with a Trace.CorrelationManager.LogicalOperationStack-based implementation (I wrote an abstraction over it) seemed to behave correctly. I guess that maybe the automatic flowing (down AND back) logic is accounting for CorrelationManager since it is a "known" object in the system???
输出中需要注意的一些事项:
Trace.CorrelationManager信息通过CallContext.LogicalSetData存储,因此它"流动"到子线程.TestThis使用Trace.CorrelationManager.StartLogicalOperation将逻辑操作(以传入的名称命名)"推送"到LogicalOperationStack上.ThreadPool线程中的第一个logger.Debug语句显示ThreadPool线程继承了与父线程相同的LogicalOperationStack.在ThreadPool线程内部,我启动一个新的逻辑操作,它被堆叠到继承的LogicalOperationStack上.您可以在第二个logger.Debug输出中看到该结果.最后,在离开之前,我停止了逻辑操作.第三个logger.Debug输出显示.
从输出中可以看出,CallContext.LogicalSetData也"流向"子线程.在我的测试代码中,我选择在ThreadPool线程内的LogicalSetData中设置一个新值,然后在离开之前将其清理(FreeNamedDataSlot).
您可以随意尝试这些模式布局转换器,看看您是否可以获得所需的结果.正如我已经演示的那样,您至少应该能够在日志记录输出中反映哪些ThreadPool线程由哪些其他(父？)线程启动/使用.
请注意,即使在某些环境中使用CallContext.LogicalSetData也存在一些问题:
"子"逻辑数据被合并回"父"逻辑数据: EndInvoke更改当前的CallContext - 为什么？
(Not an issue, but a good post about Trace.CorrelationManager.ActivityId and Task Parallel Library):
How do Tasks in the Task Parallel Library affect ActivityID?
An oft-linked blog posting about problems with various "context" storage mechanisms in the context of ASP.Net
http://piers7.blogspot.com/2005/11/threadstatic-callcontext-and_02.html
[EDIT]
I have found that maintaining the correct context while heavily (or maybe even not so heavily - my test executes DoLongRunningWork using various Thread/Task/Parallel techniques) using threads can throw some data set with CallContext.LogicalSetData out of whack.
See this question about using Trace.CorrelationManager.ActivityId here on StackOverflow. I posted an answer about using Trace.CorrelationManager.LogicalOperationStack and some of my observations.
Later I used my answer to that question as the basis for my own question about using Trace.CorrelationManager.LogicalOperationStack in the context of Threads/Tasks/Parallel.
I also posted a very similar question on Microsoft's Parallel Extensions forum.
You can read those posts see my observations. To summarize briefly:
With a code pattern like this:
DoLongRunningWork //Kicked off as a Thread/Task/Parallel(.For or .Invoke)
StartLogicalOperation
Sleep(3000) //Or do actual work
StopLogicalOperation
The contents of the LogicalOperationStack remain consistent whether DoLongRunningWork is kicked off by explicit Thread/ThreadPool threads/Tasks/Parallel(.For or .Invoke).
With a code pattern like this:
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
The contents of the LogicalOperationStack remain consistent EXCEPT when DoLongRunningWork is kicked off by Parallel.For or Parallel.Invoke. The reason seems to be related to the fact that Parallel.For and Parallel.Invoke use the main thread as one of the threads to execute the parallel operations.
That means that if you want to enclose the entire parallelized (or threaded) operation as a single logical operation and each iteration (i.e. each invocation of the delegate) as a logical operation nested within the outer operation, most techiques that I tested (Thread/ThreadPool/Task) work correctly. At each iteration, the LogicalOperationStack reflects that there is an outer task (for the main thread) and an inner task (the delegate).
If you use Parallel.For or Parallel.Invoke, the LogicalOperationStack does not work correctly. In the sample code in the posts that linked above, the LogicalOperationStack should never have more than 2 entries. One for the main thread and one for the delegate. When using Parallel.For or Parallel.Invoke the LogicalOperationStack will eventually get many more than 2 entries.
Using CallContext.LogicalSetData fares even worse (at least if trying to emulate LogicalOperationStack by storing a Stack with LogicalSetData). With a similar call pattern as above (the one with the enclosing logical operation as well as the delegate logical operation), a Stack stored with LogicalSetData and maintained identically (as far as I can tell) will get corrupted in almost all cases.
CallContext.LogicalSetData might work better for simpler types or for types that are not modified within the "logical thread". If I were to store a dictionary of values with LogicalSetData (similar to log4net.LogicalThreadContext.Properties), it would probably be inherited successfully by child threads/Tasks/etc.
I don't have any great explanations for exactly why this is happening or the best way to work around it. It might be that the way I was testing "context" went a little overboard, or it might not.
If you do look into this some more, you might try out the test programs that I posted in the links above. The test programs only test the LogicalOperationStack. I have performed similar tests with more complicated code by making a context abstraction that supports an interface like IContextStack. One implementation uses a Stack stored via CallContext.LogicalSetData (similar to how log4net's LogicalThreadContext.Stacks is stored, except that I used LogicalSetData rather than SetData). The other implementation implements that interface over Trace.CorrelationManager.LogicalOperationStack. That makes it easy for me to run the same tests with different context implementations.
Here is my IContextStack interface:
public interface IContextStack
{
IDisposable Push(object item);
object Pop();
object Peek();
void Clear();
int Count { get; }
IEnumerable<object> Items { get; }
}
Here is the LogicalOperationStack-based implementaiton:
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
}
Here is the CallContext.LogicalSetData-based implementation:
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
}
Here is the StackPopper used by both:
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
}
It's a lot to digest, but maybe you will find some of this useful!
log4net 中的上下文信息是针对每个线程的，因此每次启动新线程时，都必须向其中添加上下文信息。您可以使用属性，也可以使用 NDC。NDC 也是针对每个线程的，因此您仍然需要在某个时刻将其添加到每个线程的上下文中，这可能是也可能不是您正在寻找的内容。不过，它可以让您免于将其添加到消息本身中。在你的例子中，它会是这样的：
ThreadPool.QueueUserWorkItem(x => NDC.Push("nameStr")); log.Debug("From threadpool Thread: " + nameStr));
这是NDC 文档的链接。
总而言之，效果与使用属性类似，就像示例中的效果一样。唯一的区别是 NDC 可以堆叠，以便每次将值压入堆栈时，它都会连接到消息。它还支持 using 语句，这使得代码更清晰。
| 归档时间： |
|
| 查看次数： |
10848 次 |
| 最近记录： |