Weird long polls with Window::pollEvent

[Tijmen]

Hey all,

Second help post here, hopefully this one is easier to solve I am having trouble with calls to sf::Window::pollEvent , which usually take 0 milliseconds but spike to 10, 20 even 60 ms at times. I have not been able to localize it further than that. On the internet I have read that in the past this was due to joysticks?

My environment:

• Windows 10 x64 build 1709
• SFML 2.4.2 (x86) or the latest master branch version
• Visual Studio 2017 Community 15.5.6
• Cmake version 3.6.2
• I am using statical linking

I am not using joysticks for my game as input devices. The source code can be viewed here: https://github.com/TijmenUU/smarttalesii, but it specifically happens in https://github.com/TijmenUU/smarttalesii/blob/master/smart_tales_ii/inputhandler.cpp line 22.

Both SFML 2.4.2 (x86) and latest master version have this issue for me.

Interesting observation: I sometimes have 2 xbox controllers plugged in, like this guy over here has too https://stackoverflow.com/questions/46135226/sfml-fps-problems-with-window-event-polling. I will test if plugging 1 or 2 in makes any difference.

If this is a known issue: can I remove joystick support easily by altering the source and rebuilding SFML?

EDIT: Plugging two xbox controllers in does not get rid of the problem, but it does "seem" to reduce the occurrences of them. No hard evidence for that, problem still persists. My logs still show 27 ms spend on line 22.

Before anyone asks: I have put loggers all over my update cycles to see where the problem occurred, and it is definitely the sf::Window::pollEvent function, it never occurred in other places. So it is not an outside influence I happen to record randomly on that line.

EDIT2: My measurement is implemented as follows in the previously mentioned file inputhandler.cpp:22:

(click to show/hide)

