Condividi tramite

Trace.WriteLine may call OutputDebugString

  • Articolo

Recently, I was asked to check a couple of dump files. They were generated when their Biztalk server process was responding slow. I’ve listed the callstacks of all the threads. More than 100 threads were waiting to enter a monitor. An example callstack of such waiting threads is as follows :

 

System.Threading.Monitor.Enter(System.Object)

System.Diagnostics.TraceInternal.WriteLine(System.String)                          

XYZ.BiztalkESB.Utilities.GenericHelper.TraceWrite(System.String, System.String, System.String)

XYZ.BiztalkESB.Utilities.CacheBase.TryGetValue

XYZ.BiztalkESB.Utilities.InterchangeParameterCache.GetParamValue

XYZ.BiztalkESB.Utilities.ParameterHelper.GetInterchangeParameter

XYZ.BiztalkESB.Utilities.LoggerHelper.Log

XYZ.BiztalkESB.Utilities.LoggerHelper.LogHeader

XYZ.SomeIntegration.Biztalk.Resolvers.InterchangeDefinitionResolverOnline.Resolve

XYZ.BiztalkESB.Resolvers.XYZSomeResolveProvider.ResolveItineraryName

XYZ.BiztalkESB.Resolvers.XYZSomeResolveProvider.Resolve

Microsoft.Practices.ESB.Resolver.ResolverMgr.Resolve

Microsoft.Practices.ESB.Itinerary.PipelineComponents.ItinerarySelector.Execute

Microsoft.BizTalk.Internal.ComponentWrapper.Execute

Microsoft.BizTalk.PipelineOM.SimpleStage.Execute

Microsoft.BizTalk.PipelineOM.Pipeline.Execute

Microsoft.BizTalk.PipelineOM.ReceivePipeline.GetNext

 

And, the thread that has entered the monitor has the following callstack. This thread is waiting while executing OutputDebugString.

 

ntdll!ZwWaitForSingleObject+0xa

KERNELBASE!WaitForSingleObjectEx+0x92

KERNELBASE!WaitForSingleObject+0xd

KERNELBASE!OutputDebugStringA+0x130

KERNELBASE!OutputDebugStringW+0x58

System_ni!DomainNeutralILStubClass.IL_STUB_PInvoke(System.String)+0x82

System_ni!System.Diagnostics.DefaultTraceListener.Write(System.String, Boolean)+0x41

System_ni!System.Diagnostics.DefaultTraceListener.WriteLine(System.String, Boolean)+0x3f

System_ni!System.Diagnostics.TraceInternal.WriteLine(System.String)+0xfb

XYZ_BiztalkESB_Utilities!XYZ.BiztalkESB.Utilities.GenericHelper.TraceWrite(System.String, System.String, System.String)+0x59

XYZ_BiztalkESB_Utilities!XYZ.BiztalkESB.Utilities.CacheBase.TryGetValue

XYZ_BiztalkESB_Utilities!XYZ.BiztalkESB.Utilities.InterchangeParameterCache.GetParamValue

XYZ_BiztalkESB_Utilities!XYZ.BiztalkESB.Utilities.ParameterHelper.GetInterchangeParameter

XYZ_BiztalkESB_Utilities!XYZ.BiztalkESB.Utilities.LoggerHelper.Log

XYZ_BiztalkESB_Utilities!XYZ.BiztalkESB.Utilities.LoggerHelper.LogHeader

XYZ_SomeIntegration_Biztalk_Resolvers!XYZ.XYZSomeIntegration.Biztalk.Resolvers.InterchangeDefinitionResolverOnline.Resolve

XYZ_BiztalkESB_Resolvers!XYZ.BiztalkESB.Resolvers.XYZSomeResolveProvider.ResolveItineraryName

XYZ_BiztalkESB_Resolvers!XYZ.BiztalkESB.Resolvers.XYZSomeResolveProvider.Resolve

Microsoft_Practices_ESB_Resolver!Microsoft.Practices.ESB.Resolver.ResolverMgr.Resolve

 

It is time to use https://referencesource.microsoft.com Let’s first understand why a monitor is used. In the source of TraceInternal.WriteLine we can clearly see the synchronisation part :

 

public static void WriteLine(string message) {

 if (UseGlobalLock)  {

  lock (critSec)  {

   foreach (TraceListener listener in Listeners)  {

    listener.WriteLine(message);

    if (AutoFlush)  listener.Flush();}}

[The rest is truncated]

 The lock is defined as :

 internal static readonly object critSec = new object();

 

 

Also, we understand that once the monitor is available then a listener’s WriteLine method is called. From the callstack of the thread that entered into the monitor we see that the DefaultListener is used. And, an internal version is called :

 

void internalWrite(string message) {

 if (Debugger.IsLogging())  {

  Debugger.Log(0, null, message);

  }

  else  {

       if (message == null)

        SafeNativeMethods.OutputDebugString(String.Empty);           

       else

        SafeNativeMethods.OutputDebugString(message);         } }

 

If there is no debugger attached to the process (we knew that there was no debugger attached to Biztalk server) then OutputDebugString is called. This explains the “OutputDebugString” in callstack of the waiting threads. Next, we need to understand what the OutputDebugString is waiting on. If we examine the parameters of the WaitForSingleObject we will see that an event called DBWIN_BUFFER_READY ( E.g. \Sessions\<SessionNo>\BaseNamedObjects\DBWIN_BUFFER_READY) for 10 seconds. Now, the problem has  changed a bit. Why a string sent to OutputDebugString is processed for so long? Well we know that no debuggers are attached to the Biztalk process. Then what happens to the debug string?

We need to find out how OutputDebugString works. If you search on internet for DBWIN_BUFFER_READY you will find many examples. And, if you still have the Visual Studio 6 SDK which has the DBMon sample (https://msdn.microsoft.com/en-us/library/aa242171(v=vs.60).aspx ) then you’ll see how that string is consumed.

The string is put to a memory mapped file named “DBWIN_BUFFER”. Once the string is put an event named “DBWIN_DATA_READY” is signalled. The party that is waiting on that event will consume that memory mapped file’s content. That party is another application which does not have to be a debugger at all. E.g. the DBMon sample application is perfectly capable to consume the debug string. Once the memory mapped file’s content is consumed then the DBWIN_DATA_READY is set and another event called “DBWIN_BUFFER_READY” is signalled. Now, the application that calls OutputDebugString can continue. Meanwhile, if the consumer application cannot process the content within 10 seconds then OutputDebugString returns.

If that is the case and a fair lock is used and there are 100 threads waiting on the Trace.WriteLine function’s monitor then the last thread would wait for 10x100 seconds. Roughly 16 min. The experience will  ofcourse be a slow system. Just like my customer has felt. Let’s move on. Which application it was in our case that acted as the consumer of  OutputDebugString? The answer is DebugView. So how come DebugView did process the strings so slowly? The answer is “History Depth”. This option was not set in DebugView. If not set then all of the previous debug strings are kept. This causes the list view to operate considerably slower if there is a chatty environment in terms of OutputDebugStrings. Hence, if you want to use DebugView then you better set the History Depth.

Have a great day!

faik hakan bilgen