Recent

Author Topic: Measure code execution and convert the result to milliseconds  (Read 4231 times)

furious programming

  • Hero Member
  • *****
  • Posts: 853
Re: Measure code execution and convert the result to milliseconds
« Reply #30 on: November 09, 2022, 04:04:41 pm »
SDL_PumpEvents() seems to be the cause of the execution delay.  If you don't call it often enough it appears to take longer to execute.

Yeah, this is what my tests show (see the next paragraph).

Quote
You can test this by putting a call to SDL_PumpEvents() ahead of the time measurement code:

This is exactly what I did yesterday and the results are clear — the following measurements of the uptime of SDL_PumpEvents itself:

Code: Pascal  [Select][+][-]
  1. time: 0.193ms | sample:  1934 | events: 26 // too long
  2. time: 0.008ms | sample:    82 | events: 31
  3. time: 0.039ms | sample:   392 | events: 31
  4. time: 0.008ms | sample:    79 | events: 31
  5. time: 0.206ms | sample:  2062 | events: 32 // too long
  6. time: 0.008ms | sample:    79 | events: 31
  7. time: 0.039ms | sample:   390 | events: 31
  8. time: 0.178ms | sample:  1777 | events: 31 // too long
  9. time: 0.232ms | sample:  2316 | events: 32 // too long
  10. time: 0.055ms | sample:   546 | events: 25
  11. time: 0.039ms | sample:   391 | events: 30
  12. time: 0.008ms | sample:    82 | events: 30
  13. time: 0.952ms | sample:  9519 | events: 43 // too long
  14. time: 1.323ms | sample: 13228 | events: 47 // too looooooooong!
  15. time: 0.040ms | sample:   396 | events: 42
  16. time: 0.008ms | sample:    82 | events: 44
  17. time: 0.219ms | sample:  2190 | events: 51 // too long
  18. time: 0.008ms | sample:    80 | events: 43
  19. time: 0.039ms | sample:   391 | events: 48
  20. time: 0.007ms | sample:    67 | events: 45
  21. time: 0.097ms | sample:   968 | events: 43
  22. time: 0.008ms | sample:    79 | events: 49
  23. time: 1.818ms | sample: 18183 | events: 47 // too looooooooong!
  24. time: 0.008ms | sample:    78 | events: 44
  25. time: 0.045ms | sample:   445 | events: 18
  26. time: 0.008ms | sample:    80 | events:  0
  27. time: 0.045ms | sample:   449 | events:  0
  28. time: 0.008ms | sample:    80 | events:  0
  29. time: 0.045ms | sample:   447 | events:  0
  30. time: 0.008ms | sample:    79 | events:  0
  31. time: 0.045ms | sample:   445 | events:  0
  32. time: 0.005ms | sample:    52 | events:  0
  33. time: 0.008ms | sample:    81 | events:  0
  34. time: 0.008ms | sample:    84 | events:  0
  35. time: 0.040ms | sample:   402 | events:  9
  36. time: 0.269ms | sample:  2687 | events: 32 // too long
  37. time: 0.272ms | sample:  2717 | events: 13 // too long
  38. time: 0.041ms | sample:   408 | events: 31

On the other hand, a single call to the SDL_PeepEvents function, returning dozens of events, always takes about 0.001ms (i.e. 1µs). I tested it yesterday too.

I checked using the Intel® VTune™ Profiler and unfortunately it looks like it is not SDL's fault, but the system's fault (see the attachment). It's just a pity that this profiler has some problems recognizing my CPU and that it shows the addresses of some functions instead of their names (SDL functions).

Any other lightweight and sensible Windows 10 64-bit profiling tool for native applications?

This Intel tool not only weighs 2GB, it also does not show some data (such as function names). LazProfiler would be great, I installed it, but Lazarus crashes during boot. I changed the code as suggested in this pull request, but it doesn't help — when Lazarus starts, the IDE freezes for several seconds, and then an error pops up. Dammit...
« Last Edit: November 09, 2022, 04:10:12 pm by furious programming »
Lazarus 3.2 with FPC 3.2.2, Windows 10 — all 64-bit

Working solo on an acrade, action/adventure game in retro style (pixelart), programming the engine and shell from scratch, using Free Pascal and SDL. Release planned in 2026.

WayneSherman

  • Full Member
  • ***
  • Posts: 243
Re: Measure code execution and convert the result to milliseconds
« Reply #31 on: November 10, 2022, 04:13:03 pm »
I checked using the Intel® VTune™ Profiler and unfortunately it looks like it is not SDL's fault, but the system's fault (see the attachment).

SleepEX / NTDelayExecution is probably from the SDL_Delay call since that internally calls Sleep().  If so, this execution delay is on purpose.
https://github.com/libsdl-org/SDL/blob/main/src/timer/windows/SDL_systimer.c#L172

Without function names it is hard to know where WaitForMultipleObjectsEX is being called...

SDL_PumpEvents calls SDL_PumpEventsInternal
https://github.com/libsdl-org/SDL/blob/main/src/events/SDL_events.c#L858

which (among other things) calls WIN_PumpEvents(_THIS)
https://github.com/libsdl-org/SDL/blob/main/src/video/windows/SDL_windowsevents.c#L1778

WIN_PumpEvents processes the Windows message event queue:

PeekMessage(&msg, NULL, 0, 0, PM_REMOVE))
...
DispatchMessage(&msg);

If you can hook the Windows message queue, you can see what messages are coming in, how often, and how many.

PumpEvents behaves as if a backlog of events is building up and if you don't call it often enough it takes longer to process the events.  Maybe the events that are causing the delay are Windows messages and not SDL events.

« Last Edit: November 11, 2022, 03:57:41 pm by WayneSherman »

WayneSherman

  • Full Member
  • ***
  • Posts: 243
Re: Measure code execution and convert the result to milliseconds
« Reply #32 on: November 10, 2022, 08:17:16 pm »
I checked using the Intel® VTune™ Profiler and unfortunately it looks like it is not SDL's fault, but the system's fault (see the attachment).

I had another thought.  WaitForMultipleObjects in your screenshot shows the time, but not the number of calls made to it.  It looks like it is called *after* exiting "Main", so is it just running once on cleanup (when the program is about to terminate), or is it being called many times during your program execution?

 

TinyPortal © 2005-2018