The World's Slowest Logging Function

Deadfast

My objective was simple: there's an existing log window, log more stuff to it. And so I did. And then I noticed the application now takes 19 minutes instead of 30 seconds to start...

Sure, I do print 23 thousands lines of crap (don't ask...) and logging is generally slow. But this slow? We're talking approximately 5 lines a second! A dot matrix printer is faster than that!

And why the hell can I make it go about a billion times faster by messing with the scrollbar while the messages are being printed?!

Let's have a closer look at the code...

void PrintStuffSloooowly(const char *text)
{
    int ndx = GetWindowTextLength(logHWnd);
    SendMessageW(logHWnd, EM_SETSEL, (WPARAM)ndx, (LPARAM)ndx);

    SETTEXTEX textParam;
    LRESULT lResult;
    wParamOUT.codepage = CP_UTF8;
    wParamOUT.flags = ST_SELECTION;
        
    lResult = SendMessageW(logHWnd,EM_SETTEXTEX,(WPARAM) &wParamOUT,(LPARAM) text);
}

// N.B.: This runs in its own thread
DWORD WINAPI MessageProcessingLoop ( void *param )
{
    MSG msg;
    while (true)
    {
        while( PeekMessage(&msg, 0, 0, 0, PM_REMOVE) )
        {
            TranslateMessage(&msg);
            DispatchMessage(&msg);
            if (msg.message==USER_CLOSE)
            {
                PostMessage((HWND)hwndApp,WM_CLOSE,0,0);
            }
        }

        if (CheckExit)
            break;

        Sleep(50); // Beware! We must give the CPU time to do better things!
    }

    return 0;
}

(Slightly simplified)

So in case the error isn't obvious (this is WinAPI after all) let's go through the code together.

We have one thread populating the message queue with requests to append text and another thread periodically processing the window's messages and dispatching them. I'm no WinAPI expert but as far as I can tell this is a pretty common way to do things.

Side rant: [spoiler]Why the hell is appending text to a text box this complicated?! You have to reposition the cursor (EM_SETSEL) and then replace the nothing that is selected with something (EM_SETTEXTEX). All of this is massive fun to synchronize across different threads (what if somebody changes the text after you sent your request to reposition the cursor?) which is how this catastrophe probably came to exist in the first place.[/spoiler]

So if all the processing happens in another thread what the hell takes ~100ms in PrintStuffSloooowly?

How about SendMessage:

Sends the specified message to a window or windows. The SendMessage function calls the window procedure for the specified window and does not return until the window procedure has processed the message.

Yeah, so SendMessage doesn't actually return until the dispatched message has been processed and there are two of those damned things in there!

And how long does it take to process this message? Well, Sleep(50) ms is your answer. Unless you can produce enough other messages to keep it from falling out of the innermost loop that is. Which is where the scrollbar abuse came in - messing with it generated so many messages the loop was kept permanently busy!

Maciejasjmj

@Deadfast said:

Sleep(50) ms

Um, isn't that pretty much what GetMessage() is for? Or however WinAPI does blocking message queue reads...

RaceProUK

IIRC, GetMessage() blocks until there's a message to actually get

Maciejasjmj

Isn't that the point? The UI thread blocks, and you don't have to Sleep() to yield and are able to process messages as fast as they go, instead of one per 50ms?

RaceProUK

Pretty much, yeah. TBH, the whole message loop implementation in the OP is a complete anyway.

Deadfast

@Maciejasjmj said:

Um, isn't that pretty much what GetMessage() is for? Or however WinAPI does blocking message queue reads...

From the quick look I had at it it does seem that way.

If you can convince me it'll be totally much better to use it and won't break anything I may spend the few minutes on replacing it, though after spending an entire day on stupid log messages (Why is it always the simple things that turn out to be a massive pain in the ass?) I'm not exactly looking forward to touching this code again...

RaceProUK

while(GetMessage(&msg, NULL, 0, 0))
{
    TranslateMessage(&msg);
    DispatchMessage(&msg);
}

is the standard message loop at the heart of pretty much any Windows program with a GUI, and is designed to co-operate with other processes. If there's nothing in the message queue, GetMessage() yields to the OS scheduler so other threads/processes get a chance to run. Then when a message enters the queue, the OS can switch back and GetMessage() returns. And when GetMessage() blocks, it has zero effect on SendMessage().

Maciejasjmj

@Deadfast said:

If you can convince me it'll be totally much better to use it and won't break anything I may spend the few minutes on replacing it

Well, since you don't make a copy of the text before you pass it via the message, it's probably better to keep those blocking writes - if someone screws around with your text buffer, you'll get outdated log messages.

But Sleep(50)? Just trace the code - PeekMessage gets nothing, so it passes the loop, hits Sleep and stalls for 50ms - baton goes to your printing function. That function does a SendMessage, which blocks - but you can't schedule the UI thread back until the 50ms pass.

OTOH, using GetMessage(), you block on the read, block on the write, and then you can immediately schedule your UI thread back since it wakes GetMessage() up. Without waiting 50ms for it.

At least that's what I gather from the simplified version of the code - hell if I know what lives in the codebase written by someone who can't do a basic fucking message loop. Hell, I know only as much WinAPI as I needed to pull a function or two into my C# code, and it smells like shit for me.

Deadfast

I just realized that in the process of anonymization/simplification I left out a check for some global exit variable that causes the loop to shut down. I updated the OP to include it. Using GetMessage() wouldn't work with it and as I just remembered that's why I didn't pursue it further - I didn't have the strength to try to figure out that global is and if it even needs to be there in the first place - Couldn't you just send an exit message? There's even a fucking custom one there!

Deadfast

@Maciejasjmj said:

Well, since you don't make a copy of the text before you pass it via the message, it's probably better to keep those blocking writes - if someone screws around with your text buffer, you'll get outdated log messages.

I pretty much rewrote the whole thing except the message processing loop. The logging is now asynchronous because ~~PrintStuffSloooowly()~~PrintStuffToday() now just posts a user message that the UI loop later writes.

Maciejasjmj

@Deadfast said:

I pretty much rewrote the whole thing except the message processing loop. The logging is now asynchronous because PrintStuffSloooowly()PrintStuffToday() now just posts a user message that the UI loop later writes.

Hopefully you only use PrintStuffToday() where you're sure nobody's fucking around with your string?

Deadfast

@Maciejasjmj said:

Hopefully you only use PrintStuffToday() where you're sure nobody's fucking around with your string?

Yeah, in the unabridged version the string cannot be fucked with.

FrostCat

@RaceProUK said:

IIRC, GetMessage() blocks until there's a message to actually get

That's why it's using PeekMessage and not GetMessage. Other than that sleep() call, which is wrong, this is a perfectly cromulent message loop.

FrostCat

@RaceProUK said:

TBH, the whole message loop implementation in the OP is a complete

Nope. You see (almost) the same technique used for DirectX apps, except that if PeekMessage says the message queue is empty, you can process a frame instead.

RaceProUK

I'm pretty sure the program referenced in the OP isn't a game :P

FrostCat

@RaceProUK said:

I'm pretty sure the program referenced in the OP isn't a game

No, but there are other reasons for doing it that way. If someone went to the trouble of writing that variant message loop, I would leave it that way unless I knew exactly why they did it that way. The generalized version of my explanation above is "I want to do some processing whenever the message queue is empty".

RaceProUK

But that's the thing: it's running in its own thread. So if it was to block on GetMessage(), it would yield to the OS, and other threads would be woken up and get their shit done.

FrostCat

@RaceProUK said:

it's running in its own thread.

Maybe at some point it was single-threaded? Who knows. The thing about doing it this way is you can function single-threadedly, and as we all know, ThreHang Idisard.

tar

@Deadfast said:

Yeah, so SendMessage doesn't actually return until the dispatched message has been processed

Isn't there a PostMessage() API which plonks the message into a deferred queue and then just gets on with its life, none of this synchronous business? Been several years since I had anything to do with Win32...

But yeah, Sleep() is usually a fail, though.