Rss Feed
Tweeter button
Facebook button
Technorati button
Reddit button
Myspace button
Linkedin button
Webonews button
Delicious button
Digg button
Flickr button
Stumbleupon button
Newsvine button

The cost of using OutputDebugString

By , May 21, 2010 10:02 am

Should you use OutputDebugString? Is that an unusual question to ask? How often have you thought about the potential cost of using OutputDebugString (or TRACE, which uses OutputDebugString under the hood)?

Benefits of using OutputDebugString

The benefit of using OutputDebugString is the ability to leave a relatively benign function in your code that can output useful textual information which can be monitored by a debugger or a suitable utility (such as DebugView).

The TRACE() macro allows you to output information, but only in Debug builds. OutputDebugString() allows you to output the information in Debug and Release builds.

Problems caused by using OutputDebugString

The problem of using OutputDebugString is that it has a performance overhead, which although minimal outside a debugger is much higher in a debugger. If in a busy loop this overhead can be an unwanted burden.

It may be that the information being output by OutputDebugString is not information that you want your customers (or competitors!) to see.

Finally, depending on your software application, it may be that your customers will be using your software component (for example our injected monitoring DLLs) with their software in their debugger, debugging their software. In that situation, your customer may not appreciate the extra OutputDebugString() information filling up their Output tab with information and obscuring whatever information their own OutputDebugString() usage is providing.

I’m sorry to say it, but we have been guilty of this in the past! You may want to check your code to ensure you are not doing this by accident. Its all to easy to let things like this happen – after all there is no obvious adverse effect (like a crash or undefined behaviour) to fail your testing patterns.

Performance cost of using OutputDebugString

I’ve noticed questions asking about the cost of OutputDebugString() on a few forums but never seen any hard numbers to go with the received opinions offered. Being a curious animal I decided that I should investigate. The benefits being that I get to scratch this curious itch and if the news is bad we get to make a few modifications to the software at Software Verification.

OutputDebugString() comes in two flavours, OutputDebugStringA() for ANSI builds and OutputDebugStringW() for Unicode builds. The tests I ran tested both of these WIN32 APIs on Windows XP 64 bit, on a dual quad core Intel Xeon running at 2.83GHz. All tests done under the same load.

Testing OutputDebugString

To test the APIs we need to test a few scenarios:

  • Calling the API when running the test application outside of a debugger. This will be the equivalent of if you leave OutputDebugString() calls in your release mode application and ship it to your customer.
  • Call the API when running the test application in a debugger. This tests the overhead of OutputDebugString() communicating with the debugger so that the debugger can display the message on its output pane (assuming the debugger does that).
  • Call the API when running the test application in a debugger, adding a \r\n at the end of each line. This tests the overhead of OutputDebugString() communicating with the debugger so that the debugger can display the message on its output pane (assuming the debugger does that).

We have chosen to test with Visual Studio 6.0, Visual Studio 2005 and Visual Studio 2010. We have chosen these two IDEs/debuggers since VS6 is the old pre-.Net IDE which is still well loved by a lot of developers. We have also chosen VS2005 because based on what we can tell from our customer base this is a very popular IDE/debugger.

The test for each scenario consists of outputting three different size strings 4000 times. The three strings are a zero length strings, a short string and a longer string. The test is also repeated with the same strings with \r\n appended to the non-zero length strings. We added this test when we realized that the Visual Studio output panel behaves differently between VS6 and VS2005 for lines that do not contain \r\n at the end.

You can download full source code and project files for both VS6 and VS2005 so that you can build and run these tests for yourself. For VS2010 you can load the VS2005 solution file and convert it automatically during the load.

timeOutputDebugString screenshot

Results

We have 7 groups of test results spanning no debugger, Visual Studio 6, Visual Studio 2005, and Visual Studio 2010.

Test 1 – No Debugger

OutputDebugString() called 4000 times, no debugger monitoring the process. No \r\n per output.
What we can see is that OutputDebugStringW() is 9% slower than OutputDebugStringA() and that both calls are very fast.

Function String Time
OutputDebugStringA "" 0.0112s
OutputDebugStringA short string 0.0198s
OutputDebugStringA long string 0.0255s
Average 0.00000470s
 
OutputDebugStringW "" 0.0121s
OutputDebugStringW short string 0.0214s
OutputDebugStringW long string 0.0281s
Average 0.00000513s

Test 2 – Visual Studio 6

OutputDebugString() called 4000 times, Visual Studio 6 monitoring the process. No \r\n per output.
What we can see is that OutputDebugStringW() is 1% slower than OutputDebugStringA() and that both calls are over 19 times slower than without the debugger.

Function String Time
OutputDebugStringA "" 0.03631s
OutputDebugStringA short string 0.03837s
OutputDebugStringA long string 0.3885s
Average 0.00009641s
 
OutputDebugStringW "" 0.3693s
OutputDebugStringW short string 0.3977s
OutputDebugStringW long string 0.4068s
Average 0.00009782s

Test 3 – Visual Studio 6

OutputDebugString() called 4000 times, Visual Studio 6 monitoring the process. One \r\n per output.
What we can see is that OutputDebugStringW() is 2% slower than OutputDebugStringA() and that both calls are over 22 times slower than without the debugger.

Function String Time
OutputDebugStringA "" 0.4048s
OutputDebugStringA short string 0.4247s
OutputDebugStringA long string 0.4267s
Average 0.00010468s
 
