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 (https://github.com/TijmenUU/smarttalesii), but it specifically happens in https://github.com/TijmenUU/smarttalesii/blob/master/smart_tales_ii/inputhandler.cpp (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 (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:
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:
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
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.
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:
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:
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 (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.
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:
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):
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)
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:
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 :
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 :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 :(