Why does it take 100 times as long for the eighth DIR ?

[alan_b]

Code: Select all

DIR "%~3" /W | FIND "ill"

Above is the command which normally takes perhaps 50 mSec, but on every eighth instance it takes 4000 mSec,
and after competing a run with 31 such instances over a 136 second period,
The Windows Task Manage Resources shows under "CPU" that 19 off CMD.EXE PIDS were "terminated"
( there were perhaps 31 terminations, but the instances are progressively grayed out and vanished. )
For some reason the same code sequence runs 7 times without faltering, and on the eight run it chokes and runs out of breath.

If no arguments were given when my script is launched, it calls itself with a representative set of arguments that stipulate :-
The number of copies of a files to place in each of a sequence of paths ( e.g. "E:\Test\Fill\A" "E:\Test\Fill\B" "E:\Test\Fill\C" )
The intention was (and will be) to place one copy of the original file in each path,
and to repeat until each path has received the designated number of copies.
A lot of the complexity has been stripped away below to simplify analysis of the problem.

I have found a way to reduce the frequency with which I invoke DIR and this seems to work-a-round my problem,
BUT I WOULD APPRECIATE an explanation of this problem and if there is a better way that to avoid these 4 second periods of death.

This is my simplified script

Code: Select all

@echo off & SETLOCAL EnableDelayedExpansion
SET "TINY=500K.BIN"
IF "%1"=="" (CALL "%~f0" 1 "%TINY%" "E:\Test\Fill\A" "E:\Test\Fill\B" "E:\Test\Fill\C") & GOTO :EOF

ECHO #### %~t0 ##### %DATE% %TIME% #####################################
SET /A N=10 & SET /A P=1
SET "T1=%TIME%
CALL :SHOW_FILES %* & SET /A P+=1
CALL :SHOW_FILES %* & SET /A P+=1
CALL :SHOW_FILES %* & SET /A P+=1
CALL :SHOW_FILES_PLUS %* & SET /A P+=11
CALL :SHOW_FILES %* & SET /A P+=1
CALL :SHOW_FILES %* & SET /A P+=1

GOTO :EOF

:SHOW_FILES_PLUS
IF NOT EXIST "%~3\" GOTO :NEXT_SHOW_FILE
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##--@--%N%--##" %P% & SET /A N+=1

:SHOW_FILES
ECHO --------------  %TIME% --  START : Call %0 [%*] -----
:SHOW_FILES_LOOP
IF NOT EXIST "%~3\" GOTO :NEXT_SHOW_FILE

DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##-----%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##--A--%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##-----%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##--B--%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##-----%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##--C--%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##-----%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##--D--%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##-----%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##--E--%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##-----%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##--F--%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##-----%N%--##" %P% & SET /A N+=1
DIR "%~3" /W | FIND "ill"
CALL :SHOW_TIME %T1% "##--G--%N%--##" %P% & SET /A N+=1
ECHO(

:NEXT_SHOW_FILE
SHIFT
IF "%3" NEQ "" GOTO :SHOW_FILES_LOOP
ECHO --------------  %TIME% --  END of : Call %0 [%*] -----
ECHO(
GOTO :EOF


:SHOW_TIME
SET "TD=%TIME%"
CALL :T_DIFF %T1% %TD%
SET /A L_NUM += 1
SET "BIG=" & IF %DIFF% GEQ 1000 SET "BIG=%DIFF% Above 1000"
ECHO %L_NUM% %TIME_DIFF%    "%~2" "%~3" "%~4" %BIG%
SET "T1=%TD%"
GOTO :EOF

:T_DIFF
FOR /F "tokens=1-4 delims=:." %%d in ("%1") do SET /A mS1=%%d*360000+1%%e*6000+1%%f*100+1%%g-610100
FOR /F "tokens=1-4 delims=:." %%d in ("%2") do SET /A mS2=%%d*360000+1%%e*6000+1%%f*100+1%%g-610100
REM Add 5 mSec extra to avoid subsequent "divide by zero errors"and to +/- split digitization error
SET /A DIFF=(((%mS2%-%mS1%)*10)+5)
SET "TIME_DIFF=%TD%-%T1% = %ms2%-%ms1% mSec = %DIFF% mSec"
GOTO :EOF

This is the beginning of the script output

Code: Select all

Microsoft Windows [Version 6.1.7601]
Copyright (c) 2009 Microsoft Corporation.  All rights reserved.

C:\Users\Alan>cd /d E:\Test\Fill

E:\Test\Fill>#
#### 09/01/2014 19:45 ##### 09/01/2014 19:45:50.75 #####################################
--------------  19:45:50.76 --  START : Call :SHOW_FILES [1 "500K.BIN" "E:\Test\Fill\A" "E:\Test\Fill\B" "E:\Test\Fill\C"] -----
 Directory of E:\Test\Fill\A
1 19:45:50.80-19:45:50.75 = 7115080-7115075 mSec = 55 mSec      "##-----10--##" "1" ""
 Directory of E:\Test\Fill\A
2 19:45:50.84-19:45:50.80 = 7115084-7115080 mSec = 45 mSec      "##--A--11--##" "1" ""
 Directory of E:\Test\Fill\A
3 19:45:50.88-19:45:50.84 = 7115088-7115084 mSec = 45 mSec      "##-----12--##" "1" ""
 Directory of E:\Test\Fill\A
4 19:45:50.92-19:45:50.88 = 7115092-7115088 mSec = 45 mSec      "##--B--13--##" "1" ""
 Directory of E:\Test\Fill\A
5 19:45:50.97-19:45:50.92 = 7115097-7115092 mSec = 55 mSec      "##-----14--##" "1" ""
 Directory of E:\Test\Fill\A
6 19:45:51.00-19:45:50.97 = 7115100-7115097 mSec = 35 mSec      "##--C--15--##" "1" ""
 Directory of E:\Test\Fill\A
7 19:45:51.04-19:45:51.00 = 7115104-7115100 mSec = 45 mSec      "##-----16--##" "1" ""
 Directory of E:\Test\Fill\A
8 19:45:51.08-19:45:51.04 = 7115108-7115104 mSec = 45 mSec      "##--D--17--##" "1" ""
 Directory of E:\Test\Fill\A
9 19:45:55.30-19:45:51.08 = 7115530-7115108 mSec = 4225 mSec    "##-----18--##" "1" "" 4225 Above 1000
 Directory of E:\Test\Fill\A
10 19:45:55.38-19:45:55.30 = 7115538-7115530 mSec = 85 mSec     "##--E--19--##" "1" ""
 Directory of E:\Test\Fill\A
11 19:45:55.42-19:45:55.38 = 7115542-7115538 mSec = 45 mSec     "##-----20--##" "1" ""
 Directory of E:\Test\Fill\A
12 19:45:55.46-19:45:55.42 = 7115546-7115542 mSec = 45 mSec     "##--F--21--##" "1" ""
 Directory of E:\Test\Fill\A
13 19:45:55.50-19:45:55.46 = 7115550-7115546 mSec = 45 mSec     "##-----22--##" "1" ""
 Directory of E:\Test\Fill\A
14 19:45:55.54-19:45:55.50 = 7115554-7115550 mSec = 45 mSec     "##--G--23--##" "1" ""

 Directory of E:\Test\Fill\B
15 19:45:55.59-19:45:55.54 = 7115559-7115554 mSec = 55 mSec     "##-----24--##" "1" ""
 Directory of E:\Test\Fill\B
16 19:45:55.64-19:45:55.59 = 7115564-7115559 mSec = 55 mSec     "##--A--25--##" "1" ""
 Directory of E:\Test\Fill\B
17 19:45:59.86-19:45:55.64 = 7115986-7115564 mSec = 4225 mSec   "##-----26--##" "1" "" 4225 Above 1000
 Directory of E:\Test\Fill\B
18 19:45:59.92-19:45:59.86 = 7115992-7115986 mSec = 65 mSec     "##--B--27--##" "1" ""

When I FIND each occurrence of "Above" in the above output I get :-

Code: Select all

E:\Test\Fill>find "Above" < results.txt
9 19:45:55.30-19:45:51.08 = 7115530-7115108 mSec = 4225 mSec    "##-----18--##" "1" "" 4225 Above 1000
17 19:45:59.86-19:45:55.64 = 7115986-7115564 mSec = 4225 mSec   "##-----26--##" "1" "" 4225 Above 1000
25 19:46:04.41-19:46:00.26 = 7116441-7116026 mSec = 4155 mSec   "##-----34--##" "1" "" 4155 Above 1000
33 19:46:08.96-19:46:04.78 = 7116896-7116478 mSec = 4185 mSec   "##-----42--##" "1" "" 4185 Above 1000
41 19:46:13.51-19:46:09.28 = 7117351-7116928 mSec = 4235 mSec   "##-----50--##" "1" "" 4235 Above 1000
49 19:46:18.02-19:46:14.12 = 7117802-7117412 mSec = 3905 mSec   "##-----58--##" "2" "" 3905 Above 1000
57 19:46:22.59-19:46:18.78 = 7118259-7117878 mSec = 3815 mSec   "##-----66--##" "2" "" 3815 Above 1000
65 19:46:27.13-19:46:23.29 = 7118713-7118329 mSec = 3845 mSec   "##-----74--##" "2" "" 3845 Above 1000
73 19:46:31.64-19:46:27.79 = 7119164-7118779 mSec = 3855 mSec   "##-----82--##" "2" "" 3855 Above 1000
81 19:46:36.15-19:46:32.30 = 7119615-7119230 mSec = 3855 mSec   "##-----90--##" "2" "" 3855 Above 1000
89 19:46:40.65-19:46:36.80 = 7120065-7119680 mSec = 3855 mSec   "##-----98--##" "3" "" 3855 Above 1000
97 19:46:45.20-19:46:41.43 = 7120520-7120143 mSec = 3775 mSec   "##-----106--##" "3" "" 3775 Above 1000
105 19:46:49.75-19:46:45.94 = 7120975-7120594 mSec = 3815 mSec  "##-----114--##" "3" "" 3815 Above 1000
113 19:46:54.30-19:46:50.52 = 7121430-7121052 mSec = 3785 mSec  "##-----122--##" "3" "" 3785 Above 1000
121 19:46:58.87-19:46:55.05 = 7121887-7121505 mSec = 3825 mSec  "##-----130--##" "3" "" 3825 Above 1000
129 19:47:03.44-19:46:59.73 = 7122344-7121973 mSec = 3715 mSec  "##--A--138--##" "4" "" 3715 Above 1000
137 19:47:07.94-19:47:04.24 = 7122794-7122424 mSec = 3705 mSec  "##--E--146--##" "4" "" 3705 Above 1000
145 19:47:12.45-19:47:08.73 = 7123245-7122873 mSec = 3725 mSec  "##--B--154--##" "4" "" 3725 Above 1000
153 19:47:16.95-19:47:13.23 = 7123695-7123323 mSec = 3725 mSec  "##--F--162--##" "4" "" 3725 Above 1000
161 19:47:21.45-19:47:17.84 = 7124145-7123784 mSec = 3615 mSec  "##--C--170--##" "4" "" 3615 Above 1000
169 19:47:25.95-19:47:22.36 = 7124595-7124236 mSec = 3595 mSec  "##--G--178--##" "4" "" 3595 Above 1000
177 19:47:30.52-19:47:26.92 = 7125052-7124692 mSec = 3605 mSec  "##--D--186--##" "15" "" 3605 Above 1000
185 19:47:35.07-19:47:31.49 = 7125507-7125149 mSec = 3585 mSec  "##--A--194--##" "15" "" 3585 Above 1000
193 19:47:39.62-19:47:36.26 = 7125962-7125626 mSec = 3365 mSec  "##--E--202--##" "15" "" 3365 Above 1000
201 19:47:44.17-19:47:40.78 = 7126417-7126078 mSec = 3395 mSec  "##--B--210--##" "15" "" 3395 Above 1000
209 19:47:48.67-19:47:45.28 = 7126867-7126528 mSec = 3395 mSec  "##--F--218--##" "15" "" 3395 Above 1000
217 19:47:53.18-19:47:49.78 = 7127318-7126978 mSec = 3405 mSec  "##--C--226--##" "16" "" 3405 Above 1000
225 19:47:57.68-19:47:54.29 = 7127768-7127429 mSec = 3395 mSec  "##--G--234--##" "16" "" 3395 Above 1000
233 19:48:02.24-19:47:58.91 = 7128224-7127891 mSec = 3335 mSec  "##--D--242--##" "16" "" 3335 Above 1000
241 19:48:06.79-19:48:03.55 = 7128679-7128355 mSec = 3245 mSec  "##--A--250--##" "16" "" 3245 Above 1000
249 19:48:11.35-19:48:08.20 = 7129135-7128820 mSec = 3155 mSec  "##--E--258--##" "16" "" 3155 Above 1000

E:\Test\Fill>

http://imgur.com/C662L50

Regards
Alan

[foxidrive]

Your script doesn't seem to do much. I suspect you left out info on the operating environment of the batch file.

Code: Select all

#### 10/01/2014 14:25 ##### Fri 10/01/2014 14:27:47.00 #####################################
--------------  14:27:47.00 --  START : Call :SHOW_FILES [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fil
l\B" "D:\Test\Fill\C"] -----
--------------  14:27:47.00 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Te
st\Fill\B" "D:\Test\Fill\C"] -----

--------------  14:27:47.00 --  START : Call :SHOW_FILES [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fil
l\B" "D:\Test\Fill\C"] -----
--------------  14:27:47.00 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Te
st\Fill\B" "D:\Test\Fill\C"] -----

--------------  14:27:47.00 --  START : Call :SHOW_FILES [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fil
l\B" "D:\Test\Fill\C"] -----
--------------  14:27:47.01 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Te
st\Fill\B" "D:\Test\Fill\C"] -----

--------------  14:27:47.01 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Te
st\Fill\B" "D:\Test\Fill\C"] -----

--------------  14:27:47.01 --  START : Call :SHOW_FILES [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fil
l\B" "D:\Test\Fill\C"] -----
--------------  14:27:47.01 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Te
st\Fill\B" "D:\Test\Fill\C"] -----

--------------  14:27:47.02 --  START : Call :SHOW_FILES [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fil
l\B" "D:\Test\Fill\C"] -----
--------------  14:27:47.02 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Te
st\Fill\B" "D:\Test\Fill\C"] -----

[alan_b]

Sorry - I forgot to explain.

My script has always assumed that line 3 would stipulate paths that already exist,
it does not create paths to suit the script,
but instead line 3 is adjusted to suit the paths to be tested.
Hence line 3 processes these three paths :-
"E:\Test\Fill\A" "E:\Test\Fill\B" "E:\Test\Fill\C"

I have just renamed the parent path that was "E:\Test\Fill" to become "E:\Test\Fill-0" and now the paths no longer physically exist,
and now my script produces ALMOST the same result as you show because it is now attempting DIR on paths that are missing
The only difference is that you seem to have changed all instances of E:\ to D:\ on line 3.
I guess all you need to do is create on your machine the three folders "D:\Test\Fill\A\", "D:\Test\Fill\B\", ""D:\Test\Fill\C\",
after which the script will be able to process DIR listings and measure the duration of each access.
Please note that NORMALLY for my original needs I would show below each instance of
" Directory of E:\Test\Fill\A"
the number of files which it held, such as
" 48 File(s) 360,860 bytes"
But to reduce space occupied by my screen dumps for this topic I omit that information with many instances of

Code: Select all

DIR "%~3" /W | FIND "ill"

instead of

Code: Select all

DIR "%~3" /W | FIND "il"

N.B.
Where my line 3 shows three paths
"E:\Test\Fill\A" "E:\Test\Fill\B" "E:\Test\Fill\C"
I have tested the script with far more than 10 paths on a mix of partitions,
and the script successfully determines that the list is exhausted with the code

SHIFT
IF "%3" NEQ "" GOTO :SHOW_FILES_LOOP

Regards
Alan

[foxidrive]

I'm not sure what this is supposed to report - I don't seem to have a delay of 4 seconds.

Code: Select all

#### 10/01/2014 14:25 ##### Fri 10/01/2014 22:17:26.95 #####################################
--------------  22:17:26.95 --  START : Call :SHOW_FILES [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----
 Directory of D:\Test\Fill\A
1 22:17:26.97-22:17:26.95 = 8024697-8024695 mSec = 25 mSec    "##-----10--##" "1" "" 
 Directory of D:\Test\Fill\A
2 22:17:26.98-22:17:26.97 = 8024698-8024697 mSec = 15 mSec    "##--A--11--##" "1" "" 
 Directory of D:\Test\Fill\A
3 22:17:27.00-22:17:26.98 = 8024700-8024698 mSec = 25 mSec    "##-----12--##" "1" "" 
 Directory of D:\Test\Fill\A
4 22:17:27.00-22:17:27.00 = 8024700-8024700 mSec = 5 mSec    "##--B--13--##" "1" "" 
 Directory of D:\Test\Fill\A
5 22:17:27.01-22:17:27.00 = 8024701-8024700 mSec = 15 mSec    "##-----14--##" "1" "" 
 Directory of D:\Test\Fill\A
6 22:17:27.04-22:17:27.01 = 8024704-8024701 mSec = 35 mSec    "##--C--15--##" "1" "" 
 Directory of D:\Test\Fill\A
7 22:17:27.04-22:17:27.04 = 8024704-8024704 mSec = 5 mSec    "##-----16--##" "1" "" 
 Directory of D:\Test\Fill\A
8 22:17:27.06-22:17:27.04 = 8024706-8024704 mSec = 25 mSec    "##--D--17--##" "1" "" 
 Directory of D:\Test\Fill\A
9 22:17:27.06-22:17:27.06 = 8024706-8024706 mSec = 5 mSec    "##-----18--##" "1" "" 
 Directory of D:\Test\Fill\A
10 22:17:27.08-22:17:27.06 = 8024708-8024706 mSec = 25 mSec    "##--E--19--##" "1" "" 
 Directory of D:\Test\Fill\A
11 22:17:27.09-22:17:27.08 = 8024709-8024708 mSec = 15 mSec    "##-----20--##" "1" "" 
 Directory of D:\Test\Fill\A
12 22:17:27.09-22:17:27.09 = 8024709-8024709 mSec = 5 mSec    "##--F--21--##" "1" "" 
 Directory of D:\Test\Fill\A
13 22:17:27.11-22:17:27.09 = 8024711-8024709 mSec = 25 mSec    "##-----22--##" "1" "" 
 Directory of D:\Test\Fill\A
14 22:17:27.11-22:17:27.11 = 8024711-8024711 mSec = 5 mSec    "##--G--23--##" "1" "" 

 Directory of D:\Test\Fill\B
15 22:17:27.12-22:17:27.11 = 8024712-8024711 mSec = 15 mSec    "##-----24--##" "1" "" 
 Directory of D:\Test\Fill\B
16 22:17:27.12-22:17:27.12 = 8024712-8024712 mSec = 5 mSec    "##--A--25--##" "1" "" 
 Directory of D:\Test\Fill\B
17 22:17:27.14-22:17:27.12 = 8024714-8024712 mSec = 25 mSec    "##-----26--##" "1" "" 
 Directory of D:\Test\Fill\B
18 22:17:27.14-22:17:27.14 = 8024714-8024714 mSec = 5 mSec    "##--B--27--##" "1" "" 
 Directory of D:\Test\Fill\B
19 22:17:27.15-22:17:27.14 = 8024715-8024714 mSec = 15 mSec    "##-----28--##" "1" "" 
 Directory of D:\Test\Fill\B
20 22:17:27.15-22:17:27.15 = 8024715-8024715 mSec = 5 mSec    "##--C--29--##" "1" "" 
 Directory of D:\Test\Fill\B
21 22:17:27.17-22:17:27.15 = 8024717-8024715 mSec = 25 mSec    "##-----30--##" "1" "" 
 Directory of D:\Test\Fill\B
22 22:17:27.17-22:17:27.17 = 8024717-8024717 mSec = 5 mSec    "##--D--31--##" "1" "" 
 Directory of D:\Test\Fill\B
23 22:17:27.18-22:17:27.17 = 8024718-8024717 mSec = 15 mSec    "##-----32--##" "1" "" 
 Directory of D:\Test\Fill\B
24 22:17:27.18-22:17:27.18 = 8024718-8024718 mSec = 5 mSec    "##--E--33--##" "1" "" 
 Directory of D:\Test\Fill\B
25 22:17:27.20-22:17:27.18 = 8024720-8024718 mSec = 25 mSec    "##-----34--##" "1" "" 
 Directory of D:\Test\Fill\B
26 22:17:27.20-22:17:27.20 = 8024720-8024720 mSec = 5 mSec    "##--F--35--##" "1" "" 
 Directory of D:\Test\Fill\B
27 22:17:27.22-22:17:27.20 = 8024722-8024720 mSec = 25 mSec    "##-----36--##" "1" "" 
 Directory of D:\Test\Fill\B
28 22:17:27.22-22:17:27.22 = 8024722-8024722 mSec = 5 mSec    "##--G--37--##" "1" "" 

 Directory of D:\Test\Fill\C
29 22:17:27.23-22:17:27.22 = 8024723-8024722 mSec = 15 mSec    "##-----38--##" "1" "" 
 Directory of D:\Test\Fill\C
30 22:17:27.23-22:17:27.23 = 8024723-8024723 mSec = 5 mSec    "##--A--39--##" "1" "" 
 Directory of D:\Test\Fill\C
31 22:17:27.25-22:17:27.23 = 8024725-8024723 mSec = 25 mSec    "##-----40--##" "1" "" 
 Directory of D:\Test\Fill\C
32 22:17:27.25-22:17:27.25 = 8024725-8024725 mSec = 5 mSec    "##--B--41--##" "1" "" 
 Directory of D:\Test\Fill\C
33 22:17:27.26-22:17:27.25 = 8024726-8024725 mSec = 15 mSec    "##-----42--##" "1" "" 
 Directory of D:\Test\Fill\C
34 22:17:27.26-22:17:27.26 = 8024726-8024726 mSec = 5 mSec    "##--C--43--##" "1" "" 
 Directory of D:\Test\Fill\C
35 22:17:27.28-22:17:27.26 = 8024728-8024726 mSec = 25 mSec    "##-----44--##" "1" "" 
 Directory of D:\Test\Fill\C
36 22:17:27.28-22:17:27.28 = 8024728-8024728 mSec = 5 mSec    "##--D--45--##" "1" "" 
 Directory of D:\Test\Fill\C
37 22:17:27.29-22:17:27.28 = 8024729-8024728 mSec = 15 mSec    "##-----46--##" "1" "" 
 Directory of D:\Test\Fill\C
38 22:17:27.29-22:17:27.29 = 8024729-8024729 mSec = 5 mSec    "##--E--47--##" "1" "" 
 Directory of D:\Test\Fill\C
39 22:17:27.31-22:17:27.29 = 8024731-8024729 mSec = 25 mSec    "##-----48--##" "1" "" 
 Directory of D:\Test\Fill\C
40 22:17:27.31-22:17:27.31 = 8024731-8024731 mSec = 5 mSec    "##--F--49--##" "1" "" 
 Directory of D:\Test\Fill\C
41 22:17:27.33-22:17:27.31 = 8024733-8024731 mSec = 25 mSec    "##-----50--##" "1" "" 
 Directory of D:\Test\Fill\C
42 22:17:27.33-22:17:27.33 = 8024733-8024733 mSec = 5 mSec    "##--G--51--##" "1" "" 

--------------  22:17:27.33 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----

--------------  22:17:27.34 --  START : Call :SHOW_FILES [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----
 Directory of D:\Test\Fill\A
43 22:17:27.34-22:17:27.33 = 8024734-8024733 mSec = 15 mSec    "##-----52--##" "2" "" 
 Directory of D:\Test\Fill\A
44 22:17:27.34-22:17:27.34 = 8024734-8024734 mSec = 5 mSec    "##--A--53--##" "2" "" 
 Directory of D:\Test\Fill\A
45 22:17:27.36-22:17:27.34 = 8024736-8024734 mSec = 25 mSec    "##-----54--##" "2" "" 
 Directory of D:\Test\Fill\A
46 22:17:27.36-22:17:27.36 = 8024736-8024736 mSec = 5 mSec    "##--B--55--##" "2" "" 
 Directory of D:\Test\Fill\A
47 22:17:27.37-22:17:27.36 = 8024737-8024736 mSec = 15 mSec    "##-----56--##" "2" "" 
 Directory of D:\Test\Fill\A
48 22:17:27.37-22:17:27.37 = 8024737-8024737 mSec = 5 mSec    "##--C--57--##" "2" "" 
 Directory of D:\Test\Fill\A
49 22:17:27.39-22:17:27.37 = 8024739-8024737 mSec = 25 mSec    "##-----58--##" "2" "" 
 Directory of D:\Test\Fill\A
50 22:17:27.39-22:17:27.39 = 8024739-8024739 mSec = 5 mSec    "##--D--59--##" "2" "" 
 Directory of D:\Test\Fill\A
51 22:17:27.40-22:17:27.39 = 8024740-8024739 mSec = 15 mSec    "##-----60--##" "2" "" 
 Directory of D:\Test\Fill\A
52 22:17:27.40-22:17:27.40 = 8024740-8024740 mSec = 5 mSec    "##--E--61--##" "2" "" 
 Directory of D:\Test\Fill\A
53 22:17:27.42-22:17:27.40 = 8024742-8024740 mSec = 25 mSec    "##-----62--##" "2" "" 
 Directory of D:\Test\Fill\A
54 22:17:27.42-22:17:27.42 = 8024742-8024742 mSec = 5 mSec    "##--F--63--##" "2" "" 
 Directory of D:\Test\Fill\A
55 22:17:27.44-22:17:27.42 = 8024744-8024742 mSec = 25 mSec    "##-----64--##" "2" "" 
 Directory of D:\Test\Fill\A
56 22:17:27.44-22:17:27.44 = 8024744-8024744 mSec = 5 mSec    "##--G--65--##" "2" "" 

 Directory of D:\Test\Fill\B
57 22:17:27.45-22:17:27.44 = 8024745-8024744 mSec = 15 mSec    "##-----66--##" "2" "" 
 Directory of D:\Test\Fill\B
58 22:17:27.45-22:17:27.45 = 8024745-8024745 mSec = 5 mSec    "##--A--67--##" "2" "" 
 Directory of D:\Test\Fill\B
59 22:17:27.47-22:17:27.45 = 8024747-8024745 mSec = 25 mSec    "##-----68--##" "2" "" 
 Directory of D:\Test\Fill\B
60 22:17:27.47-22:17:27.47 = 8024747-8024747 mSec = 5 mSec    "##--B--69--##" "2" "" 
 Directory of D:\Test\Fill\B
61 22:17:27.48-22:17:27.47 = 8024748-8024747 mSec = 15 mSec    "##-----70--##" "2" "" 
 Directory of D:\Test\Fill\B
62 22:17:27.48-22:17:27.48 = 8024748-8024748 mSec = 5 mSec    "##--C--71--##" "2" "" 
 Directory of D:\Test\Fill\B
63 22:17:27.50-22:17:27.48 = 8024750-8024748 mSec = 25 mSec    "##-----72--##" "2" "" 
 Directory of D:\Test\Fill\B
64 22:17:27.50-22:17:27.50 = 8024750-8024750 mSec = 5 mSec    "##--D--73--##" "2" "" 
 Directory of D:\Test\Fill\B
65 22:17:27.51-22:17:27.50 = 8024751-8024750 mSec = 15 mSec    "##-----74--##" "2" "" 
 Directory of D:\Test\Fill\B
66 22:17:27.51-22:17:27.51 = 8024751-8024751 mSec = 5 mSec    "##--E--75--##" "2" "" 
 Directory of D:\Test\Fill\B
67 22:17:27.53-22:17:27.51 = 8024753-8024751 mSec = 25 mSec    "##-----76--##" "2" "" 
 Directory of D:\Test\Fill\B
68 22:17:27.53-22:17:27.53 = 8024753-8024753 mSec = 5 mSec    "##--F--77--##" "2" "" 
 Directory of D:\Test\Fill\B
69 22:17:27.54-22:17:27.53 = 8024754-8024753 mSec = 15 mSec    "##-----78--##" "2" "" 
 Directory of D:\Test\Fill\B
70 22:17:27.54-22:17:27.54 = 8024754-8024754 mSec = 5 mSec    "##--G--79--##" "2" "" 

 Directory of D:\Test\Fill\C
71 22:17:27.56-22:17:27.54 = 8024756-8024754 mSec = 25 mSec    "##-----80--##" "2" "" 
 Directory of D:\Test\Fill\C
72 22:17:27.56-22:17:27.56 = 8024756-8024756 mSec = 5 mSec    "##--A--81--##" "2" "" 
 Directory of D:\Test\Fill\C
73 22:17:27.58-22:17:27.56 = 8024758-8024756 mSec = 25 mSec    "##-----82--##" "2" "" 
 Directory of D:\Test\Fill\C
74 22:17:27.58-22:17:27.58 = 8024758-8024758 mSec = 5 mSec    "##--B--83--##" "2" "" 
 Directory of D:\Test\Fill\C
75 22:17:27.59-22:17:27.58 = 8024759-8024758 mSec = 15 mSec    "##-----84--##" "2" "" 
 Directory of D:\Test\Fill\C
76 22:17:27.59-22:17:27.59 = 8024759-8024759 mSec = 5 mSec    "##--C--85--##" "2" "" 
 Directory of D:\Test\Fill\C
77 22:17:27.61-22:17:27.59 = 8024761-8024759 mSec = 25 mSec    "##-----86--##" "2" "" 
 Directory of D:\Test\Fill\C
78 22:17:27.61-22:17:27.61 = 8024761-8024761 mSec = 5 mSec    "##--D--87--##" "2" "" 
 Directory of D:\Test\Fill\C
79 22:17:27.62-22:17:27.61 = 8024762-8024761 mSec = 15 mSec    "##-----88--##" "2" "" 
 Directory of D:\Test\Fill\C
80 22:17:27.62-22:17:27.62 = 8024762-8024762 mSec = 5 mSec    "##--E--89--##" "2" "" 
 Directory of D:\Test\Fill\C
81 22:17:27.64-22:17:27.62 = 8024764-8024762 mSec = 25 mSec    "##-----90--##" "2" "" 
 Directory of D:\Test\Fill\C
82 22:17:27.64-22:17:27.64 = 8024764-8024764 mSec = 5 mSec    "##--F--91--##" "2" "" 
 Directory of D:\Test\Fill\C
83 22:17:27.65-22:17:27.64 = 8024765-8024764 mSec = 15 mSec    "##-----92--##" "2" "" 
 Directory of D:\Test\Fill\C
84 22:17:27.65-22:17:27.65 = 8024765-8024765 mSec = 5 mSec    "##--G--93--##" "2" "" 

--------------  22:17:27.67 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----

--------------  22:17:27.67 --  START : Call :SHOW_FILES [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----
 Directory of D:\Test\Fill\A
85 22:17:27.67-22:17:27.65 = 8024767-8024765 mSec = 25 mSec    "##-----94--##" "3" "" 
 Directory of D:\Test\Fill\A
86 22:17:27.69-22:17:27.67 = 8024769-8024767 mSec = 25 mSec    "##--A--95--##" "3" "" 
 Directory of D:\Test\Fill\A
87 22:17:27.69-22:17:27.69 = 8024769-8024769 mSec = 5 mSec    "##-----96--##" "3" "" 
 Directory of D:\Test\Fill\A
88 22:17:27.70-22:17:27.69 = 8024770-8024769 mSec = 15 mSec    "##--B--97--##" "3" "" 
 Directory of D:\Test\Fill\A
89 22:17:27.70-22:17:27.70 = 8024770-8024770 mSec = 5 mSec    "##-----98--##" "3" "" 
 Directory of D:\Test\Fill\A
90 22:17:27.72-22:17:27.70 = 8024772-8024770 mSec = 25 mSec    "##--C--99--##" "3" "" 
 Directory of D:\Test\Fill\A
91 22:17:27.72-22:17:27.72 = 8024772-8024772 mSec = 5 mSec    "##-----100--##" "3" "" 
 Directory of D:\Test\Fill\A
92 22:17:27.73-22:17:27.72 = 8024773-8024772 mSec = 15 mSec    "##--D--101--##" "3" "" 
 Directory of D:\Test\Fill\A
93 22:17:27.73-22:17:27.73 = 8024773-8024773 mSec = 5 mSec    "##-----102--##" "3" "" 
 Directory of D:\Test\Fill\A
94 22:17:27.75-22:17:27.73 = 8024775-8024773 mSec = 25 mSec    "##--E--103--##" "3" "" 
 Directory of D:\Test\Fill\A
95 22:17:27.75-22:17:27.75 = 8024775-8024775 mSec = 5 mSec    "##-----104--##" "3" "" 
 Directory of D:\Test\Fill\A
96 22:17:27.76-22:17:27.75 = 8024776-8024775 mSec = 15 mSec    "##--F--105--##" "3" "" 
 Directory of D:\Test\Fill\A
97 22:17:27.76-22:17:27.76 = 8024776-8024776 mSec = 5 mSec    "##-----106--##" "3" "" 
 Directory of D:\Test\Fill\A
98 22:17:27.78-22:17:27.76 = 8024778-8024776 mSec = 25 mSec    "##--G--107--##" "3" "" 

 Directory of D:\Test\Fill\B
99 22:17:27.78-22:17:27.78 = 8024778-8024778 mSec = 5 mSec    "##-----108--##" "3" "" 
 Directory of D:\Test\Fill\B
100 22:17:27.79-22:17:27.78 = 8024779-8024778 mSec = 15 mSec    "##--A--109--##" "3" "" 
 Directory of D:\Test\Fill\B
101 22:17:27.79-22:17:27.79 = 8024779-8024779 mSec = 5 mSec    "##-----110--##" "3" "" 
 Directory of D:\Test\Fill\B
102 22:17:27.81-22:17:27.79 = 8024781-8024779 mSec = 25 mSec    "##--B--111--##" "3" "" 
 Directory of D:\Test\Fill\B
103 22:17:27.81-22:17:27.81 = 8024781-8024781 mSec = 5 mSec    "##-----112--##" "3" "" 
 Directory of D:\Test\Fill\B
104 22:17:27.83-22:17:27.81 = 8024783-8024781 mSec = 25 mSec    "##--C--113--##" "3" "" 
 Directory of D:\Test\Fill\B
105 22:17:27.83-22:17:27.83 = 8024783-8024783 mSec = 5 mSec    "##-----114--##" "3" "" 
 Directory of D:\Test\Fill\B
106 22:17:27.84-22:17:27.83 = 8024784-8024783 mSec = 15 mSec    "##--D--115--##" "3" "" 
 Directory of D:\Test\Fill\B
107 22:17:27.84-22:17:27.84 = 8024784-8024784 mSec = 5 mSec    "##-----116--##" "3" "" 
 Directory of D:\Test\Fill\B
108 22:17:27.86-22:17:27.84 = 8024786-8024784 mSec = 25 mSec    "##--E--117--##" "3" "" 
 Directory of D:\Test\Fill\B
109 22:17:27.86-22:17:27.86 = 8024786-8024786 mSec = 5 mSec    "##-----118--##" "3" "" 
 Directory of D:\Test\Fill\B
110 22:17:27.87-22:17:27.86 = 8024787-8024786 mSec = 15 mSec    "##--F--119--##" "3" "" 
 Directory of D:\Test\Fill\B
111 22:17:27.89-22:17:27.87 = 8024789-8024787 mSec = 25 mSec    "##-----120--##" "3" "" 
 Directory of D:\Test\Fill\B
112 22:17:27.89-22:17:27.89 = 8024789-8024789 mSec = 5 mSec    "##--G--121--##" "3" "" 

 Directory of D:\Test\Fill\C
113 22:17:27.90-22:17:27.89 = 8024790-8024789 mSec = 15 mSec    "##-----122--##" "3" "" 
 Directory of D:\Test\Fill\C
114 22:17:27.90-22:17:27.90 = 8024790-8024790 mSec = 5 mSec    "##--A--123--##" "3" "" 
 Directory of D:\Test\Fill\C
115 22:17:27.92-22:17:27.90 = 8024792-8024790 mSec = 25 mSec    "##-----124--##" "3" "" 
 Directory of D:\Test\Fill\C
116 22:17:27.92-22:17:27.92 = 8024792-8024792 mSec = 5 mSec    "##--B--125--##" "3" "" 
 Directory of D:\Test\Fill\C
117 22:17:27.94-22:17:27.92 = 8024794-8024792 mSec = 25 mSec    "##-----126--##" "3" "" 
 Directory of D:\Test\Fill\C
118 22:17:27.94-22:17:27.94 = 8024794-8024794 mSec = 5 mSec    "##--C--127--##" "3" "" 
 Directory of D:\Test\Fill\C
119 22:17:27.95-22:17:27.94 = 8024795-8024794 mSec = 15 mSec    "##-----128--##" "3" "" 
 Directory of D:\Test\Fill\C
120 22:17:27.95-22:17:27.95 = 8024795-8024795 mSec = 5 mSec    "##--D--129--##" "3" "" 
 Directory of D:\Test\Fill\C
121 22:17:27.97-22:17:27.95 = 8024797-8024795 mSec = 25 mSec    "##-----130--##" "3" "" 
 Directory of D:\Test\Fill\C
122 22:17:27.97-22:17:27.97 = 8024797-8024797 mSec = 5 mSec    "##--E--131--##" "3" "" 
 Directory of D:\Test\Fill\C
123 22:17:27.98-22:17:27.97 = 8024798-8024797 mSec = 15 mSec    "##-----132--##" "3" "" 
 Directory of D:\Test\Fill\C
124 22:17:27.98-22:17:27.98 = 8024798-8024798 mSec = 5 mSec    "##--F--133--##" "3" "" 
 Directory of D:\Test\Fill\C
125 22:17:28.00-22:17:27.98 = 8024800-8024798 mSec = 25 mSec    "##-----134--##" "3" "" 
 Directory of D:\Test\Fill\C
126 22:17:28.00-22:17:28.00 = 8024800-8024800 mSec = 5 mSec    "##--G--135--##" "3" "" 

--------------  22:17:28.00 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----

 Directory of D:\Test\Fill\A
127 22:17:28.01-22:17:28.00 = 8024801-8024800 mSec = 15 mSec    "##--@--136--##" "4" "" 
--------------  22:17:28.01 --  START : Call :SHOW_FILES_PLUS [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----
 Directory of D:\Test\Fill\A
128 22:17:28.01-22:17:28.01 = 8024801-8024801 mSec = 5 mSec    "##-----137--##" "4" "" 
 Directory of D:\Test\Fill\A
129 22:17:28.03-22:17:28.01 = 8024803-8024801 mSec = 25 mSec    "##--A--138--##" "4" "" 
 Directory of D:\Test\Fill\A
130 22:17:28.03-22:17:28.03 = 8024803-8024803 mSec = 5 mSec    "##-----139--##" "4" "" 
 Directory of D:\Test\Fill\A
131 22:17:28.09-22:17:28.03 = 8024809-8024803 mSec = 65 mSec    "##--B--140--##" "4" "" 
 Directory of D:\Test\Fill\A
132 22:17:28.11-22:17:28.09 = 8024811-8024809 mSec = 25 mSec    "##-----141--##" "4" "" 
 Directory of D:\Test\Fill\A
133 22:17:28.11-22:17:28.11 = 8024811-8024811 mSec = 5 mSec    "##--C--142--##" "4" "" 
 Directory of D:\Test\Fill\A
134 22:17:28.12-22:17:28.11 = 8024812-8024811 mSec = 15 mSec    "##-----143--##" "4" "" 
 Directory of D:\Test\Fill\A
135 22:17:28.14-22:17:28.12 = 8024814-8024812 mSec = 25 mSec    "##--D--144--##" "4" "" 
 Directory of D:\Test\Fill\A
136 22:17:28.14-22:17:28.14 = 8024814-8024814 mSec = 5 mSec    "##-----145--##" "4" "" 
 Directory of D:\Test\Fill\A
137 22:17:28.15-22:17:28.14 = 8024815-8024814 mSec = 15 mSec    "##--E--146--##" "4" "" 
 Directory of D:\Test\Fill\A
138 22:17:28.15-22:17:28.15 = 8024815-8024815 mSec = 5 mSec    "##-----147--##" "4" "" 
 Directory of D:\Test\Fill\A
139 22:17:28.17-22:17:28.15 = 8024817-8024815 mSec = 25 mSec    "##--F--148--##" "4" "" 
 Directory of D:\Test\Fill\A
140 22:17:28.17-22:17:28.17 = 8024817-8024817 mSec = 5 mSec    "##-----149--##" "4" "" 
 Directory of D:\Test\Fill\A
141 22:17:28.19-22:17:28.17 = 8024819-8024817 mSec = 25 mSec    "##--G--150--##" "4" "" 

 Directory of D:\Test\Fill\B
142 22:17:28.19-22:17:28.19 = 8024819-8024819 mSec = 5 mSec    "##-----151--##" "4" "" 
 Directory of D:\Test\Fill\B
143 22:17:28.20-22:17:28.19 = 8024820-8024819 mSec = 15 mSec    "##--A--152--##" "4" "" 
 Directory of D:\Test\Fill\B
144 22:17:28.20-22:17:28.20 = 8024820-8024820 mSec = 5 mSec    "##-----153--##" "4" "" 
 Directory of D:\Test\Fill\B
145 22:17:28.22-22:17:28.20 = 8024822-8024820 mSec = 25 mSec    "##--B--154--##" "4" "" 
 Directory of D:\Test\Fill\B
146 22:17:28.22-22:17:28.22 = 8024822-8024822 mSec = 5 mSec    "##-----155--##" "4" "" 
 Directory of D:\Test\Fill\B
147 22:17:28.23-22:17:28.22 = 8024823-8024822 mSec = 15 mSec    "##--C--156--##" "4" "" 
 Directory of D:\Test\Fill\B
148 22:17:28.23-22:17:28.23 = 8024823-8024823 mSec = 5 mSec    "##-----157--##" "4" "" 
 Directory of D:\Test\Fill\B
149 22:17:28.25-22:17:28.23 = 8024825-8024823 mSec = 25 mSec    "##--D--158--##" "4" "" 
 Directory of D:\Test\Fill\B
150 22:17:28.25-22:17:28.25 = 8024825-8024825 mSec = 5 mSec    "##-----159--##" "4" "" 
 Directory of D:\Test\Fill\B
151 22:17:28.26-22:17:28.25 = 8024826-8024825 mSec = 15 mSec    "##--E--160--##" "4" "" 
 Directory of D:\Test\Fill\B
152 22:17:28.26-22:17:28.26 = 8024826-8024826 mSec = 5 mSec    "##-----161--##" "4" "" 
 Directory of D:\Test\Fill\B
153 22:17:28.28-22:17:28.26 = 8024828-8024826 mSec = 25 mSec    "##--F--162--##" "4" "" 
 Directory of D:\Test\Fill\B
154 22:17:28.28-22:17:28.28 = 8024828-8024828 mSec = 5 mSec    "##-----163--##" "4" "" 
 Directory of D:\Test\Fill\B
155 22:17:28.29-22:17:28.28 = 8024829-8024828 mSec = 15 mSec    "##--G--164--##" "4" "" 

 Directory of D:\Test\Fill\C
156 22:17:28.29-22:17:28.29 = 8024829-8024829 mSec = 5 mSec    "##-----165--##" "4" "" 
 Directory of D:\Test\Fill\C
157 22:17:28.31-22:17:28.29 = 8024831-8024829 mSec = 25 mSec    "##--A--166--##" "4" "" 
 Directory of D:\Test\Fill\C
158 22:17:28.33-22:17:28.31 = 8024833-8024831 mSec = 25 mSec    "##-----167--##" "4" "" 
 Directory of D:\Test\Fill\C
159 22:17:28.33-22:17:28.33 = 8024833-8024833 mSec = 5 mSec    "##--B--168--##" "4" "" 
 Directory of D:\Test\Fill\C
160 22:17:28.34-22:17:28.33 = 8024834-8024833 mSec = 15 mSec    "##-----169--##" "4" "" 
 Directory of D:\Test\Fill\C
161 22:17:28.34-22:17:28.34 = 8024834-8024834 mSec = 5 mSec    "##--C--170--##" "4" "" 
 Directory of D:\Test\Fill\C
162 22:17:28.36-22:17:28.34 = 8024836-8024834 mSec = 25 mSec    "##-----171--##" "4" "" 
 Directory of D:\Test\Fill\C
163 22:17:28.36-22:17:28.36 = 8024836-8024836 mSec = 5 mSec    "##--D--172--##" "4" "" 
 Directory of D:\Test\Fill\C
164 22:17:28.37-22:17:28.36 = 8024837-8024836 mSec = 15 mSec    "##-----173--##" "4" "" 
 Directory of D:\Test\Fill\C
165 22:17:28.37-22:17:28.37 = 8024837-8024837 mSec = 5 mSec    "##--E--174--##" "4" "" 
 Directory of D:\Test\Fill\C
166 22:17:28.39-22:17:28.37 = 8024839-8024837 mSec = 25 mSec    "##-----175--##" "4" "" 
 Directory of D:\Test\Fill\C
167 22:17:28.39-22:17:28.39 = 8024839-8024839 mSec = 5 mSec    "##--F--176--##" "4" "" 
 Directory of D:\Test\Fill\C
168 22:17:28.40-22:17:28.39 = 8024840-8024839 mSec = 15 mSec    "##-----177--##" "4" "" 
 Directory of D:\Test\Fill\C
169 22:17:28.40-22:17:28.40 = 8024840-8024840 mSec = 5 mSec    "##--G--178--##" "4" "" 

--------------  22:17:28.40 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----

--------------  22:17:28.42 --  START : Call :SHOW_FILES [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----
 Directory of D:\Test\Fill\A
170 22:17:28.42-22:17:28.40 = 8024842-8024840 mSec = 25 mSec    "##-----179--##" "15" "" 
 Directory of D:\Test\Fill\A
171 22:17:28.42-22:17:28.42 = 8024842-8024842 mSec = 5 mSec    "##--A--180--##" "15" "" 
 Directory of D:\Test\Fill\A
172 22:17:28.44-22:17:28.42 = 8024844-8024842 mSec = 25 mSec    "##-----181--##" "15" "" 
 Directory of D:\Test\Fill\A
173 22:17:28.44-22:17:28.44 = 8024844-8024844 mSec = 5 mSec    "##--B--182--##" "15" "" 
 Directory of D:\Test\Fill\A
174 22:17:28.45-22:17:28.44 = 8024845-8024844 mSec = 15 mSec    "##-----183--##" "15" "" 
 Directory of D:\Test\Fill\A
175 22:17:28.47-22:17:28.45 = 8024847-8024845 mSec = 25 mSec    "##--C--184--##" "15" "" 
 Directory of D:\Test\Fill\A
176 22:17:28.47-22:17:28.47 = 8024847-8024847 mSec = 5 mSec    "##-----185--##" "15" "" 
 Directory of D:\Test\Fill\A
177 22:17:28.48-22:17:28.47 = 8024848-8024847 mSec = 15 mSec    "##--D--186--##" "15" "" 
 Directory of D:\Test\Fill\A
178 22:17:28.48-22:17:28.48 = 8024848-8024848 mSec = 5 mSec    "##-----187--##" "15" "" 
 Directory of D:\Test\Fill\A
179 22:17:28.50-22:17:28.48 = 8024850-8024848 mSec = 25 mSec    "##--E--188--##" "15" "" 
 Directory of D:\Test\Fill\A
180 22:17:28.50-22:17:28.50 = 8024850-8024850 mSec = 5 mSec    "##-----189--##" "15" "" 
 Directory of D:\Test\Fill\A
181 22:17:28.51-22:17:28.50 = 8024851-8024850 mSec = 15 mSec    "##--F--190--##" "15" "" 
 Directory of D:\Test\Fill\A
182 22:17:28.51-22:17:28.51 = 8024851-8024851 mSec = 5 mSec    "##-----191--##" "15" "" 
 Directory of D:\Test\Fill\A
183 22:17:28.53-22:17:28.51 = 8024853-8024851 mSec = 25 mSec    "##--G--192--##" "15" "" 

 Directory of D:\Test\Fill\B
184 22:17:28.53-22:17:28.53 = 8024853-8024853 mSec = 5 mSec    "##-----193--##" "15" "" 
 Directory of D:\Test\Fill\B
185 22:17:28.54-22:17:28.53 = 8024854-8024853 mSec = 15 mSec    "##--A--194--##" "15" "" 
 Directory of D:\Test\Fill\B
186 22:17:28.54-22:17:28.54 = 8024854-8024854 mSec = 5 mSec    "##-----195--##" "15" "" 
 Directory of D:\Test\Fill\B
187 22:17:28.56-22:17:28.54 = 8024856-8024854 mSec = 25 mSec    "##--B--196--##" "15" "" 
 Directory of D:\Test\Fill\B
188 22:17:28.56-22:17:28.56 = 8024856-8024856 mSec = 5 mSec    "##-----197--##" "15" "" 
 Directory of D:\Test\Fill\B
189 22:17:28.58-22:17:28.56 = 8024858-8024856 mSec = 25 mSec    "##--C--198--##" "15" "" 
 Directory of D:\Test\Fill\B
190 22:17:28.58-22:17:28.58 = 8024858-8024858 mSec = 5 mSec    "##-----199--##" "15" "" 
 Directory of D:\Test\Fill\B
191 22:17:28.59-22:17:28.58 = 8024859-8024858 mSec = 15 mSec    "##--D--200--##" "15" "" 
 Directory of D:\Test\Fill\B
192 22:17:28.59-22:17:28.59 = 8024859-8024859 mSec = 5 mSec    "##-----201--##" "15" "" 
 Directory of D:\Test\Fill\B
193 22:17:28.61-22:17:28.59 = 8024861-8024859 mSec = 25 mSec    "##--E--202--##" "15" "" 
 Directory of D:\Test\Fill\B
194 22:17:28.61-22:17:28.61 = 8024861-8024861 mSec = 5 mSec    "##-----203--##" "15" "" 
 Directory of D:\Test\Fill\B
195 22:17:28.62-22:17:28.61 = 8024862-8024861 mSec = 15 mSec    "##--F--204--##" "15" "" 
 Directory of D:\Test\Fill\B
196 22:17:28.62-22:17:28.62 = 8024862-8024862 mSec = 5 mSec    "##-----205--##" "15" "" 
 Directory of D:\Test\Fill\B
197 22:17:28.64-22:17:28.62 = 8024864-8024862 mSec = 25 mSec    "##--G--206--##" "15" "" 

 Directory of D:\Test\Fill\C
198 22:17:28.64-22:17:28.64 = 8024864-8024864 mSec = 5 mSec    "##-----207--##" "15" "" 
 Directory of D:\Test\Fill\C
199 22:17:28.65-22:17:28.64 = 8024865-8024864 mSec = 15 mSec    "##--A--208--##" "15" "" 
 Directory of D:\Test\Fill\C
200 22:17:28.67-22:17:28.65 = 8024867-8024865 mSec = 25 mSec    "##-----209--##" "15" "" 
 Directory of D:\Test\Fill\C
201 22:17:28.67-22:17:28.67 = 8024867-8024867 mSec = 5 mSec    "##--B--210--##" "15" "" 
 Directory of D:\Test\Fill\C
202 22:17:28.69-22:17:28.67 = 8024869-8024867 mSec = 25 mSec    "##-----211--##" "15" "" 
 Directory of D:\Test\Fill\C
203 22:17:28.69-22:17:28.69 = 8024869-8024869 mSec = 5 mSec    "##--C--212--##" "15" "" 
 Directory of D:\Test\Fill\C
204 22:17:28.70-22:17:28.69 = 8024870-8024869 mSec = 15 mSec    "##-----213--##" "15" "" 
 Directory of D:\Test\Fill\C
205 22:17:28.70-22:17:28.70 = 8024870-8024870 mSec = 5 mSec    "##--D--214--##" "15" "" 
 Directory of D:\Test\Fill\C
206 22:17:28.72-22:17:28.70 = 8024872-8024870 mSec = 25 mSec    "##-----215--##" "15" "" 
 Directory of D:\Test\Fill\C
207 22:17:28.72-22:17:28.72 = 8024872-8024872 mSec = 5 mSec    "##--E--216--##" "15" "" 
 Directory of D:\Test\Fill\C
208 22:17:28.73-22:17:28.72 = 8024873-8024872 mSec = 15 mSec    "##-----217--##" "15" "" 
 Directory of D:\Test\Fill\C
209 22:17:28.73-22:17:28.73 = 8024873-8024873 mSec = 5 mSec    "##--F--218--##" "15" "" 
 Directory of D:\Test\Fill\C
210 22:17:28.75-22:17:28.73 = 8024875-8024873 mSec = 25 mSec    "##-----219--##" "15" "" 
 Directory of D:\Test\Fill\C
211 22:17:28.75-22:17:28.75 = 8024875-8024875 mSec = 5 mSec    "##--G--220--##" "15" "" 

--------------  22:17:28.75 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----

--------------  22:17:28.75 --  START : Call :SHOW_FILES [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----
 Directory of D:\Test\Fill\A
212 22:17:28.76-22:17:28.75 = 8024876-8024875 mSec = 15 mSec    "##-----221--##" "16" "" 
 Directory of D:\Test\Fill\A
213 22:17:28.76-22:17:28.76 = 8024876-8024876 mSec = 5 mSec    "##--A--222--##" "16" "" 
 Directory of D:\Test\Fill\A
214 22:17:28.78-22:17:28.76 = 8024878-8024876 mSec = 25 mSec    "##-----223--##" "16" "" 
 Directory of D:\Test\Fill\A
215 22:17:28.78-22:17:28.78 = 8024878-8024878 mSec = 5 mSec    "##--B--224--##" "16" "" 
 Directory of D:\Test\Fill\A
216 22:17:28.79-22:17:28.78 = 8024879-8024878 mSec = 15 mSec    "##-----225--##" "16" "" 
 Directory of D:\Test\Fill\A
217 22:17:28.79-22:17:28.79 = 8024879-8024879 mSec = 5 mSec    "##--C--226--##" "16" "" 
 Directory of D:\Test\Fill\A
218 22:17:28.81-22:17:28.79 = 8024881-8024879 mSec = 25 mSec    "##-----227--##" "16" "" 
 Directory of D:\Test\Fill\A
219 22:17:28.81-22:17:28.81 = 8024881-8024881 mSec = 5 mSec    "##--D--228--##" "16" "" 
 Directory of D:\Test\Fill\A
220 22:17:28.83-22:17:28.81 = 8024883-8024881 mSec = 25 mSec    "##-----229--##" "16" "" 
 Directory of D:\Test\Fill\A
221 22:17:28.83-22:17:28.83 = 8024883-8024883 mSec = 5 mSec    "##--E--230--##" "16" "" 
 Directory of D:\Test\Fill\A
222 22:17:28.84-22:17:28.83 = 8024884-8024883 mSec = 15 mSec    "##-----231--##" "16" "" 
 Directory of D:\Test\Fill\A
223 22:17:28.86-22:17:28.84 = 8024886-8024884 mSec = 25 mSec    "##--F--232--##" "16" "" 
 Directory of D:\Test\Fill\A
224 22:17:28.86-22:17:28.86 = 8024886-8024886 mSec = 5 mSec    "##-----233--##" "16" "" 
 Directory of D:\Test\Fill\A
225 22:17:28.87-22:17:28.86 = 8024887-8024886 mSec = 15 mSec    "##--G--234--##" "16" "" 

 Directory of D:\Test\Fill\B
226 22:17:28.87-22:17:28.87 = 8024887-8024887 mSec = 5 mSec    "##-----235--##" "16" "" 
 Directory of D:\Test\Fill\B
227 22:17:28.89-22:17:28.87 = 8024889-8024887 mSec = 25 mSec    "##--A--236--##" "16" "" 
 Directory of D:\Test\Fill\B
228 22:17:28.89-22:17:28.89 = 8024889-8024889 mSec = 5 mSec    "##-----237--##" "16" "" 
 Directory of D:\Test\Fill\B
229 22:17:28.90-22:17:28.89 = 8024890-8024889 mSec = 15 mSec    "##--B--238--##" "16" "" 
 Directory of D:\Test\Fill\B
230 22:17:28.90-22:17:28.90 = 8024890-8024890 mSec = 5 mSec    "##-----239--##" "16" "" 
 Directory of D:\Test\Fill\B
231 22:17:28.92-22:17:28.90 = 8024892-8024890 mSec = 25 mSec    "##--C--240--##" "16" "" 
 Directory of D:\Test\Fill\B
232 22:17:28.92-22:17:28.92 = 8024892-8024892 mSec = 5 mSec    "##-----241--##" "16" "" 
 Directory of D:\Test\Fill\B
233 22:17:28.94-22:17:28.92 = 8024894-8024892 mSec = 25 mSec    "##--D--242--##" "16" "" 
 Directory of D:\Test\Fill\B
234 22:17:28.94-22:17:28.94 = 8024894-8024894 mSec = 5 mSec    "##-----243--##" "16" "" 
 Directory of D:\Test\Fill\B
235 22:17:28.95-22:17:28.94 = 8024895-8024894 mSec = 15 mSec    "##--E--244--##" "16" "" 
 Directory of D:\Test\Fill\B
236 22:17:28.95-22:17:28.95 = 8024895-8024895 mSec = 5 mSec    "##-----245--##" "16" "" 
 Directory of D:\Test\Fill\B
237 22:17:28.97-22:17:28.95 = 8024897-8024895 mSec = 25 mSec    "##--F--246--##" "16" "" 
 Directory of D:\Test\Fill\B
238 22:17:28.97-22:17:28.97 = 8024897-8024897 mSec = 5 mSec    "##-----247--##" "16" "" 
 Directory of D:\Test\Fill\B
239 22:17:28.98-22:17:28.97 = 8024898-8024897 mSec = 15 mSec    "##--G--248--##" "16" "" 

 Directory of D:\Test\Fill\C
240 22:17:28.98-22:17:28.98 = 8024898-8024898 mSec = 5 mSec    "##-----249--##" "16" "" 
 Directory of D:\Test\Fill\C
241 22:17:29.00-22:17:28.98 = 8024900-8024898 mSec = 25 mSec    "##--A--250--##" "16" "" 
 Directory of D:\Test\Fill\C
242 22:17:29.00-22:17:29.00 = 8024900-8024900 mSec = 5 mSec    "##-----251--##" "16" "" 
 Directory of D:\Test\Fill\C
243 22:17:29.01-22:17:29.00 = 8024901-8024900 mSec = 15 mSec    "##--B--252--##" "16" "" 
 Directory of D:\Test\Fill\C
244 22:17:29.01-22:17:29.01 = 8024901-8024901 mSec = 5 mSec    "##-----253--##" "16" "" 
 Directory of D:\Test\Fill\C
245 22:17:29.03-22:17:29.01 = 8024903-8024901 mSec = 25 mSec    "##--C--254--##" "16" "" 
 Directory of D:\Test\Fill\C
246 22:17:29.03-22:17:29.03 = 8024903-8024903 mSec = 5 mSec    "##-----255--##" "16" "" 
 Directory of D:\Test\Fill\C
247 22:17:29.04-22:17:29.03 = 8024904-8024903 mSec = 15 mSec    "##--D--256--##" "16" "" 
 Directory of D:\Test\Fill\C
248 22:17:29.04-22:17:29.04 = 8024904-8024904 mSec = 5 mSec    "##-----257--##" "16" "" 
 Directory of D:\Test\Fill\C
249 22:17:29.06-22:17:29.04 = 8024906-8024904 mSec = 25 mSec    "##--E--258--##" "16" "" 
 Directory of D:\Test\Fill\C
250 22:17:29.06-22:17:29.06 = 8024906-8024906 mSec = 5 mSec    "##-----259--##" "16" "" 
 Directory of D:\Test\Fill\C
251 22:17:29.08-22:17:29.06 = 8024908-8024906 mSec = 25 mSec    "##--F--260--##" "16" "" 
 Directory of D:\Test\Fill\C
252 22:17:29.08-22:17:29.08 = 8024908-8024908 mSec = 5 mSec    "##-----261--##" "16" "" 
 Directory of D:\Test\Fill\C
253 22:17:29.09-22:17:29.08 = 8024909-8024908 mSec = 15 mSec    "##--G--262--##" "16" "" 

--------------  22:17:29.09 --  END of : Call "D:\Test\Fill\A" [1 "500K.BIN" "D:\Test\Fill\A" "D:\Test\Fill\B" "D:\Test\Fill\C"] -----

[alan_b]

Thanks for testing the script

My "normal" "average" measured time was in the range 35 to 55 mSec.
Your system seems to be 2 or 3 times faster.
Could that be due to your running the script on a faster drive than mine, perhaps an SSD where I uses a secondary internal SATA connected HDD ?

I have a fairly old desktop with 64 bit Windows 7 Ultimate with an AMD 4 core processor and 8 GB of RAM .
You seem to have a smooth system, where mine has a fairly regular stutter.

I have seen learned discussions in this forum about unexpected performances consequences when creating / changing variables,
and how executing a BAT script might spawn further instances of more CMD.EXE processes,
and the imgur screen shot does show that many such processes were spawned and left to die / terminate.
I thought that I might have encountered one of these problems,
perhaps by using "SHIFT" to access arguments beyond %9,
and it caused CMD.EXE to occasionally "choke on its own vomit".
I was hoping that whatever the cause it could be identified and I could be guided on how to avoid the grief.

Some time ago I started a topic about a problem where BAT would launch a Cscript action and run this many times a second,
and periodically action would stop for perhaps 4 seconds.
I think I will just have to accept that CMD.EXE does not like hard work on my system.

QUESTION :-
Would a 3 or 4 second pause be consistent with a CMD.EXE child process being spawned to achieve some action,
and for some reason the action failed and the "parent" process that launched the "child",
might take a few seconds to recognise the child has died without achieving its purpose,
and so after 3 or 4 seconds the parent spawns a new "child" to complete the mission.

Thanks for testing my script.
I am disappointed that again I have stumbled into a problem with either Windows 7 installation or with my hardware,
but at least I can stop trying to fix an error in my script.

Regards
Alan

[foxidrive]

Alan, I was going to say that I have a Windows curiosity where a 16 bit program will sometimes take up to around 12 seconds to start,
but I wanted to clarify the issue you mentioned first.

I don't have a problem with CMD internal commands or external commands, but just some 16 bit utilities, and it doesn't happen every time they are launched.

My D: HDD is a USB 3 connected 2.5 inch drive, so it's not as fast as an internal SATA drive.

My PC is swift but not new:

Code: Select all

   Windows 8.1 Pro with Media Center

 System

   Processor:   Intel(R) Core(TM) i7-2600 CPU @ 3.40GHz   3.70 GHz
   Installed memory (RAM):   8.00 GB (3.49 GB usable)
   System type:   32-bit Operating System, x64-based processor

The 16 bit program issue I've had was first evident in Windows XP and I googled it a lot, but never found a solid reason or solution.
It went away in Windows 7 but seems to have returned in Windows 8.1

Perhaps it is some driver I have installed from a software...

[einstein1969]

hi alan,

can you do a test with "comodo" disabled? post taskmanager result.

einstein1969

[foxidrive]

I have to admit to being very lazy too - I noticed this SET "TINY=500K.BIN" but didn't examine the code closely.

Is there supposed to be any files in those folders?

[alan_b]

hi alan,
can you do a test with "comodo" disabled? post taskmanager result.
einstein1969

I did switch the Comodo Defense+ protection from "Safe Mode" to "Disabled" but left its Anti-Virus protection set at "Stateful" for my tests.
I would expect Comodo to have no effect,
and if it did have an effect I would expect to to interfere with every cycle.
I will however retest and observe whether there is any increase in the cumulative total CPU time during the operation of my script.

Regards
Alan

[alan_b]

I have to admit to being very lazy too - I noticed this SET "TINY=500K.BIN" but didn't examine the code closely.

Is there supposed to be any files in those folders?

Those files are NOT needed for the script I submitted

My original script used the routine ":SHOW_FILES" to display for each path the name of the path and the quantity of files which it held.
The heavily redacted script that I submitted shows only the name and NOT the number of files.

My project uses a routine ":DO_FILES" to make multiple copies of E:\Test\Fill\500K.BIN into :-
NTFS partition U:\#e(s)1\ plus U:\#e(s)2\
and
FAT32 partition V:\#e(s)1\ plus V:\#e(s)2\
That works perfectly and Comodo has no problems with the frantic creation of half MByte files.

I created ":SHOW_FILES" to validate ":DO_FILES",
and the simple ":SHOW_FILES" is causing more grief than the complex ":DO_FILES".

For this topic I removed ":DO_FILES" code,
but am afraid I overlooked odd bits of code such as "SET "TINY=500K.BIN"" which have no effect on ":SHOW_FILES"

Regards
Alan

[alan_b]

hi alan,

can you do a test with "comodo" disabled? post taskmanager result.

einstein1969

Thanks, you were right.

The problem was present yesterday with Comodo disabled.

This morning I decided to start the day by disabling Comodo and then shutting down,
and then powering up so that the system had a clean start without any Comodo services or gizmos in action,
and now the problem is gone until I again enable Comodo.

The thing which puzzles me most is WHY Comodo strikes exactly once in eight for each DIR command,
when each DIR command is repeated 14 times for a given path before the next path is processed.

So - problem solved - mystery remains.
I remain thankful that for all these years Comodo has kept all the bad things out.

Many thanks
Regards
Alan

[penpen]

So - problem solved - mystery remains.

This is probably just the result of scanning suspicious processes:
Any processes is marked as suspicious by a counter based heuristic:
An application is declared as suspicious if it accesses file system 14 times per second (or similar).

penpen

[alan_b]

So - problem solved - mystery remains.

An application is declared as suspicious if it accesses file system 14 times per second (or similar).
penpen

It is reasonable to be suspicious of such behaviour,
but UNREASONABLE that "Defence+" has no such suspicion.
I found that I could enable both the Firewall and Defense+ without incurring the problem.
It was only the Antivirus protection that instigated calamity.

Regards
Alan

[penpen]

I'm not familar with comodo, so i don't know what "Defence+" is.
If it is an option you may activate, then it possibly replaces some heuristic functions and uses other ones (or executes programs in a sandbox, or ...).

If it is a kind of a premium version of the antivirus tool, it might have other heuristics included (or executes programs in a sandbox, or ...).

penpen

[alan_b]

Defense+ is supposed to intercept every "dangerous" activity by one executable is interacting with another.

It is like "UAC on steroids" but different in that :-
It does NOT inevitably interfere every time that I launch a specific application - I click and it is launched without any sort "Are you sure - it might do you harm ?"
It DOES wait for actual harm to be imminent, and only then does it act by blocking the action until I have chosen :-
Whether to Allow or Deny, together with whether to remember this decision and not bother me again.

When I launch a BAT script Defense+ trusts my decision and lets that happen.
When the script takes an action, such as launching REG.EXE, then it intercepts,
UNLESS it has been told to remember my decision that the action is allowable AND ONLY THEN if the script has not been modified since it was told to remember.
Even if the BAT script is allowed to to run REG.EXE, it needs separate authorisation for other actions (e.g. launching Internet Explorer.)

When I run CCleaner.exe to clean junk from my P.C. the files are deleted quite quickly.
The job is somewhat faster if Defense+ is disabled, i.e. when fully active for each file deletion it looks up to see if I have authorised CCleaner to delete a file.
I prefer to wait the extra couple of seconds rather than launch the Comodo controls to disable before CCleaner and remember to enable afterwards.

That is why I feel it appropriate for Defense+ to cause my latest problem, rather than the Antivirus,
but perhaps things will get better when I finish experimenting and update to the latest version of Comodo.

N.B.
I have totally disabled SANDBOX.
I used Comodo before it ever had a sandbox and when it arrived it caused me grief.
With SANDBOX enabled I had no difficulty installing sundry Extensions to Firefox,
and then I found that neither LastPass nor Foxmarks were succesful - the SANDBOX had concealed from me the prompts I expect from Defense+.

Regards
Alan