OutputDebugStringW "" 0.4127s
OutputDebugStringW short string 0.4346s
OutputDebugStringW long string 0.4419s
Average 0.00010743s

Test 4 – Visual Studio 2005

OutputDebugString() called 4000 times, Visual Studio 2005 monitoring the process. No \r\n per output.
What we can see is that OutputDebugStringW() is 54% slower than OutputDebugStringA() and that both calls are over 65 times (95 times slower for OutputDebugStringW) slower than without the debugger.

Function String Time
OutputDebugStringA "" 1.0270s
OutputDebugStringA short string 1.2200s
OutputDebugStringA long string 1.3982s
Average 0.00030377s
 
OutputDebugStringW "" 1.5850s
OutputDebugStringW short string 1.8874s
OutputDebugStringW long string 2.1672s
Average 0.00046997s

Test 5 – Visual Studio 2005

OutputDebugString() called 4000 times, Visual Studio 2005 monitoring the process. One \r\n per output.
What we can see is that OutputDebugStringW() is 48% slower than OutputDebugStringA() and that both calls are over 68 times (92 times slower for OutputDebugStringW) slower than without the debugger.

Function String Time
OutputDebugStringA "" 1.1133s
OutputDebugStringA short string 1.2766s
OutputDebugStringA long string 1.4455s
Average 0.00031962s
 
OutputDebugStringW "" 1.6444s
OutputDebugStringW short string 1.9108s
OutputDebugStringW long string 2.1501s
Average 0.00047543s

Test 6 – Visual Studio 2010

OutputDebugString() called 4000 times, Visual Studio 2010 monitoring the process. No \r\n per output.
What we can see is that OutputDebugStringW() is 2% slower than OutputDebugStringA() and that both calls are over 133 times (142 times slower for OutputDebugStringA) slower than without the debugger.

Function String Time
OutputDebugStringA "" 2.8112s
OutputDebugStringA short string 2.6041s
OutputDebugStringA long string 2.6408s
Average 0.00067134s
 
OutputDebugStringW "" 2.5735s
OutputDebugStringW short string 2.5891s
OutputDebugStringW long string 3.0845s
Average 0.00068727s

Test 7 – Visual Studio 2010

OutputDebugString() called 4000 times, Visual Studio 2010 monitoring the process. One \r\n per output.
What we can see is that OutputDebugStringW() is 2% slower than OutputDebugStringA() and that both calls are over 132 times (141 times slower for OutputDebugStringA) slower than without the debugger.

Function String Time
OutputDebugStringA "" 2.6517s
OutputDebugStringA short string 2.6604s
OutputDebugStringA long string 2.6423s
Average 0.00066287s
 
OutputDebugStringW "" 2.6675s
OutputDebugStringW short string 2.7529s
OutputDebugStringW long string 2.7410s
Average 0.00068011s

Conclusion

Calling OutputDebugString() when the application is not being monitored by a debugger does not incur significant overhead, although in tight loops this could be problematic.

Calling OutputDebugString() when the application is monitored by Visual Studio 6 can result in OutputDebugString() running between 19 and 22 times slower than without Visual Studio 6 monitoring the application.

Calling OutputDebugString() when the application is monitored by Visual Studio 2005 can result in OutputDebugString() running between 65 and 95 times slower than without Visual Studio 2005 monitoring the application.

Calling OutputDebugString() when the application is monitored by Visual Studio 2010 can result in OutputDebugString() running between 132 and 142 times slower than without Visual Studio 2005 monitoring the application.

The most surprising aspect is that the newer, more modern Visual Studio 2005 and Visual Studio 2010 are so much slower at handling OutputDebugString() than the old Visual Studio 6 IDE, which is now 12 years old. The performance difference is a factor of 3x or 4x (for VS2005) and a factor of 6x or 7x (for VS2010) depending on the test. Our initial tests ran OutputDebugString 100,000 times, but the tests using Visual Studio 2005 were so slow we had to reduce the test run to 4,000 times so that we could get a result in a realistic time frame to do the test.

The other interesting aspect is that with Visual Studio 2005 monitoring the application, the disparity in performance between OutputDebugStringA() and OutputDebugStringW() is even greater. With Visual Studio 2010, the disparity is not so great, but the actual performance level is worse than for Visual Studio 2005.

It may be tempting to write off all of the above information with the remark that this test does not reflect real world usage of OutputDebugString because we are calling it in a tight loop. It is the case that our loop is exceptionally tight as we are trying to time just the function call, but we see in our own development work occasions where OutputDebugString is called frequently enough that while in the debugger there is a serious drop off in performance. For example our interprocess comms for sending data from our monitoring stub to the GUI, if we are debugging so items we either enable some logging or OutputDebugString. This data is provided from the application being monitored at a rate and volume determined by what the application is doing. For Memory Validator, say, monitoring certain apps, that could be 500,000 events just to start the target application. That is 500,000 OutputDebugString calls in our GUI, reporting comms activity. In such a case, using logging may be more efficient. I mention this just to show that although our test has a tight loop, the actual test number (4,000) is well within real world usage.

Share

2 Responses to “The cost of using OutputDebugString”

  1. Michael says:

    Just tried compiling on VS2010 and it failed with “cannot open include file ‘res\timeOutputDebugString.rc2″. I think it’s because timeOutputDebugString.ico is not included which the rc tries to open.

  2. Michael says:

    Sorry, wish I could delete my last post. All files there, just messed up de-compressing *sigh* (accidentally put all files in one folder and only noticed that now).

Leave a Reply

Panorama Theme by Themocracy