FileWrite is slow on latest Autoit version

[Zedna]

#AutoIt3Wrapper_UseX64=n
 
; zz.txt - 40kB -> 10000 x asdf
$start = TimerInit()
For $i = 1 To 10000
    $s = FileRead('zz.txt')
Next
ConsoleWrite('zz ' & TimerDiff($start) & @CRLF)

results ESET ON

; 4100-4300 3.2.12.1

; 14100 3.3.7.14

results ESET OFF

; 3800 3.2.12.1

; 13500 3.3.7.14

So the same problem (more than three times slower) is also FileRead not only FileWrite.

EDIT:

Results of the same script but with smaller TXT file

; zz.txt - 4 bytes - asdf

; 760 3.2.12.1

; 450 3.3.7.14

; zz.txt - 40 bytes - 10x asdf

; 765 3.2.12.1

; 465 3.3.7.14

Edited August 30, 2011 by Zedna

[Valik]

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

Really? You think that's how it works? Because you would be wrong. If anything it's the other way around - the Windows API would be thick wrappers around the CRT. The Windows API offers a lot more - or different takes on the same - functionality as the CRT. I really don't know if the Windows API calls CRT functions as part of their implementation but what I do know is that they do a lot more and as a result are somewhat slower.

[Shaggi]

Really? You think that's how it works? Because you would be wrong. If anything it's the other way around - the Windows API would be thick wrappers around the CRT. The Windows API offers a lot more - or different takes on the same - functionality as the CRT. I really don't know if the Windows API calls CRT functions as part of their implementation but what I do know is that they do a lot more and as a result are somewhat slower.

Yes, and i can proove it. Do you really think Microsoft would implement a subsystem (the crt) that can control file i/o outside of the kernel? Ie. without the win api.

Basic example, assume i have the following C code:

int _tmain(int argc, _TCHAR* argv[])
{
printf("0x%X\n",&_tmain); //Get position somewhat for debugging
system("pause");
char buf[3] = {0x1,0x2,0x3};
FILE * file = fopen("test.txt","w+");
fwrite(buf,sizeof buf,1,file);
fclose(file);
return 0;
}

At the system("pause") i placed a breakpoint here:

We can see it calls the c runtime system here. Here's how the stack looks:

However, if we step through, and place a debug breakpoint at CreateFileW also, we see the following in the call stack:

Moreover, in the process of debugging i discovered that theres a lot of overhead before reaching that CreateFileW call. Therefore, i would definately conclude that the CRT is really only a thick wrapper around the winapi and thus is slower.

You can read more about it here: http://www.codeproject.com/KB/cpp/api_crt_cpp_lib_et_al.aspx

specifically parts 2.4, 2.5 and 4.0.

[Valik]

Do you really think Microsoft would implement a subsystem (the crt) that can control file i/o outside of the kernel?

I never said nor thought that. I simply thought the CRT functions would be the low-level functions since they have the least amount of functionality and that the more complex and feature rich functions would be built on top. It's a difference in philosophy.

.

Moreover, in the process of debugging i discovered that theres a lot of overhead before reaching that CreateFileW call. Therefore, i would definately conclude that the CRT is really only a thick wrapper around the winapi and thus is slower.

Really? Because my results prove otherwise. Either that or something else changed between AutoIt 3.3.2.0 and 3.3.4.0 because that is when the slowdown occurred and not surprising to me that is also when Jon switched from CRT to Windows API. Specifically it was done in revision 5490. Maybe there is something else going on, I don't know. What I do know is I have the following results with those two versions:

Test 1 (3.3.2.0): 12905.6496999883
Test 2 (3.3.2.0): 13476.6497478746
Test 3 (3.3.2.0): 172.650586335081
Test 4 Ansi (3.3.2.0): 121.200010480757
Test 4 UTF16 LE (3.3.2.0): 130.50680180016
Test 4 UTF16 BE (3.3.2.0): 155.529306815413
Test 4 UTF8 (3.3.2.0): 128.840421748052
 
Test 1 (3.3.4.0): 42957.1846037687
Test 2 (3.3.4.0): 43534.83119808
Test 3 (3.3.4.0): 215.541275357483
Test 4 Ansi (3.3.4.0): 316.829956652434
Test 4 UTF16 LE (3.3.4.0): 285.317213046373
Test 4 UTF16 BE (3.3.4.0): 290.088366631319
Test 4 UTF8 (3.3.4.0): 325.889185274778

