Measure code execution and convert the result to milliseconds

[furious programming]

In my game design, I wrote a main loop to update the logic, render the frame and wait for the next frame. Everything works great. I added a code to measure precisely how long the logic update takes and how long it takes to render the frame — the result is converted into milliseconds (as float). Logic update is the processing of events from the SDL queue and calling the update function. I have neither logic nor rendering code yet, so I am currently imitating them with spinlocks that run for a few milliseconds (5ms as updating, 10ms as rendering). This is where the problem arises.

It turns out that the logic update takes more than 5ms, most often from 5.1ms to 5.4ms. If I remove the spinlock (that is, take up the CPU for 5ms), the processing of SDL events itself takes from 0.1ms to 0.4ms, sometimes even over 1ms! So I prepared a test program to confirm that the problem was with the measurement and not with my game code. This is what the tester looks like:

Code: Pascal  [Select][+][-]

1. {$MODE OBJFPC}
2.  
3. uses
4.   SDL2;
5. var
6.   Window: PSDL_Window;
7.   Event:  TSDL_Event;
8. var
9.   Stopped: Boolean = False;
10. var
11.   TicksLast:     UInt64;
12.   TicksCurrent:  UInt64;
13. var
14.   CounterBegin:     UInt64;
15.   CounterSample:    UInt64;
16.   CounterPerSecond: UInt64;
17. begin
18.   SDL_Init(SDL_INIT_EVERYTHING);
19.  
20.   Event  := Default(TSDL_Event);
21.   Window := SDL_CreateWindow(nil, SDL_WINDOWPOS_CENTERED, SDL_WINDOWPOS_CENTERED, 800, 600, SDL_WINDOW_SHOWN);
22.  
23.   CounterPerSecond := SDL_GetPerformanceFrequency();
24.   TicksLast        := SDL_GetTicks64() div (1000 div 4);
25.  
26.   repeat
27.     CounterBegin := SDL_GetPerformanceCounter();
28.  
29.       SDL_PumpEvents();
30.  
31.       while SDL_PollEvent(@Event) = 1 do
32.         Stopped := Event.Type_ = SDL_QUITEV;
33.  
34.     CounterSample := SDL_GetPerformanceCounter() - CounterBegin;
35.     TicksCurrent  := SDL_GetTicks64() div (1000 div 4);
36.  
37.     if TicksCurrent <> TicksLast then
38.     begin
39.       WriteLn('time: ', (CounterSample / CounterPerSecond * 1000):1:3, 'ms | sample: ', CounterSample);
40.       TicksLast := TicksCurrent;
41.     end;
42.  
43.     SDL_Delay(10);
44.   until Stopped;
45.  
46.   SDL_DestroyWindow(Window);
47.   SDL_Quit();
48. end.

The key is the code highlighted in yellow — event processing measurement, converting the sample to milliseconds and printing it, thread delay. Execution of the above code causes displaying the following sample data:

Code: Pascal  [Select][+][-]

1. time: 0.523ms | sample: 5231
2. time: 0.238ms | sample: 2380
3. time: 0.194ms | sample: 1941
4. time: 0.808ms | sample: 8080
5. time: 0.107ms | sample: 1070
6. time: 0.104ms | sample: 1042
7. time: 0.090ms | sample: 901
8. time: 0.115ms | sample: 1147
9. time: 0.152ms | sample: 1519
10. time: 0.420ms | sample: 4203

I don't generate events — I don't move the mouse or press any keys on the keyboard, so all this time the SDL event queue is empty. Even so, checking the event queue takes up to a millisecond. Strange things are happening right now — I change SDL_Delay(10) to SDL_Delay(100) and I get these results:

Code: Pascal  [Select][+][-]

1. time: 0.761ms | sample: 7609
2. time: 0.584ms | sample: 5836
3. time: 0.445ms | sample: 4445
4. time: 1.680ms | sample: 16797
5. time: 0.731ms | sample: 7308
6. time: 1.574ms | sample: 15739
7. time: 0.445ms | sample: 4450
8. time: 0.503ms | sample: 5034

As you can see, checking the event queue takes much longer. And now I will change to SDL_Delay(1000):

Code: Pascal  [Select][+][-]

1. time: 2.850ms | sample: 28501
2. time: 2.813ms | sample: 28133
3. time: 2.821ms | sample: 28213
4. time: 3.445ms | sample: 34452
5. time: 8.337ms | sample: 83373
6. time: 3.104ms | sample: 31039
7. time: 3.134ms | sample: 31337
8. time: 3.093ms | sample: 30932
9. time: 5.055ms | sample: 50552
10. time: 4.454ms | sample: 44541
11. time: 5.150ms | sample: 51498

