Welcome, Guest. Please login or register. Did you miss your activation email?

Author Topic: Weird long polls with Window::pollEvent  (Read 2094 times)

0 Members and 1 Guest are viewing this topic.

Tijmen

  • Newbie
  • *
  • Posts: 12
    • View Profile
Weird long polls with Window::pollEvent
« on: April 03, 2018, 06:53:39 pm »
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)

And in my log file it looks like this:
(click to show/hide)
« Last Edit: April 03, 2018, 07:04:50 pm by Tijmen »

Tijmen

  • Newbie
  • *
  • Posts: 12
    • View Profile
Re: Weird long polls with Window::pollEvent
« Reply #1 on: April 05, 2018, 11:07:52 am »
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)

Digging deeper into the WindowImplWin32::processEvents I log the following results:
(click to show/hide)
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)

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.
« Last Edit: April 05, 2018, 11:49:14 am by Tijmen »

Tijmen

  • Newbie
  • *
  • Posts: 12
    • View Profile
Re: Weird long polls with Window::pollEvent
« Reply #2 on: April 05, 2018, 11:48:16 am »
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.




« Last Edit: April 05, 2018, 03:03:40 pm by Tijmen »

Tijmen

  • Newbie
  • *
  • Posts: 12
    • View Profile
Re: Weird long polls with Window::pollEvent
« Reply #3 on: April 05, 2018, 05:30:49 pm »
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

  • SFML Team
  • Hero Member
  • *****
  • Posts: 10226
    • View Profile
    • development blog
    • Email
Re: Weird long polls with Window::pollEvent
« Reply #4 on: April 05, 2018, 05:57:17 pm »
So am I reading this right that it's the Win API that causes the delay or is it something in SFML's code?
Official FAQ: https://www.sfml-dev.org/faq.php
Nightly Builds: https://www.nightlybuilds.ch/
——————————————————————
Dev Blog: https://dev.my-gate.net/
Thor: http://www.bromeon.ch/libraries/thor/

Tijmen

  • Newbie
  • *
  • Posts: 12
    • View Profile
Re: Weird long polls with Window::pollEvent
« Reply #5 on: April 05, 2018, 06:26:36 pm »
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.
« Last Edit: April 05, 2018, 06:32:11 pm by Tijmen »

Tijmen

  • Newbie
  • *
  • Posts: 12
    • View Profile
Re: Weird long polls with Window::pollEvent
« Reply #6 on: May 08, 2018, 03:42:40 pm »
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)

Particular bad example from the event polling loop (integer values are in milliseconds):
(click to show/hide)
(each ev-catch is for a PollEvent result, note the ridicules number of events as well)

eXpl0it3r

  • SFML Team
  • Hero Member
  • *****
  • Posts: 10226
    • View Profile
    • development blog
    • Email
Re: Weird long polls with Window::pollEvent
« Reply #7 on: May 08, 2018, 04:08:08 pm »
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.
Official FAQ: https://www.sfml-dev.org/faq.php
Nightly Builds: https://www.nightlybuilds.ch/
——————————————————————
Dev Blog: https://dev.my-gate.net/
Thor: http://www.bromeon.ch/libraries/thor/

Tijmen

  • Newbie
  • *
  • Posts: 12
    • View Profile
Re: Weird long polls with Window::pollEvent
« Reply #8 on: May 08, 2018, 08:14:50 pm »
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)

Measured in /src/SFML/Window/Win32/WindowImplWin32.cpp :
(click to show/hide)

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 :P 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 :(
« Last Edit: May 08, 2018, 08:47:39 pm by Tijmen »