Mail Archives: cygwin/2010/06/03/13:35:51
Using strace I was able to look at some of the functions that are
enumerated by debugging calls.
The trace below is done by ls.exe for each file (approximately 95k files @
88 mSecs/file), approximately 40 mSecs are spent in lstat64() and another
47 mSecs are spent in getacl().
It also *looks* like since lstat() and getacl() call some of the same
internal cygwin dll functions and that 43 mSecs are duplication of effort.
A small cache may improve this.
I also have Norton Virus Scan installed on this box and noticed that
turning off Virus Scan improves performance by a factor of 4. It seems
the way Cygwin stat's files seems to trip the Virus Scanner whereas the
DOS version does not. Even with VirusScan off, it would take roughly 1800
seconds to do an "ls -lR" of the 95k file network directory with cygwin
vs. 17 seconds with native DOS dir.
So I would say a combination of duplicated functionality between the two
function calls and making the Virus Scanner run is causing some of the
performance issues in Cygwin.
So if you account for the Virus Scan overhead (that the cygwin version
seems to trip, but the DOS version does not) and the cache, you could
probably get stat performance down to around 10 mSecs/file. DOS is still
around 178 uSecs/file, still 6x better.
I have no idea why these methods are used to get file information (ie
open() vs. Win32 GetFileAttributes()). Can anyone point to the current
maintainer of the fhandler* files?
Chris
51 652056 [main] ls 3688 fhandler_disk_file::readdir: 0 = readdir
(0x6BEE88, 0x22C8E4) (L"Dup.csv" > "Dup.csv")
[STAT CALL]
25 652081 [main] ls 3688 lstat64: entering
15 652127 [main] ls 3688 normalize_posix_path: src
/cygdrive/r/dropbox/MS/Dup/original/Dup.csv
15 652142 [main] ls 3688 normalize_posix_path:
/cygdrive/r/dropbox/MS/Dup/original/Dup.csv = normalize_posix_path
(/cygdrive/r/dropbox/MS/Dup/original/Dup.csv)
17 652159 [main] ls 3688 mount_info::conv_to_win32_path:
conv_to_win32_path (/cygdrive/r/dropbox/MS/Dup/original/Dup.csv)
16 652175 [main] ls 3688 mount_info::cygdrive_win32_path: src
'/cygdrive/r/dropbox/MS/Dup/original/Dup.csv', dst
'R:\dropbox\MS\Dup\original\Dup.csv'
16 652191 [main] ls 3688 set_flags: flags: binary (0x2)
15 652206 [main] ls 3688 mount_info::conv_to_win32_path: src_path
/cygdrive/r/dropbox/MS/Dup/original/Dup.csv, dst
R:\dropbox\MS\Dup\original\Dup.csv, flags 0x4022, rc 0
390 652612 [main] ls 3688 symlink_info::check: 0xC000004F =
NtCreateFile (\??\R:\dropbox\MS\Dup\original\Dup.csv)
996 653608 [main] ls 3688 symlink_info::check: 0x0 = NtOpenFile (no-EA,
\??\R:\dropbox\MS\Dup\original\Dup.csv)
1185 654793 [main] ls 3688 symlink_info::check: not a symlink
412 655205 [main] ls 3688 symlink_info::check: 0 = symlink.check
(R:\dropbox\MS\Dup\original\Dup.csv, 0x22B4D0) (0x4022)
30 655235 [main] ls 3688 path_conv::check:
this->path(R:\dropbox\MS\Dup\original\Dup.csv), has_acls(0)
26 655261 [main] ls 3688 build_fh_pc: fh 0x61232318
26 655287 [main] ls 3688 stat_worker:
(\??\R:\dropbox\MS\Dup\original\Dup.csv, 0x6BB850, 0x61232318),
file_attributes 32
29 655316 [main] ls 3688 fhandler_base::open:
(\??\R:\dropbox\MS\Dup\original\Dup.csv, 0x110000)
694 656010 [main] ls 3688 fhandler_base::set_flags: flags 0x110000,
supplied_bin 0x10000
29 656039 [main] ls 3688 fhandler_base::set_flags: O_TEXT/O_BINARY set
in flags 0x10000
23 656062 [main] ls 3688 fhandler_base::set_flags: filemode set to binary
23 656085 [main] ls 3688 fhandler_base::open: 0 = NtCreateFile (0x620,
20080, \??\R:\dropbox\MS\Dup\original\Dup.csv, io, NULL, 0, 7, 1, 4000,
NULL, 0)
27 656112 [main] ls 3688 fhandler_base::open: 1 = fhandler_base::open
(\??\R:\dropbox\MS\Dup\original\Dup.csv, 0x110000)
35 656147 [main] ls 3688 fhandler_base::open_fs: 1 =
fhandler_disk_file::open (\??\R:\dropbox\MS\Dup\original\Dup.csv,
0x10000)
35913 692060 [main] ls 3688 fhandler_base::fstat_helper: 0 = fstat
(\??\R:\dropbox\MS\Dup\original\Dup.csv, 0x6BB850) st_atime=4BFFF67E
st_size=615923, st_mode=0x81A4, st_ino=-5315584508382449066, sizeof=96
39 692099 [main] ls 3688 fhandler_base::close: closing
'/cygdrive/r/dropbox/MS/Dup/original/Dup.csv' handle 0x620
912 693011 [main] ls 3688 stat_worker: 0 =
(\??\R:\dropbox\MS\Dup\original\Dup.csv, 0x6BB850)
[ACL CALL]
24 693095 [main] ls 3688 normalize_posix_path: src
/cygdrive/r/dropbox/MS/Dup/original/Dup.csv
30 693125 [main] ls 3688 normalize_posix_path:
/cygdrive/r/dropbox/MS/Dup/original/Dup.csv = normalize_posix_path
(/cygdrive/r/dropbox/MS/Dup/original/Dup.csv)
26 693151 [main] ls 3688 mount_info::conv_to_win32_path:
conv_to_win32_path (/cygdrive/r/dropbox/MS/Dup/original/Dup.csv)
27 693178 [main] ls 3688 mount_info::cygdrive_win32_path: src
'/cygdrive/r/dropbox/MS/Dup/original/Dup.csv', dst
'R:\dropbox\MS\Dup\original\Dup.csv'
25 693203 [main] ls 3688 set_flags: flags: binary (0x2)
21 693224 [main] ls 3688 mount_info::conv_to_win32_path: src_path
/cygdrive/r/dropbox/MS/Dup/original/Dup.csv, dst
R:\dropbox\MS\Dup\original\Dup.csv, flags 0x4022, rc 0
402 693642 [main] ls 3688 symlink_info::check: 0xC000004F =
NtCreateFile (\??\R:\dropbox\MS\Dup\original\Dup.csv)
774 694416 [main] ls 3688 symlink_info::check: 0x0 = NtOpenFile (no-EA,
\??\R:\dropbox\MS\Dup\original\Dup.csv)
1175 695591 [main] ls 3688 symlink_info::check: not a symlink
414 696005 [main] ls 3688 symlink_info::check: 0 = symlink.check
(R:\dropbox\MS\Dup\original\Dup.csv, 0x22B440) (0x4022)
31 696036 [main] ls 3688 path_conv::check:
this->path(R:\dropbox\MS\Dup\original\Dup.csv), has_acls(0)
28 696064 [main] ls 3688 build_fh_pc: fh 0x612329D8
25 696089 [main] ls 3688 acl_worker: 4 = acl
(/cygdrive/r/dropbox/MS/Dup/original/Dup.csv)
23 696154 [main] ls 3688 normalize_posix_path: src
/cygdrive/r/dropbox/MS/Dup/original/Dup.csv
28 696182 [main] ls 3688 normalize_posix_path:
/cygdrive/r/dropbox/MS/Dup/original/Dup.csv = normalize_posix_path
(/cygdrive/r/dropbox/MS/Dup/original/Dup.csv)
16 696198 [main] ls 3688 mount_info::conv_to_win32_path:
conv_to_win32_path (/cygdrive/r/dropbox/MS/Dup/original/Dup.csv)
16 696214 [main] ls 3688 mount_info::cygdrive_win32_path: src
'/cygdrive/r/dropbox/MS/Dup/original/Dup.csv', dst
'R:\dropbox\MS\Dup\original\Dup.csv'
16 696230 [main] ls 3688 set_flags: flags: binary (0x2)
14 696244 [main] ls 3688 mount_info::conv_to_win32_path: src_path
/cygdrive/r/dropbox/MS/Dup/original/Dup.csv, dst
R:\dropbox\MS\Dup\original\Dup.csv, flags 0x4022, rc 0
349 696609 [main] ls 3688 symlink_info::check: 0xC000004F =
NtCreateFile (\??\R:\dropbox\MS\Dup\original\Dup.csv)
602 697211 [main] ls 3688 symlink_info::check: 0x0 = NtOpenFile (no-EA,
\??\R:\dropbox\MS\Dup\original\Dup.csv)
1182 698393 [main] ls 3688 symlink_info::check: not a symlink
410 698803 [main] ls 3688 symlink_info::check: 0 = symlink.check
(R:\dropbox\MS\Dup\original\Dup.csv, 0x22B440) (0x4022)
30 698833 [main] ls 3688 path_conv::check:
this->path(R:\dropbox\MS\Dup\original\Dup.csv), has_acls(0)
26 698859 [main] ls 3688 build_fh_pc: fh 0x612329D8
27 698886 [main] ls 3688 fhandler_base::open:
(\??\R:\dropbox\MS\Dup\original\Dup.csv, 0x110000)
724 699610 [main] ls 3688 fhandler_base::set_flags: flags 0x110000,
supplied_bin 0x10000
29 699639 [main] ls 3688 fhandler_base::set_flags: O_TEXT/O_BINARY set
in flags 0x10000
23 699662 [main] ls 3688 fhandler_base::set_flags: filemode set to binary
24 699686 [main] ls 3688 fhandler_base::open: 0 = NtCreateFile (0x620,
20080, \??\R:\dropbox\MS\Dup\original\Dup.csv, io, NULL, 0, 7, 1, 4000,
NULL, 0)
27 699713 [main] ls 3688 fhandler_base::open: 1 = fhandler_base::open
(\??\R:\dropbox\MS\Dup\original\Dup.csv, 0x110000)
34 699747 [main] ls 3688 fhandler_base::open_fs: 1 =
fhandler_disk_file::open (\??\R:\dropbox\MS\Dup\original\Dup.csv,
0x10000)
39883 739630 [main] ls 3688 fhandler_base::fstat_helper: 0 = fstat
(\??\R:\dropbox\MS\Dup\original\Dup.csv, 0x22C670) st_atime=4BFFF67E
st_size=615923, st_mode=0x81A4, st_ino=-5315584508382449066, sizeof=96
35 739665 [main] ls 3688 fhandler_base::close: closing
'/cygdrive/r/dropbox/MS/Dup/original/Dup.csv' handle 0x620
968 740633 [main] ls 3688 acl_worker: 4 = acl
(/cygdrive/r/dropbox/MS/Dup/original/Dup.csv)
> On Wed, Jun 02, 2010 at 10:46:03AM -0700, Christopher Wingert wrote:
>>Thanks for the pointer, I just gave it a whirl, it actually didn't make
>>much of a difference.
>>
>>I am going to start looking into making a patch.
>
> Let me point out that the kind of slowdown that you are seeing is not
> something that I would consider acceptable. So what I'd like to see is
> an analysis of *why* Cygwin is so slow rather than a band-aid which uses
> an environment variable or different api to work around a real problem.
>
> cgf
>
> --
> Problem reports: http://cygwin.com/problems.html
> FAQ: http://cygwin.com/faq/
> Documentation: http://cygwin.com/docs.html
> Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
>
>
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
- Raw text -