Redirection to log file is quicker than to null : Why?

[SIMMS7400]

Hi Folks -

I run a SQL process using batch and when I redirect output to a log file it runs much quicker than if i do > nul 2>&1.

script1.cmd is executed via a parent script. Within script1.cmd is where I invoke SQLPLUS.

For instance, the first option is the quickest:

Code: Select all

call script1.cmd > Logfile.txt

While this is slower by almost 50%.

Code: Select all

call script1.cmd > nul 2>&1

Is there any reason for that?

Thanks!

[Squashman]

That is not an accurate example.

You are redirecting standard error and standard output to nul.

the other one is only redirecting standard output to a logfile.

[SIMMS7400]

Squash -

That is correct, thank you for rehashing that.

I'm seeing 50% performance increase if I direct to an actual log file rather than just direct to NUL.

1>nul yeilds same performance as > nul 2>&1

Just trying to figure out why?

Also, if I don't redirect to anything, the output is spooled to the CMD window and thus, increases run times.

[Squashman]

Well I can confirm your results just using the type command with a large file.

Code: Select all

@echo off
FOR %%G IN (test.txt) DO ECHO File Size: %%~zG
CALL jTimestamp -f {ums} -r t1
(type test.txt)>nul
CALL jTimestamp -f {ums} -r t2
CALL jTimestamp -d %t2%-%t1% -f "NUL Redirect: {ud} Days {h} Hours {n} Minutes And {s} Seconds" -u

CALL jTimestamp -f {ums} -r t1
(type test.txt)>temp.txt
CALL jTimestamp -f {ums} -r t2
CALL jTimestamp -d %t2%-%t1% -f "FILE Redirect: {ud} Days {h} Hours {n} Minutes And {s} Seconds" -u

pause

Output

Code: Select all

File Size: 2956643952
NUL Redirect: 0 Days 0 Hours 6 Minutes And 43 Seconds
FILE Redirect: 0 Days 0 Hours 2 Minutes And 2 Seconds
Press any key to continue . . .

Piping to findstr:

Code: Select all

type test.txt |findstr /V "^"

Code: Select all

Pipe to Findstr: 0 Days 0 Hours 1 Minutes And 41 Seconds

[dbenham]

That is disturbing

[penpen]

I cannot confirm this:

Code: Select all

@echo off
for %%a in (file) do echo %%~za
echo !time!
>nul type "file"
echo !time!
>"file2" type "file"
echo !time!

Result:

Code: Select all

2147483506
23:32:40,67
23:34:11,57
23:36:44,89

So 00:01:30,90 redirected to nul, and 00:02:33,32 redirected to file.

I wonder why... .
My System: Intel(R) Core(TM)2 Duo CPU E8400 @3.00GHz, 2 MB RAM, Windows 10 Pro, 32 bit.
Degree of file fragmentation: My file consists of two chunks a ~0,99GB (2 x World of Warcraft\Data\data\data.000).
Core usage: It seems, my batch always uses the same CPU core for processing the above.


penpen

[SIMMS7400]

Oh my

This is interesting.

[Squashman]

Well I could run it on my desktop rig down stairs but my work laptop is fairly comparable.

Processor: Intel(R) Core(TM) i5-5300U CPU @ 2.30GHz (4 CPUs), ~2.3GHz
Memory: 16384MB RAM

[Squashman]

Retested.

Code: Select all

File Size: 2956643952
NUL Redirect: 0 Days 0 Hours 7 Minutes And 22 Seconds
FILE Redirect: 0 Days 0 Hours 2 Minutes And 4 Seconds

[aGerman]

Win7 Enterprise, 64 bit
Intel(R) Core(TM) i5-4300U CPU @ 1,90GHz (4 CPUs), ~2.5GHz
4GB RAM

Code: Select all

File Size: 2269852080
NUL Redirect: 0 Days 0 Hours 5 Minutes And 58 Seconds
FILE Redirect: 0 Days 0 Hours 2 Minutes And 37 Seconds

I'll retest on my Win10 toy at home this evening. Maybe they changed the behavior as penpen's results show.

Steffen

[penpen]

I created a file of the exact same size, you (Squashman) are using:

Code: Select all