Even 5ms to check empty events queue... If I remove or comment out SDL_Delay, the results are minimal:

Code: Pascal  [Select][+][-]

1. time: 0.002ms | sample: 15
2. time: 0.002ms | sample: 15
3. time: 0.002ms | sample: 15
4. time: 0.002ms | sample: 15
5. time: 0.002ms | sample: 16
6. time: 0.002ms | sample: 17
7. time: 0.005ms | sample: 47
8. time: 0.002ms | sample: 15
9. time: 0.002ms | sample: 15
10. time: 0.002ms | sample: 15
11. time: 0.002ms | sample: 24

Sometimes the sample jump up to several hundred or several thousand cycles.

Can anyone tell me what's going on in this code? Why the processing of the almost constantly empty SDL event queue takes so long (even a few milliseconds) and what has to do with this SDL_Delay, which is not called during the measurement, but between measurements?

The entire test project is attached. To the program directory (next to exe file) you should paste the SDL2.dll library (here is the link to download the latest stable binary).

Either SDL_Delay affects the efficiency of reading events in some weird way, or SDL_GetPerformaceCounter returns incorrect results, or my calculations for converting tick measurements to milliseconds are incorrect. Although I doubt it, since the difference in measurement ticks (visible in the console in the sample column) clearly increases with the increase of the interval between measurements.

[Paul_]

I'm not sure whether loop is correct, but you can try https://wiki.freepascal.org/EpikTimer if there will be difference. SDL2 timing functions are not reliable for benchmarking or for other purposes that require precision like manual framerate limit via SDL_Delay(). It is not entirely clear which system clock is being used. Especially on different operating systems.

[furious programming]

I'm not sure whether loop is correct […]

What I just mentioned is not a game loop, but a test program to illustrate the problem with time-consuming SDL event processing caused by using SDL_Delay, which we should focus on.

My engine has a much more complicated main loop structure which provides a constant number of updates per second (using a constant time delta), allows it to render any number of frames, independent and different from the number of updates, and the rest of the time is given back to the system, ensuring minimal CPU power consumption. In addition, it provides precise measurements of averaged logic update time and renders, performed any number of times per second, expressed with 100-nanosecond precision (measurement results are converted to milliseconds in the form of a floating point number). There are more features — lag prevention, reading events in portions according to the current delta time, ”spiral of death” prevention and more.

Thus, the main game loop ensures that the three mechanisms (logic update, frame rendering and counters refreshing) work independently, at different frequencies, still sequentially (single-threaded), and gives the rest of the free time to the system. For example, it can update logic 60 times per second, render 50 frames per second, and refresh meters with various averaged measurements 7 times per second — each mechanism at equal intervals according to the given settings, which can be freely changed in the runtime. It's just for the record.

[…] but you can try https://wiki.freepascal.org/EpikTimer if there will be difference.

I will not try it, because firstly the results will be the same, and secondly, I will not add more dependencies just to replace simple arithmetic. Using EpikTimer won't do any good for me, because both it and SDL use QueryPerformanceFrequency and QueryPerformanceCounter internally (under Windows).

SDL2 timing functions are not reliable for benchmarking or for other purposes that require precision like manual framerate limit via SDL_Delay().

You're wrong. SDL2 functions like SDL_GetPerformanceFrequency and SDL_GetPerformanceCounter allow for very precise timing (and these are the ones I use in my engine and in the tester from this thread), because they use platform mechanisms with the highest resolution. On Windows it is QPF and QPC, which is a counter that performs millions of ticks per second (on my laptop it is 10 million ticks per second, or 10MHz). On other platforms, SDL2 uses different mechanisms, but also those with the highest resolution.

Secondly, the use of SDL_Delay (internally: Sleep on Windows) is the only available solution that allows you to create gaps between frames without using spinlocks (busy waiting), i.e. without using the CPU power to wait a given amount of time. Any serious game engine provides the ability to limit the framerate and thus save energy, so each engine necessarily uses the system's Sleep function directly or indirectly. For example, see the engine used by the S.T.A.L.K.E.R. game, whose sources are on GitHub and which is also based on SDL2.

It is not entirely clear which system clock is being used. Especially on different operating systems.

That is clear, just read the documentation or check the SDL2 sources.

I suggest focusing on the essence of the problem that the thread I set up concerns, i.e. the long processing of SDL events and the times that increase with the increase of the intervals between measurements, and not on the implementation of the main game loop, which I have not shown here at all.

