Recent

Author Topic: Trying to understand timing  (Read 730 times)

howardpc

  • Hero Member
  • *****
  • Posts: 4144
Trying to understand timing
« on: May 02, 2022, 05:15:00 pm »
The attached simple project uses a TTimer and calls GetTickCount64 in the OnTimer event.
Typical output based on my (aging) hardware is
Code: Pascal  [Select][+][-]
  1. timer.Interval: 100, timercount: 01, elapsed: 0100, diff: 100, modElapsed: 00, divElapsed: 100
  2. timer.Interval: 100, timercount: 02, elapsed: 0200, diff: 100, modElapsed: 00, divElapsed: 100
  3. timer.Interval: 100, timercount: 03, elapsed: 0301, diff: 101, modElapsed: 01, divElapsed: 100
  4. timer.Interval: 100, timercount: 04, elapsed: 0401, diff: 100, modElapsed: 01, divElapsed: 100
  5. timer.Interval: 100, timercount: 05, elapsed: 0502, diff: 101, modElapsed: 02, divElapsed: 100
  6. timer.Interval: 100, timercount: 06, elapsed: 0603, diff: 101, modElapsed: 03, divElapsed: 100
  7. timer.Interval: 100, timercount: 07, elapsed: 0704, diff: 101, modElapsed: 04, divElapsed: 100
  8. timer.Interval: 100, timercount: 08, elapsed: 0805, diff: 101, modElapsed: 05, divElapsed: 100
  9. timer.Interval: 100, timercount: 09, elapsed: 0905, diff: 100, modElapsed: 05, divElapsed: 100
  10. timer.Interval: 100, timercount: 10, elapsed: 1005, diff: 100, modElapsed: 05, divElapsed: 100
  11. timer.Interval: 100, timercount: 11, elapsed: 1106, diff: 101, modElapsed: 06, divElapsed: 100
  12. timer.Interval: 100, timercount: 12, elapsed: 1206, diff: 100, modElapsed: 06, divElapsed: 100
  13. timer.Interval: 100, timercount: 13, elapsed: 1307, diff: 101, modElapsed: 07, divElapsed: 100
  14. timer.Interval: 100, timercount: 14, elapsed: 1408, diff: 101, modElapsed: 08, divElapsed: 100
  15. timer.Interval: 100, timercount: 15, elapsed: 1508, diff: 100, modElapsed: 08, divElapsed: 100
  16. timer.Interval: 100, timercount: 16, elapsed: 1609, diff: 101, modElapsed: 09, divElapsed: 100
  17. timer.Interval: 100, timercount: 17, elapsed: 1709, diff: 100, modElapsed: 09, divElapsed: 100
  18. timer.Interval: 100, timercount: 18, elapsed: 1809, diff: 100, modElapsed: 09, divElapsed: 100
  19. timer.Interval: 100, timercount: 19, elapsed: 1910, diff: 101, modElapsed: 10, divElapsed: 100
  20. timer.Interval: 100, timercount: 20, elapsed: 2011, diff: 101, modElapsed: 11, divElapsed: 100
  21. timer.Interval: 100, timercount: 21, elapsed: 2111, diff: 100, modElapsed: 11, divElapsed: 100
  22. timer.Interval: 100, timercount: 22, elapsed: 2212, diff: 101, modElapsed: 12, divElapsed: 100
  23. timer.Interval: 100, timercount: 23, elapsed: 2312, diff: 100, modElapsed: 12, divElapsed: 100
  24. timer.Interval: 100, timercount: 24, elapsed: 2413, diff: 101, modElapsed: 13, divElapsed: 100
  25. timer.Interval: 100, timercount: 25, elapsed: 2513, diff: 100, modElapsed: 13, divElapsed: 100
  26. timer.Interval: 100, timercount: 26, elapsed: 2614, diff: 101, modElapsed: 14, divElapsed: 100
  27. timer.Interval: 100, timercount: 27, elapsed: 2714, diff: 100, modElapsed: 14, divElapsed: 100
  28. timer.Interval: 100, timercount: 28, elapsed: 2814, diff: 100, modElapsed: 14, divElapsed: 100
  29. timer.Interval: 100, timercount: 29, elapsed: 2914, diff: 100, modElapsed: 14, divElapsed: 100
  30. timer.Interval: 100, timercount: 30, elapsed: 3016, diff: 102, modElapsed: 16, divElapsed: 100
  31. timer.Interval: 100, timercount: 31, elapsed: 3116, diff: 100, modElapsed: 16, divElapsed: 100
  32. timer.Interval: 100, timercount: 32, elapsed: 3217, diff: 101, modElapsed: 17, divElapsed: 100
  33. timer.Interval: 100, timercount: 33, elapsed: 3318, diff: 101, modElapsed: 18, divElapsed: 100
  34. timer.Interval: 100, timercount: 34, elapsed: 3418, diff: 100, modElapsed: 18, divElapsed: 100
  35. timer.Interval: 100, timercount: 35, elapsed: 3519, diff: 101, modElapsed: 19, divElapsed: 100
  36. timer.Interval: 100, timercount: 36, elapsed: 3620, diff: 101, modElapsed: 20, divElapsed: 100
  37. timer.Interval: 100, timercount: 37, elapsed: 3720, diff: 100, modElapsed: 20, divElapsed: 100
  38. timer.Interval: 100, timercount: 38, elapsed: 3820, diff: 100, modElapsed: 20, divElapsed: 100
  39. timer.Interval: 100, timercount: 39, elapsed: 3921, diff: 101, modElapsed: 21, divElapsed: 100
  40. timer.Interval: 100, timercount: 40, elapsed: 4021, diff: 100, modElapsed: 21, divElapsed: 100
  41.  
  42. timer.Interval: 50, timercount: 01, elapsed: 0051, diff: 51, modElapsed: 00, divElapsed: 51
  43. timer.Interval: 50, timercount: 02, elapsed: 0101, diff: 50, modElapsed: 01, divElapsed: 50
  44. timer.Interval: 50, timercount: 03, elapsed: 0152, diff: 51, modElapsed: 02, divElapsed: 50
  45. timer.Interval: 50, timercount: 04, elapsed: 0202, diff: 50, modElapsed: 02, divElapsed: 50
  46. timer.Interval: 50, timercount: 05, elapsed: 0253, diff: 51, modElapsed: 03, divElapsed: 50
  47. timer.Interval: 50, timercount: 06, elapsed: 0304, diff: 51, modElapsed: 04, divElapsed: 50
  48. timer.Interval: 50, timercount: 07, elapsed: 0354, diff: 50, modElapsed: 04, divElapsed: 50
  49. timer.Interval: 50, timercount: 08, elapsed: 0405, diff: 51, modElapsed: 05, divElapsed: 50
  50. timer.Interval: 50, timercount: 09, elapsed: 0455, diff: 50, modElapsed: 05, divElapsed: 50
  51. timer.Interval: 50, timercount: 10, elapsed: 0506, diff: 51, modElapsed: 06, divElapsed: 50
  52. timer.Interval: 50, timercount: 11, elapsed: 0556, diff: 50, modElapsed: 06, divElapsed: 50
  53. timer.Interval: 50, timercount: 12, elapsed: 0607, diff: 51, modElapsed: 07, divElapsed: 50
  54. timer.Interval: 50, timercount: 13, elapsed: 0657, diff: 50, modElapsed: 07, divElapsed: 50
  55. timer.Interval: 50, timercount: 14, elapsed: 0707, diff: 50, modElapsed: 07, divElapsed: 50
  56. timer.Interval: 50, timercount: 15, elapsed: 0758, diff: 51, modElapsed: 08, divElapsed: 50
  57. timer.Interval: 50, timercount: 16, elapsed: 0809, diff: 51, modElapsed: 09, divElapsed: 50
  58. timer.Interval: 50, timercount: 17, elapsed: 0859, diff: 50, modElapsed: 09, divElapsed: 50
  59. timer.Interval: 50, timercount: 18, elapsed: 0910, diff: 51, modElapsed: 10, divElapsed: 50
  60. timer.Interval: 50, timercount: 19, elapsed: 0960, diff: 50, modElapsed: 10, divElapsed: 50
  61. timer.Interval: 50, timercount: 20, elapsed: 1010, diff: 50, modElapsed: 10, divElapsed: 50
  62. timer.Interval: 50, timercount: 21, elapsed: 1061, diff: 51, modElapsed: 11, divElapsed: 50
  63. timer.Interval: 50, timercount: 22, elapsed: 1111, diff: 50, modElapsed: 11, divElapsed: 50
  64. timer.Interval: 50, timercount: 23, elapsed: 1162, diff: 51, modElapsed: 12, divElapsed: 50
  65. timer.Interval: 50, timercount: 24, elapsed: 1212, diff: 50, modElapsed: 12, divElapsed: 50
  66. timer.Interval: 50, timercount: 25, elapsed: 1263, diff: 51, modElapsed: 13, divElapsed: 50
  67. timer.Interval: 50, timercount: 26, elapsed: 1313, diff: 50, modElapsed: 13, divElapsed: 50
  68. timer.Interval: 50, timercount: 27, elapsed: 1363, diff: 50, modElapsed: 13, divElapsed: 50
  69. timer.Interval: 50, timercount: 28, elapsed: 1414, diff: 51, modElapsed: 14, divElapsed: 50
  70. timer.Interval: 50, timercount: 29, elapsed: 1464, diff: 50, modElapsed: 14, divElapsed: 50
  71. timer.Interval: 50, timercount: 30, elapsed: 1514, diff: 50, modElapsed: 14, divElapsed: 50
  72. timer.Interval: 50, timercount: 31, elapsed: 1565, diff: 51, modElapsed: 15, divElapsed: 50
  73. timer.Interval: 50, timercount: 32, elapsed: 1616, diff: 51, modElapsed: 16, divElapsed: 50
  74. timer.Interval: 50, timercount: 33, elapsed: 1666, diff: 50, modElapsed: 16, divElapsed: 50
  75. timer.Interval: 50, timercount: 34, elapsed: 1717, diff: 51, modElapsed: 17, divElapsed: 50
  76. timer.Interval: 50, timercount: 35, elapsed: 1767, diff: 50, modElapsed: 17, divElapsed: 50
  77. timer.Interval: 50, timercount: 36, elapsed: 1818, diff: 51, modElapsed: 18, divElapsed: 50
  78. timer.Interval: 50, timercount: 37, elapsed: 1868, diff: 50, modElapsed: 18, divElapsed: 50
  79. timer.Interval: 50, timercount: 38, elapsed: 1919, diff: 51, modElapsed: 19, divElapsed: 50
  80. timer.Interval: 50, timercount: 39, elapsed: 1969, diff: 50, modElapsed: 19, divElapsed: 50
  81. timer.Interval: 50, timercount: 40, elapsed: 2019, diff: 50, modElapsed: 19, divElapsed: 50
  82.  
  83. timer.Interval: 10, timercount: 01, elapsed: 0010, diff: 10, modElapsed: 00, divElapsed: 10
  84. timer.Interval: 10, timercount: 02, elapsed: 0021, diff: 11, modElapsed: 01, divElapsed: 10
  85. timer.Interval: 10, timercount: 03, elapsed: 0031, diff: 10, modElapsed: 01, divElapsed: 10
  86. timer.Interval: 10, timercount: 04, elapsed: 0042, diff: 11, modElapsed: 02, divElapsed: 10
  87. timer.Interval: 10, timercount: 05, elapsed: 0052, diff: 10, modElapsed: 02, divElapsed: 10
  88. timer.Interval: 10, timercount: 06, elapsed: 0063, diff: 11, modElapsed: 03, divElapsed: 10
  89. timer.Interval: 10, timercount: 07, elapsed: 0073, diff: 10, modElapsed: 03, divElapsed: 10
  90. timer.Interval: 10, timercount: 08, elapsed: 0084, diff: 11, modElapsed: 04, divElapsed: 10
  91. timer.Interval: 10, timercount: 09, elapsed: 0094, diff: 10, modElapsed: 04, divElapsed: 10
  92. timer.Interval: 10, timercount: 10, elapsed: 0105, diff: 11, modElapsed: 05, divElapsed: 10
  93. timer.Interval: 10, timercount: 11, elapsed: 0115, diff: 10, modElapsed: 05, divElapsed: 10
  94. timer.Interval: 10, timercount: 12, elapsed: 0125, diff: 10, modElapsed: 05, divElapsed: 10
  95. timer.Interval: 10, timercount: 13, elapsed: 0136, diff: 11, modElapsed: 06, divElapsed: 10
  96. timer.Interval: 10, timercount: 14, elapsed: 0146, diff: 10, modElapsed: 06, divElapsed: 10
  97. timer.Interval: 10, timercount: 15, elapsed: 0157, diff: 11, modElapsed: 07, divElapsed: 10
  98. timer.Interval: 10, timercount: 16, elapsed: 0167, diff: 10, modElapsed: 07, divElapsed: 10
  99. timer.Interval: 10, timercount: 17, elapsed: 0178, diff: 11, modElapsed: 08, divElapsed: 10
  100. timer.Interval: 10, timercount: 18, elapsed: 0188, diff: 10, modElapsed: 08, divElapsed: 10
  101. timer.Interval: 10, timercount: 19, elapsed: 0199, diff: 11, modElapsed: 09, divElapsed: 10
  102. timer.Interval: 10, timercount: 20, elapsed: 0209, diff: 10, modElapsed: 09, divElapsed: 10
  103. timer.Interval: 10, timercount: 21, elapsed: 0220, diff: 11, modElapsed: 10, divElapsed: 10
  104. timer.Interval: 10, timercount: 22, elapsed: 0230, diff: 10, modElapsed: 10, divElapsed: 10
  105. timer.Interval: 10, timercount: 23, elapsed: 0241, diff: 11, modElapsed: 11, divElapsed: 10
  106. timer.Interval: 10, timercount: 24, elapsed: 0251, diff: 10, modElapsed: 11, divElapsed: 10
  107. timer.Interval: 10, timercount: 25, elapsed: 0262, diff: 11, modElapsed: 12, divElapsed: 10
  108. timer.Interval: 10, timercount: 26, elapsed: 0272, diff: 10, modElapsed: 12, divElapsed: 10
  109. timer.Interval: 10, timercount: 27, elapsed: 0283, diff: 11, modElapsed: 13, divElapsed: 10
  110. timer.Interval: 10, timercount: 28, elapsed: 0293, diff: 10, modElapsed: 13, divElapsed: 10
  111. timer.Interval: 10, timercount: 29, elapsed: 0304, diff: 11, modElapsed: 14, divElapsed: 10
  112. timer.Interval: 10, timercount: 30, elapsed: 0314, diff: 10, modElapsed: 14, divElapsed: 10
  113. timer.Interval: 10, timercount: 31, elapsed: 0325, diff: 11, modElapsed: 15, divElapsed: 10
  114. timer.Interval: 10, timercount: 32, elapsed: 0335, diff: 10, modElapsed: 15, divElapsed: 10
  115. timer.Interval: 10, timercount: 33, elapsed: 0345, diff: 10, modElapsed: 15, divElapsed: 10
  116. timer.Interval: 10, timercount: 34, elapsed: 0356, diff: 11, modElapsed: 16, divElapsed: 10
  117. timer.Interval: 10, timercount: 35, elapsed: 0366, diff: 10, modElapsed: 16, divElapsed: 10
  118. timer.Interval: 10, timercount: 36, elapsed: 0376, diff: 10, modElapsed: 16, divElapsed: 10
  119. timer.Interval: 10, timercount: 37, elapsed: 0387, diff: 11, modElapsed: 17, divElapsed: 10
  120. timer.Interval: 10, timercount: 38, elapsed: 0397, diff: 10, modElapsed: 17, divElapsed: 10
  121. timer.Interval: 10, timercount: 39, elapsed: 0408, diff: 11, modElapsed: 18, divElapsed: 10
  122. timer.Interval: 10, timercount: 40, elapsed: 0418, diff: 10, modElapsed: 18, divElapsed: 10
