更新:
2014年12月11日 - 请参阅我在此处发布的第一部分内容:
log4net.ThreadContext和log4net.LogicalThreadContext之间有什么区别?
最近(在过去的几年中),Log4Net的LogicalThreadContext已经进行了更新,以便它现在可以正常工作。链接帖子中的更新提供了一些详细信息。
END UPDATE.
这里有一个可能会对您有所帮助的想法。问题的一部分是log4net上下文对象(ThreadContext和LogicalThreadContext)不会将其属性“流动”到“子”线程。LogicalThreadContext给出了它能够这样做的错误印象,但实际上并没有。它在内部使用CallContext.SetData来存储其属性。通过SetData设置的数据附加到线程,但不会被子线程“继承”。因此,如果您像这样设置属性:
log4net.LogicalThreadContext.Properties["myprop"] = "abc"
该属性可以通过%property模式转换器进行记录,并且在从设置该属性的同一线程记录时将包含一个值,但是在从该线程生成的任何子线程中都不会包含值。
如果您可以通过CallContext.LogicalSetData(请参见上面的链接)保存属性,则这些属性会“流动”到(或被继承到)任何子线程。因此,如果您可以执行以下操作:
CallContext.LogicalSetData("MyLogicalData", nameStr + Thread.CurrentThread.ManagedThreadId);
那么,“MyLogicalData”将在您设置它的线程以及任何子线程中都可用。
有关使用CallContext.LogicalSetData的更多信息,请参见这篇Jeffrey Richter的博客文章。
通过编写自己的PatternLayoutConverter,您可以轻松地通过CallContext.LogicalSetData存储自己的信息,并使其可供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)
{
los = Trace.CorrelationManager.LogicalOperationStack.Count > 0 ?
string.Join(">>",Trace.CorrelationManager.LogicalOperationStack.ToArray()) :
"";
}
else
if (String.Compare(Option.Substring(0, 1), "T", true) == 0)
{
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>
这是我的测试代码:
new Thread(TestThis).Start("ThreadA");
new Thread(TestThis).Start("ThreadB");
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 = ] [LOS.All = ThreadA10] [LOS.Top = ThreadA10] [LCC = ThreadA10] From Thread itself
Form1: 2011-01-14 09:18:53,160 [ThreadB] Form1 DEBUG [PROP = ] [LOS.All = ThreadB11] [LOS.Top = ThreadB11] [LCC = ThreadB11] From Thread itself
Form1: 2011-01-14 09:18:53,192 [12] Form1 DEBUG [PROP = ] [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 = ] [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 = ] [LOS.All = ThreadB11] [LOS.Top = ThreadB11] [LCC = ] From threadpool Thread_3: ThreadB
Form1: 2011-01-14 09:18:53,207 [13] Form1 DEBUG [PROP = ] [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 = ] [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 = ] [LOS.All = ThreadA10] [LOS.Top = ThreadA10] [LCC = ] From threadpool Thread_3: ThreadA
当我进行这个测试(以及其他一些测试)时,我创建了自己的“上下文”堆栈对象(类似于log4net的“堆栈”实现),通过使用CallContext.LogicalSetData而不是CallContext.SetData(这是log4net存储它的方式)。我发现当我有几个线程池线程时,我的堆栈变得混乱了。也许是因为当子上下文退出时将数据合并回父上下文导致的。我本不认为会是这样,在我的测试中,我明确地将新值推入线程池线程并在退出时将其弹出。使用基于Trace.CorrelationManager.LogicalOperationStack的实现进行类似的测试(我编写了一个抽象层),似乎表现正确。我猜可能是自动流动(向下和向上)逻辑考虑到了CorrelationManager,因为它是系统中“已知”的对象吗???
输出中需要注意的一些事项:
Trace.CorrelationManager信息通过CallContext.LogicalSetData存储,因此会"流动"到子线程中。TestThis使用Trace.CorrelationManager.StartLogicalOperation将一个逻辑操作(以传入的名称命名)"推送"到LogicalOperationStack上。线程池线程中的第一个logger.Debug语句显示线程池线程继承了与父线程相同的LogicalOperationStack。在线程池线程内部,我启动了一个新的逻辑操作,它被堆叠在继承的LogicalOperationStack上。您可以在第二个logger.Debug输出中看到其结果。最后,在离开之前,我停止了逻辑操作。第三个logger.Debug输出显示了这一点。
从输出中可以看出,CallContext.LogicalSetData也会"流动"到子线程中。在我的测试代码中,我选择在线程池线程中设置一个新值,并在离开之前清除它(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
[编辑]
我发现在使用线程(可能甚至不是很重)时,保持正确的上下文可能会使一些使用CallContext.LogicalSetData的数据集出现问题。
请参见StackOverflow上关于使用Trace.CorrelationManager.ActivityId的问题。我发布了一个关于使用Trace.CorrelationManager.LogicalOperationStack和我的一些观察结果的答案。
后来我使用了那个问题的答案作为在线程/任务/并行的上下文中使用Trace.CorrelationManager.LogicalOperationStack的基础提出了自己的问题。
我还在Microsoft的Parallel Extensions论坛上发布了一个非常相似的问题。
您可以阅读这些帖子以查看我的观察结果。简要总结如下:
使用以下代码模式:
DoLongRunningWork //Kicked off as a Thread/Task/Parallel(.For or .Invoke)
StartLogicalOperation
Sleep(3000) //Or do actual work
StopLogicalOperation
无论是由显式线程/线程池线程/任务/Parallel(.For或.Invoke)启动DoLongRunningWork,LogicalOperationStack的内容始终保持一致。
使用以下代码模式:
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 的内容保持一致,除了当使用 Parallel.For 或 Parallel.Invoke 启动 DoLongRunningWork 时。原因似乎与 Parallel.For 和 Parallel.Invoke 使用主线程作为执行并行操作的线程之一有关。
这意味着,如果您想将整个并行化(或线程化)操作作为单个逻辑操作封闭,并将每次迭代(即每次委托调用)作为外部操作中嵌套的逻辑操作,请测试过的大多数技术(Thread/ThreadPool/Task)都能正常工作。在每次迭代中,LogicalOperationStack 反映出有一个外部任务(针对主线程)和一个内部任务(即委托)。
如果使用 Parallel.For 或 Parallel.Invoke,则 LogicalOperationStack 不会正常工作。在上面链接的帖子中的示例代码中,LogicalOperationStack 永远不应该有超过 2 个条目。一个是主线程,另一个是委托。但是,使用 Parallel.For 或 Parallel.Invoke 后,LogicalOperationStack 最终将拥有比 2 个更多的条目。
通过使用 CallContext.LogicalSetData 进行存储(如果尝试通过存储具有 LogicalSetData 的 Stack 来模拟 LogicalOperationStack),结果会更糟糕。使用与上述类似的调用模式(包括封闭逻辑操作以及委托逻辑操作),使用 LogicalSetData 存储并相同维护(据我所知)的堆栈在几乎所有情况下都会损坏。
对于较简单的类型或在“逻辑线程”中未修改的类型,CallContext.LogicalSetData 可能会工作得更好。如果我要使用 LogicalSetData 存储值字典(类似于 log4net.LogicalThreadContext.Properties),则可能会被子线程/Tasks/等成功继承。
我没有关于为什么会发生这种情况或如何解决它的完美解释。可能是因为我对“上下文”的测试有些过头了,也可能不是这样。
如果您想进一步研究此问题,可以尝试使用我在上面链接中发布的测试程序。测试程序仅测试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
}
这是很多需要消化的内容,但也许你会发现其中一些对你有用!