[KodeZwerg]

I will not try it, because firstly the results will be the same, and secondly, I will not add more dependencies just to replace simple arithmetic. Using EpikTimer won't do any good for me, because both it and SDL use QueryPerformanceFrequency and QueryPerformanceCounter internally (under Windows).

I would not agree when I did understand all correct.
EpikTimer would be native in code calling Windows API methods, your code calls an external library (sdl2.dll) that calls Windows API get back to sdl2.dll to give it your app.
What be faster?....

[furious programming]

It doesn't matter, because before I started this topic, I checked the code directly using the QueryPerformanceFrequency, QueryPerformanceCounter and Sleep functions, which are imported in the Windows unit. And the result is exactly the same. You don't have to believe me — the test program is attached, you can download, replace the SDL functions with those of the Win32 API and see that nothing will change.

[mika]

i.e. the long processing of SDL events and the times that increase with the increase of the intervals between measurements, and not on the implementation of the main game loop, which I have not shown here at all.

Agree and culprit is:

Code: Pascal  [Select][+][-]

1. SDL_PumpEvents();

Longer interval in between calls - longer execution of mentioned procedure. It seams that there is upper limit, but  in case of event accruing execution is even longer.

[Jorg3000]

Hi!

Sometimes the sample jump up to several hundred or several thousand cycles.

Could it simply be that the CPU core has processed another thread in between?

Code: Pascal  [Select][+][-]

1. Windows.SetPriorityClass(Windows.GetCurrentProcess(),HIGH_PRIORITY_CLASS);  // REALTIME_PRIORITY_CLASS
2.  

Actually you should measure it using REALTIME_PRIORITY_CLASS, but that is only available as admin, I think.
Jörg

[furious programming]

@mika: SDL_PumpEvents should not be used if the events are being pulled from the queue using SDL_PollEvent. All because SDL_PollEvent can call SDL_PumpEvents internally. But even if I remove it and leave only the loop, reading the events is still time consuming and continues to fluctuate as the interval between measurements increases. So removing SDL_PumpEvents fixes almost nothing, because the time gain is microscopic:

Code: Pascal  [Select][+][-]

1. time: 0.090ms | sample: 899
2. time: 0.231ms | sample: 2313
3. time: 0.090ms | sample: 898
4. time: 0.090ms | sample: 903
5. time: 0.321ms | sample: 3206
6. time: 0.090ms | sample: 896
7. time: 0.089ms | sample: 893
8. time: 0.071ms | sample: 708
9. time: 0.089ms | sample: 892
10. time: 0.090ms | sample: 899
11. time: 0.191ms | sample: 1911
12. time: 0.077ms | sample: 767
13. time: 0.610ms | sample: 6099
14. time: 0.089ms | sample: 894
15. time: 0.072ms | sample: 716
16. time: 0.091ms | sample: 912
17. time: 0.091ms | sample: 906
18. time: 0.070ms | sample: 700
19. time: 0.094ms | sample: 943
20. time: 0.074ms | sample: 739
21. time: 0.100ms | sample: 1003
22. time: 0.651ms | sample: 6509
23. time: 0.098ms | sample: 975
24. time: 0.765ms | sample: 7652
25. time: 0.354ms | sample: 3535

As you can see, processing an ~empty queue still takes up to half a millisecond (with SDL_Delay(10) between frames/measurements), and when I move the cursor over the window quickly (for example, making a circles), it takes up to two milliseconds to get events out of the queue, which is ridiculous. There is a hidden problem, and I don't know where exaclty. This test program is too simple to make such a terrible bugs (still I don't see any).

@Jorg3000: I don't want to use platform specific functions — the game code must be cross-platform, that's why I'm using SDL functions only. Anyway, using the administrator's rights and setting the "real time" priority does not change anything.

[Paul_]

What I just mentioned is not a game loop .. and not on the implementation of the main game loop, which I have not shown here at all

I didn't mention "game loop" anywhere. There is repeat while loop in the code above. Therefore, I wrote about the loop.

Secondly, the use of SDL_Delay (internally: Sleep on Windows) is the only available solution that allows you to create gaps between frames without using spinlocks (busy waiting)

This is rather a dead end if you want to use vsync for example. There are a number of techniques that can be combined in various ways and where Sleep() is not used - https://dewitters.com/dewitters-gameloop/, https://gafferongames.com/post/fix_your_timestep/ but I assume you've seen it before.

SDL2 - SDL_Delay() issues - https://discourse.libsdl.org/t/sdl-delay-accuracy-question/20458/4 (still actual, I guess)