sf::Clock timer;
sf::Event event;
while (window.pollEvent(event))
{
   logger << "poll_ev_time " << timer.restart().asMilliseconds() << '\n';
   switch (event.type)

And in my log file it looks like this:

(click to show/hide)

poll_ev_time 0
poll_ev_time 0
poll_ev_time 0
poll_ev_time 0
poll_ev_time 22
poll_ev_time 0
poll_ev_time 0
poll_ev_time 0
poll_ev_time 0
poll_ev_time 0
poll_ev_time 3
poll_ev_time 0
poll_ev_time 0
poll_ev_time 1
poll_ev_time 0
poll_ev_time 1
poll_ev_time 0
poll_ev_time 0
poll_ev_time 0
poll_ev_time 6

[Tijmen]

Digging into the SFML internals a little. I logged the time taken inside the functions WindowImplWin32::processEvents and WindowImplWin32::processEvent. Unsurprisingly, the mainly switch statement function processEvent takes less than a millisecond to complete on average. But the processEvents function has these extreme spikes of 20, 30 and 60 at times.

(click to show/hide)

WM_SETCURSOR 0
WindowImplWin32::processEvent end 0
WM_MOUSEMOVE 0
WindowImplWin32::processEvent end 0
WindowImplWin32::processEvent end 0
WM_SETCURSOR 0
WindowImplWin32::processEvent end 0
WM_MOUSEMOVE 0
WindowImplWin32::processEvent end 0
WindowImplWin32::processEvents end 62
WindowImplWin32::processEvents end 0
WindowImplWin32::processEvents end 0
WindowImplWin32::processEvent end 0
WM_SETCURSOR 0
WindowImplWin32::processEvent end 0
WM_MOUSEMOVE 0
WindowImplWin32::processEvent end 0
WindowImplWin32::processEvents end 0
WindowImplWin32::processEvents end 0
WindowImplWin32::processEvent end 0

Digging deeper into the WindowImplWin32::processEvents I log the following results:

(click to show/hide)

   PeekMessageW 2
   TranslateMessage 2
   DispatchMessageW 2
   PeekMessageW 5
   TranslateMessage 5
   DispatchMessageW 5
   PeekMessageW 8
   TranslateMessage 8
   DispatchMessageW 8
   PeekMessageW 11
   TranslateMessage 11
   DispatchMessageW 11
   PeekMessageW 15
   TranslateMessage 15
   DispatchMessageW 15
   PeekMessageW 19
   TranslateMessage 19
   DispatchMessageW 19
   PeekMessageW 22
   TranslateMessage 22
   DispatchMessageW 22
   PeekMessageW 25
   TranslateMessage 26
   DispatchMessageW 26
   PeekMessageW 28
   TranslateMessage 29
   DispatchMessageW 29
   PeekMessageW 31
   TranslateMessage 31
   DispatchMessageW 31
   PeekMessageW 35
   TranslateMessage 35
   DispatchMessageW 35
   PeekMessageW 38
   TranslateMessage 38
   DispatchMessageW 38
   PeekMessageW 40
   TranslateMessage 40
   DispatchMessageW 40
   PeekMessageW 42
   TranslateMessage 42
   DispatchMessageW 42
   PeekMessageW 45
   TranslateMessage 45
   DispatchMessageW 45
   PeekMessageW 47
   TranslateMessage 47
   DispatchMessageW 47
   PeekMessageW 49
   TranslateMessage 49
   DispatchMessageW 49
   PeekMessageW 49
   TranslateMessage 49
   DispatchMessageW 49
WindowImplWin32::processEvents end 49

Judging from the timestamps we can see pretty clearly that the PeekMessageW call causes the troubles here.

The function processEvents in question looks like this:

(click to show/hide)

void WindowImplWin32::processEvents()
{
   const auto timestamp = clock();
    // We process the window events only if we own it
    if (!m_callback)
    {
        //auto timestamp_loop = clock();
        MSG message;
        while (PeekMessageW(&message, NULL, 0, 0, PM_REMOVE))
        {
            logger << "\tPeekMessageW " << GetElapsedMs(timestamp) << '\n';
            TranslateMessage(&message);
            logger << "\tTranslateMessage " << GetElapsedMs(timestamp) << '\n';
            DispatchMessageW(&message);
            logger << "\tDispatchMessageW " << GetElapsedMs(timestamp) << '\n';
            //timestamp_loop = clock();
        }
    }
    logger << "WindowImplWin32::processEvents end " << GetElapsedMs(timestamp) << '\n';
}

The MSDN page on this function is pretty straightforward https://msdn.microsoft.com/en-us/library/windows/desktop/ms644943%28v=vs.85%29.aspx?f=255&MSPPError=-2147217396. I shall see if I can narrow down what type of messages cause my issue by changing the call.

EDIT Changing the call or using the ANSI function did not change anything about the behaviour.

[Tijmen]

Testing it on my Windows 10 tablet device it suffers from no stutters and the logs show this as well. I am now pretty confident my quarrel is with the Windows API. Notable difference between the tablet and desktop is that the tablet is still on an older version of Windows Home 10 (1603), whilst the desktop is at a recent version (Windows 10 Education 1709). Furthermore their GPUs differ, with the tablet using an iGPU of Intel and the desktop running a GTX970 with driver version 391.01.

I cannot imagine this problem was present in the past, making one of the recent Windows updates or upgraded VS toolsets a probable cause. I shall investigate it further... 

EDIT Error is reproducible on another desktop running Windows 7. The odd thing even was that the PeekMessageW function doesn't have to return anything to block. It will also block for random amounts of time without any events coming actually through.

[Tijmen]

I can confirm plugging in an XBOX controller AND pressing a few random buttons on it / moving the thumbsticks THEN launch the SFML application gets rid of the spikes. I tried it before with two controllers, but I only plugged them in, did not touch any of their buttons / thumbsticks.

So that was the part I was missing... 

[eXpl0it3r]

So am I reading this right that it's the Win API that causes the delay or is it something in SFML's code?

[Tijmen]

So am I reading this right that it's the Win API that causes the delay or is it something in SFML's code?

Yes, specifically the PeekMessageW call. If you google for something like PeekMessageW delay it shows you a host of people having similar issues through the years.

A complete log can be found here on pastebin: https://pastebin.com/G88AjDrG. The spikes are spread randomly through the file. See my second post, third spoiler, for how the function looked with the logger. The numbers are in milliseconds and are measured using <ctime>'s std::clock: ((end_timestamp - start_timestamp) * 1000 / CLOCKS_PER_SEC). These modifications were made to the master branch version of SFML on GitHub and compiled using Visual Studio 2017's tools.
Edit I see this log is not very representative, but testing for longer created huge logs with more peaks. Since I had my logger overwrite any previous logs I do not have a good example handy at this moment. If anyone wants I can redo it and pick out a more interesting section of the log. Or log it differently.

The pictures in my third post are from a friend's SFML project that has the same issue but the delay introduced by PeekMessageW was considerably less. He runs Windows 7 with Visual Studio 2015. Why my stutters were up to 60+ milliseconds is still a mystery to me.

My tablet device running Windows 10 Home 1607 (not 1603, oops) does not have this stuttering issue. Interestingly enough it also has probably never had a gamepad attached to it. I am not going to try to find out if that's the origin of the problem, since I want to test my app on that without having to do silly things with a gamepad.

[Tijmen]

Just a heads up on this issue. I can't seem to reproduce it with SFML 2.5.0 in DEBUG builds. The problem does appear irregularly in RELEASE builds. Very strange!

I've double checked that the include folders and lib folders point at the SFML 2.5.0 binaries, so I am not mixing versions. I am using a static build of SFML.

If anyone is interested I can dig some more into it. I just briefly checked with the new release. Doesn't seem to reliably fix the problem.

main loop time recordings:

(click to show/hide)

Frame [662] start <0 ms> inputhandling <6 ms> manager-update <0 ms> draw-display <9 ms>
Frame [663] start <0 ms> inputhandling <10 ms> manager-update <0 ms> draw-display <5 ms>
Frame [664] start <0 ms> inputhandling <26 ms> manager-update <0 ms> draw-display <0 ms>
Frame [665] start <0 ms> inputhandling <41 ms> manager-update <0 ms> draw-display <0 ms>
Frame [666] start <0 ms> inputhandling <4 ms> manager-update <0 ms> draw-display <0 ms>
Frame [667] start <0 ms> inputhandling <3 ms> manager-update <0 ms> draw-display <3 ms>
Frame [668] start <0 ms> inputhandling <3 ms> manager-update <0 ms> draw-display <11 ms>
Frame [669] start <0 ms> inputhandling <2 ms> manager-update <0 ms> draw-display <13 ms>
Frame [670] start <0 ms> inputhandling <3 ms> manager-update <0 ms> draw-display <13 ms>
Frame [671] start <0 ms> inputhandling <14 ms> manager-update <0 ms> draw-display <1 ms>
Frame [672] start <0 ms> inputhandling <10 ms> manager-update <0 ms> draw-display <5 ms>
Frame [673] start <0 ms> inputhandling <26 ms> manager-update <0 ms> draw-display <0 ms>
Frame [674] start <0 ms> inputhandling <0 ms> manager-update <0 ms> draw-display <9 ms>
Frame [675] start <1 ms> inputhandling <29 ms> manager-update <0 ms> draw-display <0 ms>
Frame [676] start <0 ms> inputhandling <9 ms> manager-update <0 ms> draw-display <0 ms>

Particular bad example from the event polling loop (integer values are in milliseconds):

(click to show/hide)

clr-state <0> ev-catch <13> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <6> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <8> ev-catch <52> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <7> ev-catch <2> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <0> ev-catch <1> ev-catch <4> ev-catch <1>
        TOTAL 106 ms

(each ev-catch is for a PollEvent result, note the ridicules number of events as well)

[eXpl0it3r]

I can't reproduce this and it's happening irregularly, as such I'd suggest to modify SFML and build in some logging into the event loop, that way, you should be able to identify for what kind of events the loop slows down.

[Tijmen]

All PeekMessageW events were of type 512 -> 0x200 -> WM_MOUSEMOVE oddly enough. This is before translation and dispatch of said message. Do I need to record its contents at another stage perhaps?

Example output:

(click to show/hide)

WindowImplWin32::processEvents took 3ms
        Message type <512> took 0 milliseconds
        Message type <512> took 2 milliseconds
WindowImplWin32::processEvents took 11ms
        Message type <512> took 1 milliseconds
        Message type <512> took 3 milliseconds
        Message type <512> took 3 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 0 milliseconds
WindowImplWin32::processEvents took 3ms
        Message type <512> took 1 milliseconds
        Message type <512> took 0 milliseconds
WindowImplWin32::processEvents took 4ms
        Message type <512> took 1 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 0 milliseconds
        Message type <512> took 0 milliseconds
WindowImplWin32::processEvents took 3ms
        Message type <512> took 1 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 0 milliseconds
WindowImplWin32::processEvents took 4ms
        Message type <512> took 2 milliseconds
        Message type <512> took 1 milliseconds
WindowImplWin32::processEvents took 3ms
        Message type <512> took 2 milliseconds
WindowImplWin32::processEvents took 5ms
        Message type <512> took 2 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 0 milliseconds
WindowImplWin32::processEvents took 3ms
        Message type <512> took 1 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 0 milliseconds
        Message type <512> took 0 milliseconds
WindowImplWin32::processEvents took 23ms
        Message type <512> took 2 milliseconds
        Message type <512> took 5 milliseconds
        Message type <512> took 2 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 2 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 0 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 0 milliseconds
        Message type <512> took 0 milliseconds
WindowImplWin32::processEvents took 3ms
        Message type <512> took 2 milliseconds
        Message type <512> took 1 milliseconds
WindowImplWin32::processEvents took 4ms
        Message type <512> took 1 milliseconds
        Message type <512> took 1 milliseconds
        Message type <512> took 0 milliseconds

Measured in /src/SFML/Window/Win32/WindowImplWin32.cpp :

(click to show/hide)

void WindowImplWin32::processEvents()
{
   // We process the window events only if we own it
   if (!m_callback)
   {
      MSG message;
      std::vector<long long> msgs;
      msgs.reserve(16);

      const auto fn_start = std::chrono::system_clock::now();

      auto start = std::chrono::high_resolution_clock::now();
      while (PeekMessageW(&message, NULL, 0, 0, PM_REMOVE))
      {
         const auto timespan = std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now() - start).count();
         msgs.push_back(message.message);
         msgs.push_back(timespan);

         TranslateMessage(&message);
         DispatchMessageW(&message);

         start = std::chrono::high_resolution_clock::now();
      }

      const auto fn_duration = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now() - fn_start).count();
      if(fn_duration > 2)
      {
         std::cout << "WindowImplWin32::processEvents took " << fn_duration << "ms\n";
         for(size_t i = 0; i < msgs.size(); i += 2)
         {
            std::cout << "\tMessage type <" << msgs << "> took " << (msgs[i + 1] / 1000) << " milliseconds\n";
         }
      }
   }
}

I do not have this issue in any other application, including a variety of games, which makes me very suspicious of me doing something weird I'll see if I can make a minimal working example.

EDIT: I can't seem to make a simpler version of it. This suggests to me that I am doing something wonky... somewhere. OR that something is seriously messed up with my drivers, as it appears irregularly. What an annoying problem