Timing commands with $= in the prompt?

[vefatica]

As far as I can tell, the minimum time that can be measured with $= in the prompt is 50 ms. For example

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.

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]

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

 

[vefatica]

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.

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.

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:\>

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:

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?

 

[rconn]

Try unloading your plugins, and check your system for background processes eating a lot of CPU.

 

[vefatica]

It's the History logging! Using $= ...

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?

 

[Charles Dye]

I guess you could move your log files to a RAMdisk....

 

[rconn]

Can the timer for $= be started after the command is logged? ... maybe PRE_EXEC done after the logging also?

Not without rewriting the parser (and breaking everything else).

 

[vefatica]

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.

 

[vefatica]

I guess you could move your log files to a RAMdisk....

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?

 

[Joe Caverly]

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

IMDisk
FAQs and How-Tos

Also includes the source code.

Joe

 

[rconn]

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!)

 

[vefatica]

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?

 

[vefatica]

IMDisk
FAQs and How-Tos

Also includes the source code.

Joe

That was easy enough. For now I have a 50MB ramdrive. It doesn't make TCC's history logging any faster.

0.004 v:\> rem

0.004 v:\>

I wonder what it will do to DevStudio build times if I put the TEMP directory there.

 

[vefatica]

I wonder what it will do to DevStudio build times if I put the TEMP directory there.

... nothing!

 

[Joe Caverly]

... nothing!

Did you create the virtual Disk in virtual or physical memory?

Not sure if it will make any difference, though.

Joe

 

[vefatica]

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.

 

[drwtsn32]

My new computer seems pretty fast ... 3.5MHz

An old IBM XT is 4.77MHz, so it's got you beat... ;)