[mika]

@furious programming you cannot get rid of SDL_PumpEvents. If you use SDL_PollEvent, then it will call SDL_PumpEvents for you. I only confirmed that there is a problem. You have to find solution.
For me maximal time for SDL_PumpEvents was 1ms and with event 3ms. Still possible achieve decent frame rates. You cannot expect constant execution time for any code, especially, when measurement interval is small. 1ms is small interval.

[furious programming]

This is rather a dead end if you want to use vsync for example.

I'm not interested in supporting VSync.

There are a number of techniques that can be combined in various ways and where Sleep() is not used

Well, that's why these loops use as much CPU power as possible by using spinlocks. So what if they work and meet the assumption, since their operation raises the frequency of the CPU to the maximum (if possible, probably also activates the CPU Turbo mode) and quickly drains the energy from the battery. This is not good, especially for battery powered mobile devices (such as laptops). And even worse now, when electricity prices are rising drastically.

That's why I wrote my own version of the main game loop which meets the assumptions of the articles you provided, but does not use spinlocks, so it uses a minimal amount of CPU power. And this can only be achieved with SDL_Delay (at least on Windows).

SDL2 - SDL_Delay() issues - https://discourse.libsdl.org/t/sdl-delay-accuracy-question/20458/4 (still actual, I guess)

I don't mind the low precision of the SDL_Delay function, and the fact that executing this function between event processing measurements affects the processing time itself. And as you can see in the example code, the measurement is not performed with SDL_Delay, but with SDL_GetPerformanceCounter functions, which have nothing to do with SDL_Delay and its intervals.

@furious programming you cannot get rid of SDL_PumpEvents. If you use SDL_PollEvent, then it will call SDL_PumpEvents for you.

It looks like self-denial — I don't know if you wanted to write that. In any case, SDL_PumpEvents is redundant when using SDL_PollEvent.

Still possible achieve decent frame rates.

Not if the frame generation time is approaching the maximum allotted time for the frame. For example, if the logic update takes 5ms and the rendering time is 10ms, the game will drop frames if SDL is so slow in processing events.

You cannot expect constant execution time for any code, especially, when measurement interval is small. 1ms is small interval.

I will write again and bold the key part, to be clearly visible — the measurement is performed using the SDL_GetPerformanceCounter function (internally a QPC from Win32 API), which provides an interval of 100ns (100 nanoseconds, because its resolution is 10 million ticks per second on my laptop).

See this — https://learn.microsoft.com/en-us/windows/win32/sysinfo/acquiring-high-resolution-time-stamps#direct-tsc-usage — this is the same method of measuring execution time I'm using in my code. Also, the multiplication by 1000 first and then the division by the counter resolution do not change anything, because the time result (visible in the console) must be in milliseconds, not microseconds (floating point precision does not distort the results).

[Paul_]

Well, that's why these loops use as much CPU power as possible by using spinlocks.

When the game logic is started at the exact time and then waiting for next exact time, how such solution itself can load the processor at 100%?

[furious programming]

When the game logic is started at the exact time and then waiting for next exact time, how such solution itself can load the processor at 100%?

And how do you want to wait for that "exact time" other than doing spinlock?

The loops in these articles perform millions of iterations and time tests before the condition is true and the frame can be updated and rendered. And those millions of iterations testing to see if "exact time" has arrived are doing a spinlock that will consume all available CPU power. This is not a rocket science.

Also, in article https://dewitters.com/dewitters-gameloop/ you have sampl loop that use the system's Sleep function to limit CPU usage (second in the article):

Code: C  [Select][+][-]

1. const int FRAMES_PER_SECOND = 25;
2. const int SKIP_TICKS = 1000 / FRAMES_PER_SECOND;
3.  
4. DWORD next_game_tick = GetTickCount();
5. // GetTickCount() returns the current number of milliseconds
6. // that have elapsed since the system was started
7.  
8. int sleep_time = 0;
9.  
10. bool game_is_running = true;
11.  
12. while( game_is_running ) {
13.     update_game();
14.     display_game();
15.  
16.     next_game_tick += SKIP_TICKS;
17.     sleep_time = next_game_tick - GetTickCount();
18.     if( sleep_time >= 0 ) {
19.         Sleep( sleep_time );
20.     }
21.     else {
22.         // Shit, we are running behind!
23.     }
24. }

See?

