FileWrite is slow on latest Autoit version

[Zedna]

Tested on

Windows 7 SP1 64 bit

Intel Core i5 760 @ 2.8 GHz (4 CPU cores)

16 GB RAM

#AutoIt3Wrapper_UseX64=n

FileDelete('zz.txt')
$start = TimerInit()
For $i = 1 To 10000
;~  $s = 'asdf' & $i & '#'
;~  FileWrite('zz.txt', $s & @CRLF)
    FileWrite('zz.txt', 'asdf' & @CRLF)
Next
ConsoleWrite('zz ' & TimerDiff($start) & @CRLF)

Here are results for number of writes 1 000/10 000/ 100 000 (average from several runs) in form: miliseconds / Autoit's version.

Example was executed from Scite4Autoit3 by F5/Alt+F5.

FileWrite forks here in default append mode.

For big number of writes/appends it much slower on new Autoit's versions.

I think the is maybe some internal bug as cause of this unexpected slow down.

; 1 000

; --------

; 280 3.2.12.1

; 230 3.3.6.1

; 230 3.3.7.14

; 10 000

; --------

; 2700 3.2.12.1

; 3180 3.3.6.1

; 3450 3.3.7.14

; 100 000

; --------

; 30300 3.2.12.1

; 43100 3.3.6.1

; 48300 3.3.7.14

Can somebody tell me why it happens and if I should add this as bug on BugTrack?

30-50% difference is really big!

Edited August 26, 2011 by Zedna

[Valik]

For me (in a single run), 10,000 was faster on 3.3.7.14 and with 100,000 3.3.6.1 was faster. I don't see anything obvious in the changelog except maybe something was changed as part of the code cleanup to fix a bunch of Code Analysis warnings.

[Zedna]

For me (in a single run), 10,000 was faster on 3.3.7.14 and with 100,000 3.3.6.1 was faster. I don't see anything obvious in the changelog except maybe something was changed as part of the code cleanup to fix a bunch of Code Analysis warnings.

And what about much better speed of older 3.2.12.1?

You can temporary replace Autoit3.exe in "C:\Program Files\AutoIt3\" directory by older Autoit3.exe from 3.2..12.1 SFX instalation for this test.

It was last release with Win9x support so maybe it has relation, probably new versions were compiled with newer VC version.

Anyhow I think speed for FileWrite() should be the same or better in new versions.

[Valik]

Are you using the UNICODE version from that release? At some point - I'm not sure when - there was a complete rewrite of the file handling code which added many new features internally. There have been tweaks and changes to that code since then. I know I've personally written some idiotic and redundant code (in other places, not in the file code) that has performance impacts (although nobody noticed it but me when I was doing a self-code-review due to a Code Analysis warning). It's possible Jon has accidentally done one of those really dumb and obvious things that is hurting performance.

[Zedna]

Now tested on other slower machine with Win XP SP3

P4 @ 2.8 GHz (1 CPU core 2 threads)

1GB RAM

The difference is even bigger!!

I think there must be some problem with default file buffer size or FileFlush or something like this.

; 10 000

; --------

; 3300 3.2.12.1

; 4600 3.3.6.1

; 8100 3.3.7.14

; 100 000

; --------

; 34700 3.2.12.1

; 66100 3.3.6.1

; 136900 3.3.7.14

[Zedna]

Are you using the UNICODE version from that release?