I can always checkout and build revisions 5489 and 5490 and re-run my tests to see if it was really the file changes. I hope that won't be necessary.

Edit: Thank you for the information in any case.

Edit 2: Actually, as luck would have it, Revision 5490 has the Visual Studio 2010 build files so I can easily download it and build it. Which I shall do now.

Edited August 30, 2011 by Valik

[Valik]

Hmm. I ran the tests twice. First set of results:

>"C:\Data\My Programs\C++\AutoIt - 5489\bin\AutoIt3.exe" /ErrorStdOut "C:\Data\Downloads\New AutoIt v3 Script.au3"    
Test 1 (3.3.3.0): 13925.5763889035
Test 2 (3.3.3.0): 11867.4410178863
Test 3 (3.3.3.0): 175.749938786961
Test 4 Ansi (3.3.3.0): 140.401479232291
Test 4 UTF16 LE (3.3.3.0): 142.991250074163
Test 4 UTF16 BE (3.3.3.0): 152.930500838611
Test 4 UTF8 (3.3.3.0): 145.23858930222
>Exit code: 0   Time: 26.840
 
>"C:\Data\My Programs\C++\AutoIt - 5490\bin\AutoIt3.exe" /ErrorStdOut "C:\Data\Downloads\New AutoIt v3 Script.au3"    
Test 1 (3.3.3.0): 13457.8644976721
Test 2 (3.3.3.0): 13655.5806564989
Test 3 (3.3.3.0): 174.566034940071
Test 4 Ansi (3.3.3.0): 326.768002732225
Test 4 UTF16 LE (3.3.3.0): 296.884896296227
Test 4 UTF16 BE (3.3.3.0): 309.086846018111
Test 4 UTF8 (3.3.3.0): 322.114607072523
>Exit code: 0   Time: 28.745

Second set of results:

>"C:\Data\My Programs\C++\AutoIt - 5489\bin\AutoIt3.exe" /ErrorStdOut "C:\Data\Downloads\New AutoIt v3 Script.au3"    
Test 1 (3.3.3.0): 11882.7116006013
Test 2 (3.3.3.0): 11901.2824169347
Test 3 (3.3.3.0): 172.14491995021
Test 4 Ansi (3.3.3.0): 136.335367342987
Test 4 UTF16 LE (3.3.3.0): 145.156670745528
Test 4 UTF16 BE (3.3.3.0): 158.939769080021
Test 4 UTF8 (3.3.3.0): 138.456515853198
>Exit code: 0   Time: 24.747
 
>"C:\Data\My Programs\C++\AutoIt - 5490\bin\AutoIt3.exe" /ErrorStdOut "C:\Data\Downloads\New AutoIt v3 Script.au3"    
Test 1 (3.3.3.0): 13439.7848915076
Test 2 (3.3.3.0): 12939.5269384054
Test 3 (3.3.3.0): 174.242577109606
Test 4 Ansi (3.3.3.0): 347.725901713995
Test 4 UTF16 LE (3.3.3.0): 301.519017001413
Test 4 UTF16 BE (3.3.3.0): 309.838268073056
Test 4 UTF8 (3.3.3.0): 323.534629112229
>Exit code: 0   Time: 28.033

Things to notice:

• The open test (Test 4) doubles in time which is consistent with previous results. This could be due to extra processing in AutoIt or the API, I'm not sure.
• The write test DOES NOT change (much). It's consistently slower but not by the significant numbers we've been seeing. Again, the slowdown could either be the API or it could be extra UNICODE non-sense that's going on.

In other words, these aren't the [revisions] you're looking for. That means between 3.3.2.0 and 3.3.4.0 something else changed that had a significant impact on file write speed.

[Shaggi]

I never said nor thought that. I simply thought the CRT functions would be the low-level functions since they have the least amount of functionality and that the more complex and feature rich functions would be built on top. It's a difference in philosophy.

Thats one way of looking at it, but reality is that windows instead have to "come up" with the missing feautures, you don't specify through the CRT.

