SDL: Event processing seems to be slow and dependent on the SDL_Delay interval between frames
I have created a fairly complex main loop in my engine. This loop calls the logic update and rendering functions at approximately equal intervals (fixed/limited frame rate). I have neither the target logic update code nor the rendering code yet, so I implemented spinlocks that mimic the actual code.
These spinlocks consume a certain number of milliseconds over and over again by calling SDL_GetPerformanceCounter, so they wait a given number of milliseconds with a very high precision (usually down to a microsecond). I added code for updating and rendering time measurements, which are represented as milliseconds (as floats). If the spinlock of the logic update is to be 5ms and the rendering time is 10ms, the measurement results look something like this:
Update: 5.00059ms | Render: 10.00030ms
A high enough precision. This is where the problem arises. Logic update is also event queue processing, so the update measurement relates to event processing and the update function (the one with a spinlock for 5ms). The results are as follows:
Update: 5.14063ms | Render: 10.00047ms
If I exclude the 5ms spinlock from the measurement and measure only the event queue processing time, the results look like this:
Update: 0.18426ms | Render: 10.00049ms
Thus, processing the event queue itself takes from a few tenths of a millisecond to even more than one millisecond (sometimes almost two milliseconds). It is unacceptable for event processing to take up to 5-10% of the time devoted to generating a frame (at 60fps). I measured the SDL event processing time by running the program and not generating any events (I didn’t move the mouse, I didn’t press any keys), so the events queue was empty almost all the time.
I thought the problem was with my loop, so I created a minimal test program to test the event processing only measurement. It looks like this:
{$MODE OBJFPC}
uses
SDL2;
var
Window: PSDL_Window;
Event: TSDL_Event;
var
Stopped: Boolean = False;
var
TicksLast: Int64;
TicksCurrent: Int64;
var
CounterBegin: Int64;
CounterEnd: Int64;
CounterSample: Int64;
CounterPerSecond: Int64;
begin
SDL_Init(SDL_INIT_EVERYTHING);
Event := Default(TSDL_Event);
Window := SDL_CreateWindow(nil, SDL_WINDOWPOS_CENTERED, SDL_WINDOWPOS_CENTERED, 800, 600, SDL_WINDOW_SHOWN);
CounterPerSecond := SDL_GetPerformanceFrequency();
TicksLast := SDL_GetTicks64() div (1000 div 4);
repeat
CounterBegin := SDL_GetPerformanceCounter();
while SDL_PollEvent(@Event) = 1 do
if Event.Type_ = SDL_QUITEV then
Stopped := True;
CounterEnd := SDL_GetPerformanceCounter();
CounterSample := CounterEnd - CounterBegin;
TicksCurrent := SDL_GetTicks64() div (1000 div 4);
if TicksCurrent <> TicksLast then
begin
WriteLn('time: ', (CounterSample * 1000 / CounterPerSecond):1:3, 'ms | sample: ', CounterSample);
TicksLast := TicksCurrent;
end;
SDL_Delay(1);
until Stopped;
SDL_DestroyWindow(Window);
SDL_Quit();
end.
Operation is simple:
- get the number of ticks before processing the event loop,
- process all queued events
- get the number of ticks after processing the event loop,
- display the measurement in the console (limited to four times per second)
- wait a millisecond for the next measurement (it saves CPU) and go back to step 1.
The results are as follows:
time: 0.046ms | sample: 461
time: 0.010ms | sample: 100
time: 0.047ms | sample: 465
time: 0.010ms | sample: 103
time: 0.047ms | sample: 473
time: 0.010ms | sample: 103
time: 0.047ms | sample: 469
time: 0.010ms | sample: 103
time: 0.047ms | sample: 468
time: 0.010ms | sample: 101
time: 0.124ms | sample: 1238
time: 0.047ms | sample: 467
time: 0.010ms | sample: 101
time: 0.046ms | sample: 463
time: 0.136ms | sample: 1359
time: 0.136ms | sample: 1362
time: 0.045ms | sample: 449
As you can see, the very processing of events (despite not generating them) takes from a few hundredths of a millisecond to a few tenths of a millisecond. Now the most interesting — I change SDL_Delay(1) to SDL_Delay(10):
time: 0.091ms | sample: 905
time: 0.068ms | sample: 681
time: 0.379ms | sample: 3794
time: 0.103ms | sample: 1033
time: 0.069ms | sample: 686
time: 0.176ms | sample: 1764
time: 0.294ms | sample: 2942
time: 0.175ms | sample: 1754
time: 0.121ms | sample: 1210
time: 0.093ms | sample: 933
time: 0.095ms | sample: 949
time: 0.090ms | sample: 901
time: 0.089ms | sample: 893
time: 0.076ms | sample: 761
time: 0.179ms | sample: 1793
Now event processing takes from a few hundredths of a millisecond to even 0.4ms. Now for SDL_Delay(100):
time: 0.295ms | sample: 2945
time: 0.345ms | sample: 3451
time: 0.794ms | sample: 7941
time: 0.323ms | sample: 3227
time: 0.298ms | sample: 2982
time: 0.295ms | sample: 2953
time: 0.469ms | sample: 4691
time: 0.295ms | sample: 2950
time: 0.323ms | sample: 3230
time: 0.615ms | sample: 6154
time: 0.340ms | sample: 3403
time: 0.339ms | sample: 3388
time: 0.356ms | sample: 3556
time: 0.337ms | sample: 3370
time: 0.343ms | sample: 3433
time: 1.159ms | sample: 11585
time: 0.660ms | sample: 6601
time: 0.341ms | sample: 3411
time: 0.352ms | sample: 3523
time: 0.342ms | sample: 3415
Processing of events takes from a few tenths of a millisecond to over one millisecond. For SDL_Delay(500):
time: 2.073ms | sample: 20731
time: 1.399ms | sample: 13985
time: 3.798ms | sample: 37983
time: 4.745ms | sample: 47452
time: 2.030ms | sample: 20296
time: 2.040ms | sample: 20396
time: 2.259ms | sample: 22590
time: 4.019ms | sample: 40187
time: 2.196ms | sample: 21957
time: 1.975ms | sample: 19749
time: 2.307ms | sample: 23074
time: 2.301ms | sample: 23013
time: 2.593ms | sample: 25927
time: 1.972ms | sample: 19722
time: 2.032ms | sample: 20317
time: 3.758ms | sample: 37582
Now it takes a few milliseconds all the time. For SDL_Delay(1000):
time: 4.549ms | sample: 45487
time: 4.860ms | sample: 48596
time: 4.597ms | sample: 45973
time: 4.699ms | sample: 46986
time: 5.158ms | sample: 51582
time: 4.550ms | sample: 45502
time: 5.308ms | sample: 53084
time: 5.304ms | sample: 53037
time: 2.319ms | sample: 23192
time: 4.635ms | sample: 46354
time: 4.761ms | sample: 47608
time: 4.454ms | sample: 44542
time: 4.637ms | sample: 46371
time: 4.949ms | sample: 49490
time: 4.469ms | sample: 44686
time: 4.661ms | sample: 46608
time: 4.728ms | sample: 47281
As you can see, the larger the SDL_Delay interval between individual measurements, the longer it takes to process the event queue, or at least this is what the measurements show. The larger the interval, the greater the difference in the number of ticks taken before and after the event loop.
Why does the interval of the SDL_Delay function called between measurements affect the measurement of event processing time? After all, this function is called between measurements, not during them, so it should not affect them (only increase or decrease the number of measurements per second).
The same is true if I explicitly use the QueryPerformanceFrequency, QueryPerformanceCounter and Sleep functions, so this is not a problem with SDL_Delay (especially since it uses Sleep internally).
I know guys that you use C language and I use Free Pascal, so in the attachment I added test programs compiled in FPC so that you can test them on your own (Win 64-bit). Attached is the last stable library SDL2.dll, downloaded from this repository.
There are several executable files in the attachment — the number in the executable name is the interval used in the SDL_Delay function called between measurements (no number in the name is a version without using SDL_Delay).
Attachment — timming_test.zip
About this issue
- Original URL
- State: closed
- Created 2 years ago
- Comments: 15 (8 by maintainers)
@peppy: even if
PeekEventsworks for their case, I think it is worth to check whyPumpEventsis slow. At some pointPumpEventsmust be called either directly or indirectly. It does not make sense to expect the application to change its main loop.@furious-programming : do you have some special sensor or what kind of videocard are you using? I think it would help to find out the bottleneck. Have you tried to set SDL_JOYSTICK_DISABLED or SDL_SENSOR_DISABLED?
I’ll go ahead and close this, but if you find new information, please let us know!
Before creating this issue, I checked if the queue was actually empty, so I did not include it in the logs. Anyway, it is logical that if I do not move the mouse over the window and do not press the keys, then no events are generated.
Okay, here are the logs with added event count tracking and comments that indicate problematic lines. This time, I alternately did nothing and tested the event generation by moving the cursor over the window. I removed the excess lines showing
0events to shorten the log. This is a test forSDL_Delay(1):As can be clearly seen in the logs, when events appear in the queue, their processing time varies greatly. SDL can return
30events in0.01 ms, and then returns a similar number of events in several dozen times longer. Besides, once in a while it takes even0.2 msto process an empty queue (so calling theSDL_PollEventfunction to get the result0).Another problem I noticed is that when you drag a window with the mouse, by grabbing its title bar, it adds moving time to adding the event processing time itself. Example for
SDL_Delay(1):I held the window by the title bar and moved it for about two seconds. The time of holding and moving the window has been added to the measurement — why? This happens at any
SDL_Delayinterval and every time I move the window.And this is the test for
SDL_Delay(100)between measurements:When no events is processed, the times are significantly longer. For the
SDL_Delay(1000):The times are ridiculous. It’s also interesting that I’m moving the cursor all the time, making circles, but the queue only gets one event each second. The situation is different if I also click LMB while making circles with the cursor:
There are many events in the queue, but I didn’t click 21 times per second, but only few times per second (3-5), so the rest of the events must be related to the mouse movement.
It should also be taken into account that if the
SDL_Delayinterval is less than a quarter of a second (e.g.1or10), the number of events displayed in the console does not apply to the number of events per frame, but to the sum of events in the last250 ms. If the event counter is reset every frame (below printing data, at the end of the loop), the number of events in the console will be smaller, but the time samples will be the same (so much the worse for SDL).It is difficult for me to say why the measurements look like this, and it is especially difficult for me to understand why manipulating the
SDL_Delayinterval (which is called between frames) has a real impact on the amount of time used bySDL_PollEvent. I am adding a new package of test programs to the attachments, which also displays the number of processed events every quarter second (events counter is reset 4 times per second).Attachment — timming_test_2.zip
Here is the code template of these programs: