X-Recipient: archive-cygwin AT delorie DOT com X-SWARE-Spam-Status: No, hits=-0.0 required=5.0 tests=AWL,BAYES_50,TW_CG X-Spam-Check-By: sourceware.org Message-ID: In-Reply-To: <20100602174848.GA14172@ednor.casa.cgf.cx> References: <20100530170747 DOT GA8605 AT ednor DOT casa DOT cgf DOT cx> <4C03D6C5 DOT 4050004 AT x-ray DOT at> <80373222dd5d43b134a5ede7036e7674 DOT squirrel AT www DOT webmail DOT wingert DOT org> <20100602080626 DOT GV16885 AT calimero DOT vinschen DOT de> <383c8b44a088dad09a0b77d3299feda7 DOT squirrel AT www DOT webmail DOT wingert DOT org> <20100602174848 DOT GA14172 AT ednor DOT casa DOT cgf DOT cx> Date: Thu, 3 Jun 2010 10:35:55 -0700 Subject: Re: Cygwin Performance and stat() From: "Christopher Wingert" To: cygwin AT cygwin DOT com User-Agent: SquirrelMail/1.4.20 MIME-Version: 1.0 Content-Type: text/plain;charset=iso-8859-1 Content-Transfer-Encoding: 8bit Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm Precedence: bulk List-Id: List-Unsubscribe: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: cygwin-owner AT cygwin DOT com Mail-Followup-To: cygwin AT cygwin DOT com Delivered-To: mailing list cygwin AT cygwin DOT com 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