3/23/2009

03-23-09 - A Better Log Window

I just put a LogWindow in cblib and I thought I'd make some notes about it. The reason it exists is that stdio on Windows is so ungodly slow. The console is actually a seperate process, and when you printf to stdout, it creates an interprocess communication packet and fires it over. I'm sure every programmer knows that doing lots of stdio printing can be the bottleneck in your app if you're not careful. We all take this for granted and take a lot of steps to avoid printing too often. For example my file copy percent display routines look like :

    int lastPercentShowed = -1;

    .. copy N more bytes ..
    int percentDone = (100 * bytesDone + (bytesTotal/2) ) / bytesTotal;
    if ( percentDone != lastPercentShowed )
    {
        fprintf(stderr,"%d%%\r",percentDone);
        fflush(stderr);
        lastPercentShowed = percentDone;
    }

where the whole purpose of lastPercentShowed is to avoid doing too many prints. (you could also use timers and check enough time has passed, etc).

But sometimes it's a pain to limit this kind of stuff at the high level. For example Oodle logs all the files it opens. Normally that's fine because you don't open files too often. But sometimes you do something that opens a ton of tiny files, and suddenly the printf to stdio becomes the bottleneck. Well you know what, that's retarded, it's just putting text on the screen, it shouldn't be such a huge perf hit.

So I just did my own Log Window.

It's just a simple Window on a thread. It runs its message pump for that Window on that thread (BTW to do this you must also Create the window on that thread - Windows automatically associate themselves with the thread they are made on, unless you do AttachThreadInput which you don't want to do).

The LogWindow::Puts from the main thread just uses my lock-free SPSC FIFO to send the string as a packet to the LogWindow thread. That makes it nice and nonblocking and fast for the main thread. (I just duplicate the string to make it safe to send to the thread).

So that's all nice and simple and fast and the main thread can just fire tons of logs and not worry about it. The other big speed improvement is in the LogWindow update.

The LogWindow thread sleeps when it has no windows messages. It needs to wake up occasionally if it got a mouse click or a paint that it needs to respond to. It also needs to pull new strings off the FIFO and add them to its list. When it does that, it can just keep pulling off the FIFO while it's not empty - it doesn't cause a redraw for every new string it gets, it only redraws once for a whole bunch of strings. This is much neater, if the main thread is firing tons of strings at it really quick, it will wind up just grabbing them all and doing one big step instead of tons of little ones.

The LogWindow thread also needs to wake up when there are new messages in the FIFO even if it hasn't gotten a paint message. I guess I should do that with an Event signal, but right now I'm just using a timer. The timer just wakes it up and makes it pull the fifo. Yeah in fact I'll switch that to an Event right now and use "MsgWaitForMultipleObjectsEx" that lets you wait on either an Event or a Windows HWND Message.

Though actually they optimize slightly different cases. The Event is better if you log very rarely or with big gaps, because it lets the LogWindow completely sleep when it's not being updated (with the Timer it still wakes up on the timer interval all the time and costs you some thread switch penalty even though it does nothing). The Timer is better if you are logging very heavily, because just setting the Event for each printf is not at all free. Maybe there's a way to get the best of both worlds, but really either one is miles ahead of using a standard console.

1 comment:

ryg said...

OutputDebugString (the function that lets you write stuff into the debugger output window) is also dog slow - the debugger has to get the strings from the debuggee via ReadProcessMemory, which doesn't come cheap. (Good entry point to "how Win32 debuggers work" in MSDN is WaitForDebugEvent, by the way).

To make matters worse, the VC++ output window seems to have a buffer that grows in linear increments (or something similar); whatever the exact technical reason, the observed cost of OutputDebugString is O(N) in the amount of text already present in the buffer, for an accumulated O(N^2). So if your app is spamming the debug log, this is not only slow in the first place, it also gets slower over time.

old rants