Timing commands with $= in the prompt?

May 20, 2008
10,618
81
Syracuse, NY, USA
As far as I can tell, the minimum time that can be measured with $= in the prompt is 50 ms. For example

Code:
v:\> eset prompt
prompt=$= $e[32;1m$p$g$s$e[0m

5.043 v:\> ()

0.050 v:\> noop

0.050
In fact anything measured with $= is 50 ms longer than when measured with TIMER.

I don't know when this started but it is not the case in v20.

Code:
g:\tc20> ver

TCC  20.11.46   Windows 7 [Version 6.1.7601]

g:\tc20> eset prompt
PROMPT=$= $e[32;1m$p$g$s$e[0m

0:00:04.98 g:\tc20> ()

0:00:00.00 g:\tc20> noop

0:00:00.00 g:\tc20>
Can the behavior be changed so that timing with $= will be more accurate?

Speculation: It's almost as if there's a hard-coded Sleep(50) after the start time of a command is recorded (I see the same thing if I use PRE_EXEC and POST_EXEC to do the timing myself). If that's the case, couldn't 50 ms be subtracted from $='s time (and the result max'd with 0)? If that's not the case, I'm very curious about what's happening.
 

rconn

Administrator
Staff member
May 14, 2008
11,925
133
1. There is no Sleep().
2. TCC v20 shows 0 because its timer resolution is much coarser (like 50x).
3. On my system, I see about 0.006 seconds for something like "rem".
4. You apparently believe that executing several thousand lines of code to parse the command line (even if it's only something like "rem") can be done without using any CPU cycles. Would that it were true ...
 
May 20, 2008
10,618
81
Syracuse, NY, USA
1. There is no Sleep().
2. TCC v20 shows 0 because its timer resolution is much coarser (like 50x).
3. On my system, I see about 0.006 seconds for something like "rem".
4. You apparently believe that executing several thousand lines of code to parse the command line (even if it's only something like "rem") can be done without using any CPU cycles. Would that it were true ...
Here, REM shows 0.050.
Code:
v:\> eset prompt
prompt=$= $e[32;1m$p$g$s$e[0m

3.717 v:\> rem

0.050 v:\>
And EVERYTHING takes ~50 ms longer according to $= than according to TIMER.

Code:
0.050 v:\> timer & (rem) & timer
Timer 1 on: 21:45:12
Timer 1 off: 21:45:12  Elapsed: 0:00:00.001

0.052 v:\>
Code:
0.050 v:\> timer & do i=1 to 10000 ( rem ) & timer
Timer 1 on: 21:50:58
Timer 1 off: 21:50:59  Elapsed: 0:00:01.427

1.478 v:\>
I see the same ~50 ms if I do the timing like this:

Code:
v:\> alias pre_exec `timer /10 /q on`

0.000 v:\> set prompt=`%@timer[10]$s$p$g$s`

0:00:00.049 v:\> rem

0:00:00.049 v:\>
50 ms is quite a long time. I know TCC can parse much longer command lines in much less time. And, here, that ~50 ms is pretty constant. Do you have any concrete ideas about what I'm seeing/measuring?
 
May 20, 2008
10,618
81
Syracuse, NY, USA
It's the History logging! Using $= ...

Code:
0.000 v:\> rem

0.050 v:\> option //histlogon=no

0.050 v:\> rem

0.001 v:\>
Can the timer for $= be started after the command is logged? ... maybe PRE_EXEC done after the logging also?
 
May 20, 2008
10,618
81
Syracuse, NY, USA
Not without rewriting the parser (and breaking everything else).
Oh, well! No big deal. TIMER works well.

My history log was about 1MB. Copying it to an archive and emptying it brought the 50 ms for REM down to 4 ms. I think I'll make a task to do that regularly. I don't normally use $= in my prompt, but keeping the log file small will speed everything up even when I'm not timing anything.

I'm a little surprised that seeking to the end of a 1MB file takes that long.
 
May 20, 2008
10,618
81
Syracuse, NY, USA
I guess you could move your log files to a RAMdisk.... :rolleyes:
That's not very permanent. I like having a record of everything I've done. I don't like figuring out difficult command lines (DUMPEL.EXE comes to mind) years after I last used them.

That said ... I used to love ramdisk.sys. Are there any modern ones? ... that automatically backup/restore their contents at shutdown/startup?
 

rconn

Administrator
Staff member
May 14, 2008
11,925
133
Oh, well! No big deal. TIMER works well.

My history log was about 1MB. Copying it to an archive and emptying it brought the 50 ms for REM down to 4 ms. I think I'll make a task to do that regularly. I don't normally use $= in my prompt, but keeping the log file small will speed everything up even when I'm not timing anything.

I'm a little surprised that seeking to the end of a 1MB file takes that long.
History logging uses Windows APIs call to request a semaphore to lock the file, open the file, seek to the end, write the command, close the file & release the semaphore. If you want all of that to run faster, you should contact Microsoft directly. (Or get a faster system!)
 
May 20, 2008
10,618
81
Syracuse, NY, USA
History logging uses Windows APIs call to request a semaphore to lock the file, open the file, seek to the end, write the command, close the file & release the semaphore. If you want all of that to run faster, you should contact Microsoft directly. (Or get a faster system!)
My new computer seems pretty fast ... 3.5MHz, SSDs, 16GB RAM. How much faster do workstations get?
 
May 20, 2008
10,618
81
Syracuse, NY, USA
Did you create the virtual Disk in virtual or physical memory?
View attachment 2593
Not sure if it will make any difference, though.

Joe
It was in virtual memory. So I tried again, putting it in physical memory ... no difference. When I copied my archived 1MB history log to the ramdrive history log, the $= time for REM went right back to 50 ms. I guess the moral of the story is that the SSD is pretty fast and the Win32 APIs that Rex described are the limiting factor.