TIMER off by factor of 10 (or even 100)

[vefatica]

I have been noticing this fairly regularly and in a variety of situations. When measuring fairly short times (say <500ms), TIMER, about 10% of the time and randomly, reports an elapsed time that's off (depending of the time being measured) by a factor of 10 or 100. I'm not calling it a bug, but it is certainly very strange.

In this first test, consider the times in lines 12, 17, 22, 24, and 26; compared to the rest they're off by a factor of 10.

v:\> do j=1 to 30 (echos %@format[2,%_do_loop]^^s & timer /q & do i=1 to 500 ( echo foo > NUL ) & timer)
 1 Timer 1 off: 23:30:36  Elapsed: 0:00:00.154
 2 Timer 1 off: 23:30:36  Elapsed: 0:00:00.156
 3 Timer 1 off: 23:30:36  Elapsed: 0:00:00.149
 4 Timer 1 off: 23:30:36  Elapsed: 0:00:00.153
 5 Timer 1 off: 23:30:37  Elapsed: 0:00:00.153
 6 Timer 1 off: 23:30:37  Elapsed: 0:00:00.154
 7 Timer 1 off: 23:30:37  Elapsed: 0:00:00.148
 8 Timer 1 off: 23:30:37  Elapsed: 0:00:00.153
 9 Timer 1 off: 23:30:37  Elapsed: 0:00:00.148
10 Timer 1 off: 23:30:37  Elapsed: 0:00:00.155
11 Timer 1 off: 23:30:37  Elapsed: 0:00:00.155
12 Timer 1 off: 23:30:38  Elapsed: 0:00:00.015
13 Timer 1 off: 23:30:38  Elapsed: 0:00:00.155
14 Timer 1 off: 23:30:38  Elapsed: 0:00:00.149
15 Timer 1 off: 23:30:38  Elapsed: 0:00:00.154
16 Timer 1 off: 23:30:38  Elapsed: 0:00:00.152
17 Timer 1 off: 23:30:38  Elapsed: 0:00:00.015
18 Timer 1 off: 23:30:38  Elapsed: 0:00:00.152
19 Timer 1 off: 23:30:39  Elapsed: 0:00:00.152
20 Timer 1 off: 23:30:39  Elapsed: 0:00:00.152
21 Timer 1 off: 23:30:39  Elapsed: 0:00:00.151
22 Timer 1 off: 23:30:39  Elapsed: 0:00:00.015
23 Timer 1 off: 23:30:39  Elapsed: 0:00:00.153
24 Timer 1 off: 23:30:39  Elapsed: 0:00:00.015
25 Timer 1 off: 23:30:40  Elapsed: 0:00:00.156
26 Timer 1 off: 23:30:40  Elapsed: 0:00:00.015
27 Timer 1 off: 23:30:40  Elapsed: 0:00:00.149
28 Timer 1 off: 23:30:40  Elapsed: 0:00:00.151
29 Timer 1 off: 23:30:40  Elapsed: 0:00:00.153
30 Timer 1 off: 23:30:40  Elapsed: 0:00:00.148

And in the test below, line 12 seems off by a factor of 10 and lines 4, 11, 18, and 19 seem off by a factor of 100.

v:\> do j=1 to 30 (echos %@format[2,%_do_loop]^^s & timer /q & do i=1 to 1000 ( echo foo > NUL ) & timer)
 1 Timer 1 off: 23:28:28  Elapsed: 0:00:00.301
 2 Timer 1 off: 23:28:28  Elapsed: 0:00:00.304
 3 Timer 1 off: 23:28:28  Elapsed: 0:00:00.311
 4 Timer 1 off: 23:28:28  Elapsed: 0:00:00.003
 5 Timer 1 off: 23:28:29  Elapsed: 0:00:00.302
 6 Timer 1 off: 23:28:29  Elapsed: 0:00:00.302
 7 Timer 1 off: 23:28:29  Elapsed: 0:00:00.299
 8 Timer 1 off: 23:28:30  Elapsed: 0:00:00.302
 9 Timer 1 off: 23:28:30  Elapsed: 0:00:00.304
10 Timer 1 off: 23:28:30  Elapsed: 0:00:00.308
11 Timer 1 off: 23:28:31  Elapsed: 0:00:00.003
12 Timer 1 off: 23:28:31  Elapsed: 0:00:00.031
13 Timer 1 off: 23:28:31  Elapsed: 0:00:00.301
14 Timer 1 off: 23:28:32  Elapsed: 0:00:00.305
15 Timer 1 off: 23:28:32  Elapsed: 0:00:00.304
16 Timer 1 off: 23:28:32  Elapsed: 0:00:00.303
17 Timer 1 off: 23:28:32  Elapsed: 0:00:00.312
18 Timer 1 off: 23:28:33  Elapsed: 0:00:00.003
19 Timer 1 off: 23:28:33  Elapsed: 0:00:00.003
20 Timer 1 off: 23:28:33  Elapsed: 0:00:00.302
21 Timer 1 off: 23:28:34  Elapsed: 0:00:00.308
22 Timer 1 off: 23:28:34  Elapsed: 0:00:00.304
23 Timer 1 off: 23:28:34  Elapsed: 0:00:00.299
24 Timer 1 off: 23:28:35  Elapsed: 0:00:00.306
25 Timer 1 off: 23:28:35  Elapsed: 0:00:00.306
26 Timer 1 off: 23:28:35  Elapsed: 0:00:00.302
27 Timer 1 off: 23:28:35  Elapsed: 0:00:00.306
28 Timer 1 off: 23:28:36  Elapsed: 0:00:00.307
29 Timer 1 off: 23:28:36  Elapsed: 0:00:00.311
30 Timer 1 off: 23:28:36  Elapsed: 0:00:00.304

 

[AnrDaemon]

In "timer /q & do i=1 to 1000 ( echo foo > NUL ) & timer" you're measuring filesystem IO, which is often not consistent for a single application.

 

[vefatica]

In "timer /q & do i=1 to 1000 ( echo foo > NUL ) & timer" you're measuring filesystem IO, which is often not consistent for a single application.

Did you look carefully at the times? In my second test, 25 of the 30 times are between 0.299 and 0.312. One of them is 0.031 (1/10 of those 25). And four of them are 0.003 (1/100 of those 25). I doubt it's filesystem IO inconsistencies. I find no (zero) inconsistencies when I do the same test (and many similar ones) with v24.

 

[vefatica]

Here's another. I'll time "DELAY /M 200" ten times. Two of the results (3rd and 8th) are 1/100 of what they should be.

v:\> do i=1 to 10 ( timer /q on & delay /m 200 & echo %@timer[1] & timer /q off )
0:00:00.196
0:00:00.194
0:00:00.002
0:00:00.197
0:00:00.197
0:00:00.196
0:00:00.193
0:00:00.002
0:00:00.196
0:00:00.197

 

[K_Meinhard]

I see the same. V24 is okay, timer values of 00:00:20 - 21 throughout.

Output in V25 goes wildly all over a range of values:

0:00:00,3119
0:00:00,9206
0:00:00,678
0:00:00,1464
0:00:00,1131
0:00:00,2363
0:00:00,7390
0:00:00,1371
0:00:00,1537
0:00:00,2352