Z:\>test.bat
@echo off
setlocal enableExtensions enableDelayedExpansion
type "%~f0" & echo(
if not exist "file" (
        set "a=aaaa"
        call set "a=%%a:a=!a:a=aa!%%"
        call set "a=%%a:a=!a:a=aa!%%"
        echo !time!
        set "a=!a:~-1022!"
        >file (
                for /l %%a in (1, 1, 2887347) do echo(!a!
                echo(!a:~-624!
        )
)
for %%a in ("file") do echo %%~za
echo !time!
>nul type "file"
echo !time!
>"file2" type "file"
echo !time!
endlocal

13:21:21,71
2956643954
13:25:03,57
13:27:07,63
13:30:45,65

Same result (00:02:04,06 to nul, 00:03:38,02 to file), so it is neither the filesize nor its fragmentation.
The core speed (2.3/3.0 GHz) shouldn't make such a difference (and i assume the cores are running in parallel - but to be honest i never realy thought about it).

Another possible cause were the 32 versus 64 bit win os.
@SIMMS7400:
Are you also using a 64 bit OS?

The bad thing: Actually i have no access to other PCs.


penpen

[SIMMS7400]

Thank you all for your help on this!

So I did some additional testing this morning and performance doesn't become affected TOO much until you hit .5g or higher. Under .5g the differences are only seconds. Here a few tests above .5g.

Code: Select all

File Size: 613110967
NUL Redirect: 0 Days 0 Hours 1 Minutes And 11 Seconds
FILE Redirect: 0 Days 0 Hours 0 Minutes And 40 Seconds

So at about 1 gig, we see performance begins to degrade by 50%

Code: Select all

File Size: 1021851611
NUL Redirect: 0 Days 0 Hours 2 Minutes And 24 Seconds
FILE Redirect: 0 Days 0 Hours 0 Minutes And 50 Seconds

Computer Info:

Code: Select all

-----------------------------------------------------------------------------
--------------QUICK REFERENCE------------------------------------------------
-----------------------------------------------------------------------------

Windows version        :  Microsoft Windows [Version 6.1.7601]
Product name           :  Windows 7 Enterprise, 32 bit
Performance indicators :  Processor Cores: 4      Visible RAM: 3376796 Bytes

Date/Time format       :  mm/dd/yy (12 hours)     Fri 02/24/2017   8:49:41.23
Extensions             :  system: Enabled   user: Enabled 
Delayed expansion      :  system: Disabled  user: Disabled
Locale name            :  en-US       Code Pages: OEM  437    ANSI 1252
DIR  format            :  02/14/2017  08:23 AM     3,457,839,104 pagefile.sys
Permissions            :  Elevated Admin=Yes, Admin group=Yes

 
Disk Space - Total     :  179 GB
Disk Space - Available :  61 GB

Memory - Total         :  3298
Memory - Used          :  2061

[Squashman]

PenPen,
Would there be any differences with processor architecture. You have an older duo core which as I understand is two separate processors linked together whereas the newer I5 and I7 are 4 cores on one wafer?

[penpen]

The Intel Core2 Duo Processor E8400 also is just a single processor with two cores on one wafer.
So the processor architecture should not differ that much, except that my CPU has 6MB internal cache instead of 3MB (which shouldn't make any difference here), and the number of threads of your CPU is 4 (instead of 1), so your CPU should be able up to process 8 instructions at the same time (instead of 2).

If i don't misinterpret the core speed usage, then your CPU should be up to (8/2*2.3/3.0~=) 3,0667 times faster (on overall computation) than mine, athough each single thread is a little bit slower and reaches only (2.3/3.0~=) 76.7% of the speed of the other CPU.
This also shouldn't explain the big difference.

Under XP the nul device is just a file device (class) which write function just is an empty function, so it should be faster than a function that also does something (writing to file).

Another possible reason that came to my mind (seeing SIMMS7400 his last post; "until you hit .5g or higher" ):
A virus scanner may find it suspicious to pass big amounts of data to nul;
i'm using the built in windows defender only.


penpen

[SIMMS7400]

Team -

Some new development.

I did some additonal testing direction output to the console INSTEAD of NUL. The performance degradation is insane.

Please see: File is 1.6gigs

Code: Select all

File Size: 1634962577
Command Window Redirect: 0 Days 0 Hours 48 Minutes And 16 Seconds
FILE Redirect: 0 Days 0 Hours 1 Minutes And 29 Seconds

Yikes.