Also, even in the comments below this article, it is noted that these more advanced loops do not use the Sleep function, and therefore use maximum CPU power. Admittedly, the author of this comment asked a question because he was either unsure or tried to be kind, but it is obvious that if Sleep is not present then full CPU power is used and waiting for "exact time" is pure spinlock. In both articles all the loops do just that — eat as many power as the game can.

There are only two solutions — either spinlock or Sleep, depending on requirements. Either we gain very precise intervals between frames (at the expense of the maximum CPU consumption), or we reduce the CPU consumption to a minimum (at the cost of a bit less precise intervals between frames). I chose the second approach — the lowest CPU consumption possible, because an error of one millisecond waiting for the frame to be generated (because of the low precision of SDL_Delay) is not of great importance (it is practically imperceptible).


There is also a third approach, a compromise — Sleep + spinlock. The waiting time for the next frame is mostly consumed with Sleep, and the remaining time (usually less than 1ms) is consumed with a spinlock. However, Sleep can sometimes freeze the thread for 1ms longer than it was ordered, so you should calculate the waiting time in milliseconds, then subtract 1 from it and pass it to Sleep (at the end of the spinlock). If Sleep creates a delay exactly as specified, the spinlock will run a millisecond longer. On the other hand, if it creates a delay longer by 1ms, the spinlock will work as much as it should. In both cases, it will not be late with generating the frame, but it will reduce the CPU consumption to a minimum.

I used this approach in Fairtris and it works great (here exactly). It not only creates the delays between frames precisely enough, but also uses only a few percent of the CPU power (see screenshot). But this game has a main loop written to mimic the NES console — that is, while lagging, updating the logic is paused and not being caught up after the lag ceases (which is intentional). The engine for my new game will work completely differently.

[Paul_]

The loops in these articles perform millions of iterations and time tests before the condition is true and the frame can be updated and rendered. And those millions of iterations testing to see if "exact time" has arrived are doing a spinlock that will consume all available CPU power. This is not a rocket science.

It consume power needed to perform the function, not all available CPU power. That's a pretty significant difference. The processor still runs at minimum frequency when is solving such real time checking. Using FPC and the C library by itself generates a diametrically greater load of up to tens of percents of performance unlike the native solution. Doesn't that upset you? I'm not saying that loop with Sleep() is pointless. Each implementation is somehow useful. Anyway, Sleep() can be avoided if it's needed. But that's your fight.

[furious programming]

It consume power needed to perform the function, not all available CPU power.

No — loops consume CPU all the time, maximum power that is available, because they use spinlocks. In the loop examples that do not use Sleep, there is no instruction or construct to limit the CPU usage. You can see this at first glance, if of course you understand the code that uses the basic constructs of a programming language.

Doesn't that upset you?

I am upset, because I asked a question about why the processing of SDL events takes a long time and why it is affected by SDL_Delay being called between executing the event reading loop, and I did not get any answer explaining these anomalies (apparently the problem is not trivial).

I am upset, because despite asking for a piece of code provided in the first post, instead of answering about this test program, for several posts you have been trying to show that I have no idea how to implement the main loop in games, that I do not know how make precise measurements, and now that the sleepless loop will use minimal CPU power, without giving any specific example to support these claims.

I am upset, because I've already made two whole games using my own loops that work as expected and use minimal CPU power, and now I'm developing a third one and my new engine that works even better (and also uses a minimal amount of CPU power, solely thanks to the Sleep function). In addition, I checked hundreds of different ways to implement the main game loop (for different requirements and applications), so I have hundreds of evidence to support my theses and a lot of knowledge on this subject, supported by practice. And despite all this, you still treat me like an idiot.

So yes, I am upset.


But since you don't want to focus on the problem I asked about, that's great — so please, show me that it's possible to write the main game loop that uses a minimal amount of CPU power, without using Sleep. Below is the template to which you should add your code.

Code: Pascal  [Select][+][-]

1. {$MODE OBJFPC}
2.  
3.   procedure Update();
4.   begin
5.     // leave it empty, just do nothing.
6.   end;
7.  
8.   procedure Render();
9.   begin
10.     // leave it empty, just do nothing.
11.   end;
12.  
13. var
14.   Spinning: Boolean = True;
15. begin
16.   while Spinning do
17.   begin
18.     Update();
19.     Render();
20.  
21.     // fill the loop.
22.   end;
23. end.

Fill in the code in the place highlighted above. This program doesn't require any libraries to run, you don't need SDL or anything else. Do what you want, take any example from any of the articles you've linked before (or any other article) and make sure that this loop doesn't consume all the available CPU power. Yes, this loop consumes as much power as it can, because nothing limits it (neither here, nor in any of the provided articles).