Welcome!

By registering with us, you'll be able to discuss, share and private message with other members of our community.

SignUp Now!

TIMER off by factor of 10 (or even 100)

May
12,798
160
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.
Code:
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.

Code:
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
 
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.
 
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.
 
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.
Code:
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
 
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
 

Similar threads

Back
Top