I used default Autoit3Warapper settings (I don't know which it is, probably unicode).

EDIT: Now I see 3.2.12.1 was the last version containing Ansi and Unicode, later have only unicode ones.

Now I tested to manually set UseAnsi=0/1 in

"C:\Program Files\AutoIt3\SciTE\AutoIt3Wrapper\AutoIt3Wrapper.ini"

and the results are exactly the same for Ansi/Unicode in 3.2.12.1.

EDIT:

Now I noticed new Scite/Autoit3Wrapper ignores this old UseAnsi=0/1 option

it runs Unicode version no matter of value of this option

so I will test it manually to see the difference Ansi/Unicode in 3.2.12.1

EDIT2: Tested also 3.2.12.1 ANSI and results are exactly the same as with 3.2.12.1 UNICODE

Edited August 26, 2011 by Zedna

[Valik]

For curiosity's sake, run the following on all 3 and let me know the results:

expandcollapse popup

#AutoIt3Wrapper_UseX64=n

Global Const $g_sFile = "zz.txt"
Global Const $g_iIterations = 10000

Test1()
Test2()
Test3()

Func Test1()
    FileDelete($g_sFile)
    Local $hTimer = TimerInit()
    For $i = 1 To $g_iIterations
        FileWrite($g_sFile, "asdf" & @CRLF)
    Next
    ConsoleWrite("Test 1 (" & @AutoItVersion & "): " & TimerDiff($hTimer) & @CRLF)
    FileDelete($g_sFile)
EndFunc

Func Test2()
    FileDelete($g_sFile)
    Local Const $sString = "asdf" & @CRLF
    Local $hTimer = TimerInit()
    For $i = 1 To $g_iIterations
        FileWrite($g_sFile, $sString)
    Next
    ConsoleWrite("Test 2 (" & @AutoItVersion & "): " & TimerDiff($hTimer) & @CRLF)
    FileDelete($g_sFile)
EndFunc

Func Test3()
    Local $sString
    #ForceRef $sString
    Local $hTimer = TimerInit()
    For $i = 1 To $g_iIterations
        $sString = "asdf" & @CRLF
    Next
    ConsoleWrite("Test 3 (" & @AutoItVersion & "): " & TimerDiff($hTimer) & @CRLF)
EndFunc

[Zedna]

For curiosity's sake, run the following on all 3 and let me know the results:

Test 1 (3.2.12.1): 3458.95016720253

Test 2 (3.2.12.1): 3115.73995674933

Test 3 (3.2.12.1): 66.4244838919879

Test 1 (3.3.6.1): 4814.5012839149

Test 2 (3.3.6.1): 4694.8755554919

Test 3 (3.3.6.1): 58.8182139762694

Test 1 (3.3.7.14): 8182.38322962242

Test 2 (3.3.7.14): 5396.74011929739

Test 3 (3.3.7.14): 44.7902685981482

[Zedna]

Whole story:

I noticed this very slow FileWrite() when I did some speed optimizations in one of my project (mainly string operations)

and tried compilation with different Autoit's versions too.

It was good to see much better speeds of StringRegExp functions in latest beta

but I did writes some performance testing data to LOG so the final result was slower in newer Autoit than the same logging in older one

so I tried to comments those logging using FileWrite() and then overall result in latest beta was better as I expected.

Edited August 26, 2011 by Zedna

[Valik]

New version of the script with an additional test called in various permutations. Please give it a try and let me know the results for all 3 versions.

expandcollapse popup

#AutoIt3Wrapper_UseX64=n

Global Const $g_sFile = "zz.txt"
Global Const $g_iIterations = 10000

Test1()
Test2()
Test3()
Test4(0, "Ansi")
Test4(32, "UTF16 LE")
Test4(64, "UTF16 BE")
Test4(128, "UTF8")

Func Test1()
    FileDelete($g_sFile)
    Local $hTimer = TimerInit()
    For $i = 1 To $g_iIterations
        FileWrite($g_sFile, "asdf" & @CRLF)
    Next
    ConsoleWrite("Test 1 (" & @AutoItVersion & "): " & TimerDiff($hTimer) & @CRLF)
    FileDelete($g_sFile)
EndFunc

Func Test2()
    FileDelete($g_sFile)
    Local Const $sString = "asdf" & @CRLF
    Local $hTimer = TimerInit()
    For $i = 1 To $g_iIterations
        FileWrite($g_sFile, $sString)
    Next
    ConsoleWrite("Test 2 (" & @AutoItVersion & "): " & TimerDiff($hTimer) & @CRLF)
    FileDelete($g_sFile)
EndFunc

Func Test3()
    Local $sString
    #ForceRef $sString
    Local $hTimer = TimerInit()
    For $i = 1 To $g_iIterations
        $sString = "asdf" & @CRLF
    Next
    ConsoleWrite("Test 3 (" & @AutoItVersion & "): " & TimerDiff($hTimer) & @CRLF)
EndFunc

Func Test4($iMode, $sMode)
    FileDelete($g_sFile)
    Local $sString = "asdf" & @CRLF
    Local $hFile = FileOpen($g_sFile, 1 + $iMode)
    Local $hTimer = TimerInit()
    For $i = 1 To $g_iIterations
        FileWrite($hFile, $sString)
    Next
    FileClose($hFile)
    ConsoleWrite("Test 4 " & $sMode & " (" & @AutoItVersion & "): " & TimerDiff($hTimer) & @CRLF)
    FileDelete($g_sFile)
EndFunc

[Zedna]

New version of the script with an additional test called in various permutations. Please give it a try and let me know the results for all 3 versions.

I will post results on Saturday evening when I will be home, now I'm not at my computer.

[Zedna]

New version of the script with an additional test called in various permutations. Please give it a try and let me know the results for all 3 versions.

On my WinXP

Test 1 (3.2.12.1): 3240.24226905258

Test 2 (3.2.12.1): 3045.46765483019

Test 3 (3.2.12.1): 67.74447953141

Test 4 Ansi (3.2.12.1): 50.0276728749114

Test 4 UTF16 LE (3.2.12.1): 43.9627691492485

Test 4 UTF16 BE (3.2.12.1): 54.5330913048771

Test 4 UTF8 (3.2.12.1): 48.6532935203683

Test 1 (3.3.6.1): 4699.45833100614

Test 2 (3.3.6.1): 4628.291765304

Test 3 (3.3.6.1): 50.3100026494239

Test 4 Ansi (3.3.6.1): 170.133755809041

Test 4 UTF16 LE (3.3.6.1): 154.364060922429

Test 4 UTF16 BE (3.3.6.1): 160.055872770367

Test 4 UTF8 (3.3.6.1): 170.804084409214

Test 1 (3.3.7.14): 8076.60911545044

Test 2 (3.3.7.14): 5553.24258053891

Test 3 (3.3.7.14): 46.2230456918219

Test 4 Ansi (3.3.7.14): 170.796535699197

Test 4 UTF16 LE (3.3.7.14): 153.850771555212

Test 4 UTF16 BE (3.3.7.14): 156.990751362305

Test 4 UTF8 (3.3.7.14): 172.965520253772

[Valik]

That was probably the version Jon rewrote the file functions. It seems like we switched from using the C Standard Library functions in favor of the Windows API functions even though they were slower. I'll have to look at the commit logs to see if that is indeed what happened.

[Zedna]

#AutoIt3Wrapper_UseX64=n

Global Const $g_sFile = "zz.txt"
Global Const $g_iIterations = 10000

Test5(0) ; Read mode
Test5(1) ; Write mode (append to end of file)
Test5(2) ; Write mode (erase previous contents)

Func Test5($mode)
    Local $hTimer = TimerInit()
    For $i = 1 To $g_iIterations
        $file = FileOpen($g_sFile, $mode)
        FileClose($file)
    Next
    ConsoleWrite("Test 5 mode=" & $mode & " (" & @AutoItVersion & "): " & TimerDiff($hTimer) & @CRLF)
EndFunc

first run

Test 5 mode=0 (3.2.12.1): 617.583817032216

Test 5 mode=1 (3.2.12.1): 943.059165216644

Test 5 mode=2 (3.2.12.1): 2836.09148031192

second run

Test 5 mode=0 (3.2.12.1): 921.334365892605

Test 5 mode=1 (3.2.12.1): 942.659400084495

Test 5 mode=2 (3.2.12.1): 2883.31610205295

first run

Test 5 mode=0 (3.3.7.14): 376.001327576207

Test 5 mode=1 (3.3.7.14): 609.313550013247

Test 5 mode=2 (3.3.7.14): 2734.52560489213

second run

Test 5 mode=0 (3.3.7.14): 616.389101558864

Test 5 mode=1 (3.3.7.14): 612.484552426371

Test 5 mode=2 (3.3.7.14): 2829.94590735609

[trancexx]

#AutoIt3Wrapper_UseX64=n

Global Const $g_sFile = "zz.txt"
Global Const $g_iIterations = 10000

Test5(0) ; Read mode
Test5(1) ; Write mode (append to end of file)
Test5(2) ; Write mode (erase previous contents)

Func Test5($mode)
    Local $hTimer = TimerInit()
    For $i = 1 To $g_iIterations
        $file = FileOpen($g_sFile, $mode)
        FileClose($file)
    Next
    ConsoleWrite("Test 5 mode=" & $mode & " (" & @AutoItVersion & "): " & TimerDiff($hTimer) & @CRLF)
EndFunc

first run

Test 5 mode=0 (3.2.12.1): 617.583817032216

Test 5 mode=1 (3.2.12.1): 943.059165216644

Test 5 mode=2 (3.2.12.1): 2836.09148031192

second run

Test 5 mode=0 (3.2.12.1): 921.334365892605

Test 5 mode=1 (3.2.12.1): 942.659400084495

Test 5 mode=2 (3.2.12.1): 2883.31610205295

first run

Test 5 mode=0 (3.3.7.14): 376.001327576207

Test 5 mode=1 (3.3.7.14): 609.313550013247

Test 5 mode=2 (3.3.7.14): 2734.52560489213

second run

Test 5 mode=0 (3.3.7.14): 616.389101558864

Test 5 mode=1 (3.3.7.14): 612.484552426371

Test 5 mode=2 (3.3.7.14): 2829.94590735609

How would you interpret the results of that test5?

[Zedna]

How would you interpret the results of that test5?

I wanted to eliminate FileOpen/FileClose as (part of) source of problems.

Results are OK for me. On new version it's not slower than on older one.

FileOpen/FileClose is internally called everytime when you use FileWrite without previously explicitly called FileOpen.

So speed problem is really only in FileWrite in part directly writing data and not in part opening/closing file.

EDIT: faster speed of first run is because at that time file didn't exist.

Edited August 28, 2011 by Zedna

[trancexx]

I wanted to eliminate FileOpen/FileClose as (part of) source of problems.

Results are OK for me. On new version it's not slower than on older one.

FileOpen/FileClose is internally called everytime when you use FileWrite without previously explicitly called FileOpen.

So speed problem is really only in FileWrite in part directly writing data and not in part opening/closing file.

EDIT: faster speed of first run is because at that time file didn't exist.

Ok, that's fine.

What you should consider is that it doesn't need to be AutoIt's fault if you have slower performance for newer versions of the engine.

If the performance hit is the result of switching from statically linked CRT to Win32 API, as Valik suggests (?), then it may just be your AV software as the real cause.

Edited August 28, 2011 by trancexx

[Zedna]

What you should consider is that it doesn't need to be AutoIt's fault if you have slower performance for newer versions of the engine.

If the performance hit is the result of switching from statically linked CRT to Win32 API, as Valik suggests (?) then it may just be your AV software as the real cause.

On my slower WinXP I don't use AV software.

On Win7 there is ESET but I can test its temporary switch-off - thanks for the tip.

[Zedna]

#AutoIt3Wrapper_UseX64=n

FileDelete('zz.txt')
$start = TimerInit()
For $i = 1 To 10000
    FileWrite('zz.txt', 'asdf')
Next
ConsoleWrite('zz ' & TimerDiff($start) & @CRLF)

Now I tried it on Win7 with ESET resident file checking OFF and here are results

1500 3.2.12.1

2150 3.3.7.14

With ESET resident ON

9000-15000 3.2.12.1

10000-15000 3.3.7.14

[Shaggi]

That was probably the version Jon rewrote the file functions. It seems like we switched from using the C Standard Library functions in favor of the Windows API functions even though they were slower. I'll have to look at the commit logs to see if that is indeed what happened.

Well the CRT evidently exists as a wrapper for the windows api, so it should in fact be faster.