This is the mail archive of the cygwin mailing list for the Cygwin project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

Re: Cygwin Performance and stat()


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


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]