The cost of using OutputDebugString
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 with 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.
The 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 three 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 string, 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.
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 some 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.