Testing in AutoIT is not very objective if you're testing raw speeds. I built this program for this sole purpose of testing the difference between the crt, stl and winapi:

expandcollapse popup

// Fex.cpp : Defines the entry point for the console application.
//
#include "stdafx.h"
#include <stdlib.h>
#include <fstream>
#include <Windows.h>
#define TIMES 1000
 
char buf[3] = {0x1,0x2,0x3};
 
void __declspec(noinline) __stdcall winapi_test();
void __declspec(noinline) __stdcall crt_test();
void __declspec(noinline) __stdcall stl_test();
 
int _tmain(int argc, _TCHAR* argv[])
{
printf("Press any key to start test...\n");
getc(stdin);
DWORD starttime = GetTickCount();
for(int i = 0; i < TIMES; i++)
  crt_test();
printf("Time take for crt: %d\n",GetTickCount()-starttime);
starttime = GetTickCount();
for(int i = 0; i < TIMES; i++)
  stl_test();
printf("Time take for stl: %d\n",GetTickCount()-starttime);
starttime = GetTickCount();
for(int i = 0; i < TIMES; i++)
  winapi_test();
printf("Time take for winapi: %d\n",GetTickCount()-starttime);
system("pause");
return 0;
}
 
void __declspec(noinline) __stdcall winapi_test()
{
DWORD written;
HANDLE file = CreateFileA("test.txt",
    GENERIC_WRITE,
    NULL,
    NULL,
    OPEN_ALWAYS,
    FILE_ATTRIBUTE_NORMAL,
    NULL);
if(file)
{
  WriteFile(file,buf,sizeof buf,&written,NULL);
  CloseHandle(file);
}
}
 
void __declspec(noinline) __stdcall crt_test()
{
FILE * file = fopen("test.txt","w+");
if(file)
{
  fwrite(buf,sizeof buf,1,file);
  fclose(file);
}
}
 
void __declspec(noinline) __stdcall stl_test()
{
using namespace std;
ofstream file("test.txt");
if(file.is_open())
{
  file << buf;
  file.close();
}
}

Results are as following:

Press any key to start test...
 
Time take for crt: 592
Time take for stl: 515
Time take for winapi: 374
Tryk paa en vilkaarlig tast for at fortsaette . . .

Please note that this is a bad way to do it; open a file, write and close each time. However, if you only compare write speeds, winapi is very slow compared to the others, and this is because that winapi flushes the file each time, while crt and stl only writes to a cache and then writes stuff at closure calls.

E:

If you are experiencing slower calls with winapi, i suggest looking into your code again.

And if you were wondering, yes fwrite() is a wrapper around WriteFile() again

Edited August 30, 2011 by Shaggi

[Jon]

Just to resurrect this one with the results of my own testing. I don't see any differences at all. I even recompiled the old "fast" version with the compiler that was used in subsequent versions.

(Original 3.2.12.1 release, was compiled with VC9)
Test 1 (3.2.12.1): 22528.1046194419
Test 2 (3.2.12.1): 21333.6222201425
Test 3 (3.2.12.1): 29.0036862226903

(3.2.12.1, recompiled with VC10)
Test 1 (3.2.12.1): 19579.6386132874
Test 2 (3.2.12.1): 18075.0954381074
Test 3 (3.2.12.1): 9.39407103416775

(VC10)
Test 1 (3.2.13.0): 19579.6386132874
Test 2 (3.2.13.0): 18075.0954381074
Test 3 (3.2.13.0): 9.39407103416775

(VC10)
Test 1 (3.3.3.0): 18715.5103511759
Test 2 (3.3.3.0): 18087.0056110483
Test 3 (3.3.3.0): 68.5362944173072

(VC10)
Test 1 (3.3.8.1): 18552.3612637919
Test 2 (3.3.8.1): 18774.6650063067
Test 3 (3.3.8.1): 5.40229274949749

(VC10)
Test 1 (3.3.9.6): 18396.4698725676
Test 2 (3.3.9.6): 18413.056617531
Test 3 (3.3.9.6): 15.0019066669088

[Zedna]

@Jon

Don't forget to disable your resident antivirus it has very big impact on the results.

I will do more tests later, probably this weekend ...

[Jon]

I don't run AV on my dev machine. It's pretty much vanilla plus visual studio.