Is the variation in the diff value, and the slow upward drift in modElapsed because of basic differences between the timing of TTimer and GetTickCount64, or because GetTickcount64 is taking into account the time taken by the OnTimer event itself? Or is there some other reason?

440bx

  • Hero Member
  • *****
  • Posts: 3921
Re: Trying to understand timing
« Reply #1 on: May 02, 2022, 05:58:16 pm »
I cannot give you a precise description of the reason because there are some details about GetTickCount64 that I don't recall exactly at this time but... here is the "gist" of the reason for the divergence between the two.

First, here is how GetTickCount64 is implemented:
Code: ASM  [Select][+][-]
  1. .text:000000018004DC80 ; ULONGLONG __stdcall GetTickCount64()
  2. .text:000000018004DC80                 public GetTickCount64
  3. .text:000000018004DC80 GetTickCount64  proc near               ; DATA XREF: .rdata:00000001801C04A3↓o
  4. .text:000000018004DC80                                         ; .rdata:off_180275008↓o
  5. .text:000000018004DC80                 mov     ecx, ds:7FFE0004h
  6. .text:000000018004DC87                 mov     eax, 7FFE0320h
  7. .text:000000018004DC8C                 shl     rcx, 20h
  8. .text:000000018004DC90                 mov     rax, [rax]
  9. .text:000000018004DC93                 shl     rax, 8
  10. .text:000000018004DC97                 mul     rcx
  11. .text:000000018004DC9A                 mov     rax, rdx
  12. .text:000000018004DC9D                 retn
  13. .text:000000018004DC9D GetTickCount64  endp
  14. .text:000000018004DC9D
