How can I keep a large amount of OutputDebugString() calls from degrading my application in the Delphi 6 IDE?

Question

This has happened to me on more than one occasion and has led to many lost hours chasing a ghost. As typical, when I am debugging some really difficult timing-related code I start adding tons of OutputDebugString() calls, so I can get a good picture of the sequence of related operations. The problem is, the Delphi 6 IDE seems to be able to only handle that situation for so long. I'll use a concrete example I just went through to avoid generalities (as much as possible).

I spent several days debugging my inter-thread semaphore locking code along with my DirectShow timestamp calculation code that was causing some deeply frustrating problems. After having eliminated every bug I could think of, I still was having a problem with Skype, which my application sends audio to.

After about 10 seconds the delay between my talking and hearing my voice come out of Skype on the second PC that I was using for testing, the far end of the call, started to grow. At around 20 - 30 seconds the delay started to grow exponentially and at that point triggered code I have that checks to see if a critical section was being held too long.

Fortunately it wasn't too late at night and having been through this before, I decided to stop relentlessly tracing and turned off the majority of the OutputDebugString(). Thankfully I had most of them wrapped in a conditional compiler define so it was easy to do. The instant I did this the problems went away, and it turned out my code was working fine.

So it looks like the Delphi 6 IDE starts to really bog down when the amount of OutputDebugstring() traffic is above some threshold. Perhaps it's just the task of adding strings to the Event Log debugger pane, which holds all the OutputDebugString() reports. I don't know, but I have seen similar problems in my applications when a TMemo or similar control starts to contain too many strings.

What have those of you out there done to prevent this? Is there a way of clearing the Event Log via some method call or at least a way of limiting its size? Also, what techniques do you use via conditional defines, IDE plug-ins, or whatever, to cope with this situation?

Hydrogenate

See here to find out which-logging-library-is-better. – Purchase

@LURD. Thanks! Nice round-up post on logging tools. – Hydrogenate

Answer 1

A similar problem happened to me before with Delphi 2007. Disable event viewing in the IDE and instead use DebugView from Sysinternals.

Emelina

I have DebugView but I didn't know you could disable event viewing. I'll see if Delphi6 has that option, thanks. – Hydrogenate

... I was told then that the reason of the slowness is due to a StringGrid being used for the event log (now it's a VirtualStringTree). Here is a cache of the thread of my specific problem, which was on the Emb.. forums at that time. – Emelina

Answer 2

I hardly ever use OutputDebugString. I find it hard to analyze the output in the IDE and it takes extra effort to keep several sets of multiple runs.

I really prefer a good logging component suite (CodeSite, SmartInspect) and usually log to various files. Standard files for example are "General", "Debug" (standard debug info that I want to collect from a client installation as well), "Configuration", "Services", "Clients". These are all set up to "overflow" to a set of numbered files, which allows you to keep the logs of several runs by simply allowing more numbered files. Comparing log info from different runs becomes a whole lot easier that way.

In the situation you describe I would add debug statements that log to a separate logfile. For example "Trace". The code to make "Trace" available is between conditional defines. That makes turning it on pretty simple.

To avoid leaving in these extra debug statements, I tend to make the changes to turn on the "Trace" log without checking it out from source control. That way, the compiler of the build server will throw out "identifier not defined" errors on any statements unintentionally left in. If I want to keep these extra statements I either change them to go to the "Debug" log, or put them between conditional defines.

Lombardo

Thanks for the tips on the logging components. I'll take a look at those. However I find that for some high-speed real-time critical debugging cases writing to a log file disrupts the timing too much or even makes it impossible. But outside of that narrow slice of use cases they definitely help a lot. – Hydrogenate

@RobertOschler: I haven't done any real-time work, but in the high-performant heavily multi-threaded server software (at my employer), we usually can get away with a fair bit of logging before the timings change enough for the behaviour to change and make the bug disappear. Of course you do want to keep your logging messages short and avoid string concatenation (use Format), memory re-allocation, function calls or property getters for logging as much as possible. – Lombardo

Answer 3

The first thing I would do is make certain that the problem is what you think it is. It has been a long time since I've used Delphi, so I'm not sure about the IDE limitations, but I'm a bit skeptical that the event log will start bogging down exponentially over time with the same number of debug strings being written in a period of 20-30 seconds. It seems more likely that the number of debug strings being written is increasing over time for some reason, which could indicate a bug in your application control flow that is just not as obvious with the logging disabled.

To be sure I would try writing a simple application that just runs in a loop writing out debug strings in chunks of 100 or so, and start recording the time it takes for each chunk, and see if the time starts to increase as significantly over a 20-30 second timespan.

If you do verify that this is the problem - or even if it's not - then I would recommend using some type of logging library instead. OutputDebugString really loses it's effectiveness when you use it for massive log dumps like that. Even if you do find a way to reset or limit the output window, you'd be losing all of that logging data.

Flessel

Thanks. See my comment to Marjan below regarding logging. – Hydrogenate

A good logging library will allow you to configure buffering so you're not hit with a file write for every log entry, so it wouldn't be any more disruptive than OutputDebugString. Many of them can also use external processes to handle the log entries and pass the log entries via shared memory, which is essentially the same thing OutputDebugString does. – Flessel

Answer 4

IDE Fix Pack has an optimisation to improve performance of OutputDebugString

The IDE’s Debug Log View also got an optimization. The debugger now updates the Log View only when the IDE is idle. This allows the IDE to stay responsive when hundreds of OutputDebugString messages or other debug messages are written to the Debug Log View.

Note that this only runs on Delphi 2007 and above.

Annikaanniken