Lots of input messages lingering in server slowing down wine tremendously?

[Alexander Dorofeyev]

Hi.

There was a problem found recently in a fan-made mod of Forsaken (game), that 
certain input combinations were slowing wine very seriously. Holding down a 
keyboard button and moving mouse was found to be especially devastating to 
performance (200 fps to 10fps in a matter of 10-20 seconds).

With help from people who develop this mod, I was able to isolate it in a very 
small and simplistic testcase, which shows this same problem. It will be 
included as attachment. Holding a key and moving mouse over the window steadily 
increases main loop latency from 10 to 50 (and even 100) in a short time, 
especially so if quickly clicking both mouse buttons as well. In a game this 
means going from 100 fps to 20 or 10 just because of input messages. Has to be 
noted that in the actual game the rate of slowdown seemed at least 2-3 times 
faster for reasons I don't know, but the testcase still should enough to show 
the problem.

Now, I do realize that what the testcase is doing is bad practice, it's 
basically refusing to process certain types of messages, and PeekMessage just 
once during a loop is probably bad as well, but that's what the game was 
originally doing in its main game loop. They do plan to fix it in the game. 
Still, there are several concerns about it:

1) No slowdown happens of Windows as far as I can tell. No matter how much I 
move the mouse holding key and clicking madly, it shows same stable 15-16 ticks 
latency in the testcase. I don't know what it does, but somehow it handles this 
situation better than Wine.

2) Can this (broken) way of doing things be exposing some inefficiency in 
message handling, maybe something that could use optimization? I tried to put 
debug hacks into queue_hardware_message(), it seems that when slowdown is 
already VERY bad in Forsaken (10fps), message queue in wine server has about 400 
or maybe 600 messages. Is that kind of processing overhead per message 
inevitable? (This is happening on AMD Athlon(tm) 3200+). Perhaps somebody who 
knows that part of code well may be interested in looking into performance 
issues in this case. Because, if 400-600 messages in the queue slow down the 
application to a crawl, then who knows, perhaps it decreases performance of more 
well-behaved but input-intensive apps as well, just less drastically (holding 
one or several keys to move, all the while aiming with mouse and abusing mouse 
buttons is a common thing in games, so there can be quite a few input messages 
flooding the server).

The reason I decided to post it to wine-devel is because I'm not sure if this 
kind of thing is expected and unavoidable or a bug that can be fixed, so better 
to hear some comments first, then a bug entry can be opened if needed.

#include <windows.h>

HWND window;

int PASCAL WinMain(HINSTANCE hInstance, HINSTANCE hPrevInstance, LPSTR lpCmdLine, int nCmdShow)
{
WNDCLASS wc = {0};
MSG msg;
DWORD ticks, ticks2;
HHOOK kbd_hook, mouse_hook;

wc.lpfnWndProc = &DefWindowProc;
wc.lpszClassName = "testwc";
RegisterClass(&wc);
window = CreateWindow("testwc", "test", WS_OVERLAPPED | WS_VISIBLE | WS_CAPTION , 0, 0, 640, 480, 0, 0, 0, 0);

ticks = GetTickCount();

for (;;) {
    if (PeekMessage(&msg, NULL, WM_NULL, WM_KEYFIRST, PM_REMOVE)) {
        if (msg.message == WM_QUIT) {
         DestroyWindow(window);
         break;
         }

        TranslateMessage(&msg);
        DispatchMessage(&msg);
        }

    //simulated work
    ticks2 = GetTickCount();
    for (;;) {
        UINT i;
        volatile int dummy = 1;
        for (; i < 10000 && dummy; i++) ;
        if (GetTickCount() - ticks2 >= 10) break;
        }

    printf("main loop %u tick latency\n", GetTickCount() - ticks);
    ticks = GetTickCount();
    }
}

[Saulius Krasuckas]

* On Mon, 14 Apr 2008, Alexander Dorofeyev wrote:
> I was able to isolate it in a very small and simplistic testcase, which 
> shows this same problem. It will be included as attachment. Holding a 
> key and moving mouse over the window steadily increases main loop 
> latency from 10 to 50 (and even 100) in a short time, especially so if 
> quickly clicking both mouse buttons as well. In a game this means going 
> from 100 fps to 20 or 10 just because of input messages.

...
> Now, I do realize that what the testcase is doing is bad practice, it's 
> basically refusing to process certain types of messages, and PeekMessage 
> just once during a loop is probably bad as well, but that's what the 
> game was originally doing in its main game loop. They do plan to fix it 
> in the game. Still, there are several concerns about it:
>
> 1) No slowdown happens of Windows as far as I can tell. No matter how 
> much I move the mouse holding key and clicking madly, it shows same 
> stable 15-16 ticks latency in the testcase. I don't know what it does, 
> but somehow it handles this situation better than Wine.

I am not minded in this area, Alexander (an am a bit away in time), but is 
it algorithmically possible to convert this code to somewhat reliable test 
case which wouln't depend on CPU perfomance(s) (by any chance)?
> #include <windows.h>
>
> HWND window;
>
> int PASCAL WinMain(HINSTANCE hInstance, HINSTANCE hPrevInstance, LPSTR lpCmdLine, int nCmdShow)
> {
> WNDCLASS wc = {0};
> MSG msg;
> DWORD ticks, ticks2;
> HHOOK kbd_hook, mouse_hook;
>
> wc.lpfnWndProc = &DefWindowProc;
> wc.lpszClassName = "testwc";
> RegisterClass(&wc);
> window = CreateWindow("testwc", "test", WS_OVERLAPPED | WS_VISIBLE | WS_CAPTION , 0, 0, 640, 480, 0, 0, 0, 0);
>
> ticks = GetTickCount();
>
> for (;;) {
>    if (PeekMessage(&msg, NULL, WM_NULL, WM_KEYFIRST, PM_REMOVE)) {
>        if (msg.message == WM_QUIT) {
>         DestroyWindow(window);
>         break;
>         }
>
> TranslateMessage(&msg);
>        DispatchMessage(&msg);
>        }
>
> //simulated work
>    ticks2 = GetTickCount();
>    for (;;) {
>        UINT i;
>        volatile int dummy = 1;
>        for (; i < 10000 && dummy; i++) ;
>        if (GetTickCount() - ticks2 >= 10) break;
>        }
>
> printf("main loop %u tick latency\n", GetTickCount() - ticks);
>    ticks = GetTickCount();
>    }
> }