in the above code, eax is an address into the USER_SHARED_DATA which among other things keeps a count that is set from kernel mode (ring-0), as you can see, some calculations using that value yield the tick count value returned by GetTickCount64.  The important thing is, GetTickCount64 is almost independent of the Windows scheduler, something which the timer event isn't. 

That  combined with the fact that timer messages are _low_ priority is what accounts for most of the variation.
(FPC v3.0.4 and Lazarus 1.8.2) or (FPC v3.2.2 and Lazarus v3.2) on Windows 7 SP1 64bit.

howardpc

  • Hero Member
  • *****
  • Posts: 4144
Re: Trying to understand timing
« Reply #2 on: May 02, 2022, 08:19:04 pm »
Does that mean that using GetTickCount64 to calculate elapsed times gives a more accurate result than using a message-based timer?

440bx

  • Hero Member
  • *****
  • Posts: 3921
Re: Trying to understand timing
« Reply #3 on: May 02, 2022, 08:30:39 pm »
Does that mean that using GetTickCount64 to calculate elapsed times gives a more accurate result than using a message-based timer?
It should because there is less overhead involved and, calling GetTickCount64 isn't a "low priority" event (however, it is subject to thread scheduling.)

For most purposes, the precision of GetTickCount64 is quite acceptable.  For really high resolution measurements, it is inadequate but not as inadequate as a timer event.


(FPC v3.0.4 and Lazarus 1.8.2) or (FPC v3.2.2 and Lazarus v3.2) on Windows 7 SP1 64bit.

howardpc

  • Hero Member
  • *****
  • Posts: 4144
Re: Trying to understand timing
« Reply #4 on: May 02, 2022, 08:35:55 pm »
Thank you.

440bx

  • Hero Member
  • *****
  • Posts: 3921
Re: Trying to understand timing
« Reply #5 on: May 02, 2022, 08:36:36 pm »
You're welcome :)
(FPC v3.0.4 and Lazarus 1.8.2) or (FPC v3.2.2 and Lazarus v3.2) on Windows 7 SP1 64bit.

 

TinyPortal © 2005-2018