Forum > Games
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 [+][-]window.onload = function(){var x1 = document.getElementById("main_content_section"); if (x1) { var x = document.getElementsByClassName("geshi");for (var i = 0; i < x.length; i++) { x[i].style.maxHeight='none'; x[i].style.height = Math.min(x[i].clientHeight+15,306)+'px'; x[i].style.resize = "vertical";}};} ---{$MODE OBJFPC} uses SDL2;var Window: PSDL_Window; Event: TSDL_Event;var Stopped: Boolean = False;var TicksLast: UInt64; TicksCurrent: UInt64;var CounterBegin: UInt64; CounterSample: UInt64; CounterPerSecond: UInt64;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(); SDL_PumpEvents(); while SDL_PollEvent(@Event) = 1 do Stopped := Event.Type_ = SDL_QUITEV; CounterSample := SDL_GetPerformanceCounter() - CounterBegin; TicksCurrent := SDL_GetTicks64() div (1000 div 4); if TicksCurrent <> TicksLast then begin WriteLn('time: ', (CounterSample / CounterPerSecond * 1000):1:3, 'ms | sample: ', CounterSample); TicksLast := TicksCurrent; end; SDL_Delay(10); until Stopped; SDL_DestroyWindow(Window); SDL_Quit();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 [+][-]window.onload = function(){var x1 = document.getElementById("main_content_section"); if (x1) { var x = document.getElementsByClassName("geshi");for (var i = 0; i < x.length; i++) { x[i].style.maxHeight='none'; x[i].style.height = Math.min(x[i].clientHeight+15,306)+'px'; x[i].style.resize = "vertical";}};} ---time: 0.523ms | sample: 5231time: 0.238ms | sample: 2380time: 0.194ms | sample: 1941time: 0.808ms | sample: 8080time: 0.107ms | sample: 1070time: 0.104ms | sample: 1042time: 0.090ms | sample: 901time: 0.115ms | sample: 1147time: 0.152ms | sample: 1519time: 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 [+][-]window.onload = function(){var x1 = document.getElementById("main_content_section"); if (x1) { var x = document.getElementsByClassName("geshi");for (var i = 0; i < x.length; i++) { x[i].style.maxHeight='none'; x[i].style.height = Math.min(x[i].clientHeight+15,306)+'px'; x[i].style.resize = "vertical";}};} ---time: 0.761ms | sample: 7609time: 0.584ms | sample: 5836time: 0.445ms | sample: 4445time: 1.680ms | sample: 16797time: 0.731ms | sample: 7308time: 1.574ms | sample: 15739time: 0.445ms | sample: 4450time: 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 [+][-]window.onload = function(){var x1 = document.getElementById("main_content_section"); if (x1) { var x = document.getElementsByClassName("geshi");for (var i = 0; i < x.length; i++) { x[i].style.maxHeight='none'; x[i].style.height = Math.min(x[i].clientHeight+15,306)+'px'; x[i].style.resize = "vertical";}};} ---time: 2.850ms | sample: 28501time: 2.813ms | sample: 28133time: 2.821ms | sample: 28213time: 3.445ms | sample: 34452time: 8.337ms | sample: 83373time: 3.104ms | sample: 31039time: 3.134ms | sample: 31337time: 3.093ms | sample: 30932time: 5.055ms | sample: 50552time: 4.454ms | sample: 44541time: 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 [+][-]window.onload = function(){var x1 = document.getElementById("main_content_section"); if (x1) { var x = document.getElementsByClassName("geshi");for (var i = 0; i < x.length; i++) { x[i].style.maxHeight='none'; x[i].style.height = Math.min(x[i].clientHeight+15,306)+'px'; x[i].style.resize = "vertical";}};} ---time: 0.002ms | sample: 15time: 0.002ms | sample: 15time: 0.002ms | sample: 15time: 0.002ms | sample: 15time: 0.002ms | sample: 16time: 0.002ms | sample: 17time: 0.005ms | sample: 47time: 0.002ms | sample: 15time: 0.002ms | sample: 15time: 0.002ms | sample: 15time: 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:
--- Quote from: Paul_ on November 01, 2022, 03:16:53 am ---I'm not sure whether loop is correct […]
--- End quote ---
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.
--- Quote ---[…] but you can try https://wiki.freepascal.org/EpikTimer if there will be difference.
--- End quote ---
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).
--- Quote ---SDL2 timing functions are not reliable for benchmarking or for other purposes that require precision like manual framerate limit via SDL_Delay().
--- End quote ---
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.
--- Quote ---It is not entirely clear which system clock is being used. Especially on different operating systems.
--- End quote ---
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:
--- Quote from: furious programming on November 01, 2022, 12:03:59 pm ---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).
--- End quote ---
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.
Navigation
[0] Message Index
[#] Next page