Few facts about OutputDebugString and default settings of the System.Diagnostics.Trace


I recently spent some time analyzing OutputDebugString method. For my another experiment I needed a version of OutputDebugString which depends only on Native API. While implementing it, I discovered few interesting facts about OutputDebugString that maybe will interest you too. The title mentions System.Diagnostics.Trace. It is because the default trace configuration in .NET sends trace messages to an instance of the DefaultTraceListener class, which uses OutputDebugString. And if you do not remove it explicitly from the trace listener collection, your logs will always go through it. You will later see why sometimes it might not be a good idea.

How OutputDebugString works

In short words, OutputDebugString tries to send a message to a debugger attached to a given process, and if there is no debugger listening, it tries to map a global section into the process memory and save the debug message in it. My sample implementation of OutputDebugStringA (the ANSI version) using the Native API looks as follows:

VOID NTAPI RtlOutputDebugStringA(_In_opt_ LPCSTR OutputString) {
    if (OutputString) {
        EXCEPTION_RECORD exceptionRecord{ 0 };

        exceptionRecord.ExceptionCode = DBG_PRINTEXCEPTION_C;
        exceptionRecord.NumberParameters = 2;
        exceptionRecord.ExceptionInformation[0] = strlen(OutputString) + 1;
        exceptionRecord.ExceptionInformation[1] = reinterpret_cast<ULONG_PTR>(OutputString);

        __try {
            RtlRaiseException(&exceptionRecord);
        } __except (EXCEPTION_EXECUTE_HANDLER) {
            NotifyGlobalDebugOutputMonitor(OutputString);
        }
    }
}

The way how RtlOutputDebugStringA (and also OutputDebugString) checks the debugger presence is quite interesting: it raises an exception. If there is a debugger listening, it will swallow the exception (exception code: 0x40010006L for ANSI messages, 0x4001000A for UNICODE messages) and the handler will never execute. We all know that exceptions are expensive and we should use them only for exceptional situations. Thus, throwing an exception on every write to a trace does not seem right. In a moment I will show you some benchmarking results and a simple remedy to this problem (I guess you already know it:)). But first few more words about the NotifyGlobalDebugOutputMonitor method. It uses a global mapped section, two event objects, and a mutex to write a debug message. Event objects and the mutex guard the section against concurrent usage. I won’t dwell on this subject too much; if you are interested, have a look at the excellent article by zhangyuwu on Code Project. You may also check the source code of my implementation on github (it is just a POC so, please do not use it anywhere near production). Enough to say that having the debug output monitor (such as DebugView) running in the system has also a negative impact on the OutputDebugString performance, especially when multiple processes are writing to the debug output at the same time.

Impact on the performance

You may be now wondering what the DefaultTraceListener impact on the performance of the application is. To measure it I used BenchmarkDotNet on a slightly modified version of the MD5 benchmark:

public class DefaultTraceTests
{
    private const int N = 10000;
    private readonly byte[] data;

    private readonly MD5 md5 = MD5.Create();

    public DefaultTraceTests()
    {
        data = new byte[N];
        new Random(42).NextBytes(data);
    }

    [GlobalSetup(Target = nameof(TracedMd5WithNoTraceListener))]
    public void GlobalSetupNoTraceListener()
    {
        Trace.Listeners.Remove("Default");
    }

    [GlobalSetup(Target = nameof(TracedMd5WithEtwTraceListener))]
    public void GlobalSetupEtwTraceListener()
    {
        Trace.Listeners.Remove("Default");
        Trace.Listeners.Add(new EventProviderTraceListener(Guid.NewGuid().ToString()));
    }

    [Benchmark]
    public string TracedMd5WithDefaultTraceListener()
    {
        var hash = Hex.ToHexString(md5.ComputeHash(data));
        Trace.Write(hash);
        return hash;
    }

    [Benchmark]
    public string TracedMd5WithEtwTraceListener()
    {
        var hash = Hex.ToHexString(md5.ComputeHash(data));
        Trace.Write(hash);
        return hash;
    }

    [Benchmark]
    public string TracedMd5WithNoTraceListener()
    {
        var hash = Hex.ToHexString(md5.ComputeHash(data));
        Trace.Write(hash);
        return hash;
    }

    [Benchmark]
    public string Md5() => Hex.ToHexString(md5.ComputeHash(data));
}

public class Program
{
    public static void Main(string[] args)
    {
        var summary = BenchmarkRunner.Run<DefaultTraceTests>();
    }
}

The results are as follows:

                            Method |     Mean |     Error |    StdDev |
---------------------------------- |---------:|----------:|----------:|
 TracedMd5WithDefaultTraceListener | 45.86 us | 0.2084 us | 0.1847 us |
     TracedMd5WithEtwTraceListener | 24.67 us | 0.2315 us | 0.2165 us |
      TracedMd5WithNoTraceListener | 24.62 us | 0.0693 us | 0.0578 us |
                               Md5 | 24.40 us | 0.1906 us | 0.1783 us |

There was no debug output monitor running on the system and yet there was a drastic drop in the application performance with the DefaultTraceListener enabled. On the other hand, usage of the EventProviderTraceListener (which uses ETW) is almost unnoticeable.

Remedy

After seeing the results of the benchmark, I am a bit surprised that DefaultTraceListener is in the default trace configuration. If you are using System.Diagnostics.Trace in your application you definitely should replace the default trace listener with something faster before deploying the code to production. You may do this in C#:

Trace.Listeners.Remove("Default");
Trace.Listeners.Add(...here your chosen TraceListener...);

or in the app.config file:

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <system.diagnostics>
    <trace>
      <listeners>
        <remove name="Default" />
      </listeners>
    </trace>
  </system.diagnostics>
</configuration>

Unfortunately, this won’t remove the DefaultTraceListener from listeners collection in the System.Diagnostics.TraceSource‘s you may be using. You need to configure each instance separately.

On a side note, you should also disable assert UI messages before deployment (so no MessageBox will block your application execution whenever assert fails) and use Debug.Assert instead of Trace.Assert.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

w

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.