X-Spam-Check-By: sourceware.org Date: Sun, 14 May 2006 17:31:23 -0700 From: clayne AT anodized DOT com To: cygwin AT cygwin DOT com Subject: Re: slowness issue between 20060309 and 20060313 Message-ID: <20060515003123.GH1783@ns1.anodized.com> References: <20060514202404 DOT GF1783 AT ns1 DOT anodized DOT com> <20060514204949 DOT GG1783 AT ns1 DOT anodized DOT com> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20060514204949.GG1783@ns1.anodized.com> User-Agent: Mutt/1.5.11 X-Assp-Spam-Prob: 0.00000 X-Assp-Whitelisted: Yes X-Assp-Envelope-From: clayne AT ns1 DOT anodized DOT com X-IsSubscribed: yes Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm Precedence: bulk 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 On Sun, May 14, 2006 at 01:49:49PM -0700, clayne AT anodized DOT com wrote: > On Sun, May 14, 2006 at 01:24:04PM -0700, clayne AT anodized DOT com wrote: > > not even slowdown that could be explained by typical fork overhead, it's literally > > 200% the difference. > > > > >From 20060313 and any snapshot above that, I see the exact same behavior. From any > > below *and including* 20060309 I do *not* see the behavior. > > > > -cl So from analyzing strace output of two exact same commands, (in this case "strace make clean"), everything is about the same between 20060309 and 20060313 up until forking off make.exe: 20060309: ********************************************** Program name: C:\cygwin\bin\make.exe (pid 12812, ppid 7488) App version: 1005.20, api: 0.155 DLL version: 1005.20, api: 0.155 DLL build: 20060309 10:35:06SNP OS version: Windows NT-5.2 Heap size: 402653184 Date/Time: 2006-05-14 15:57:54 ********************************************** 26 196 [main] make 12812 set_myself: myself->dwProcessId 12812 58 254 [main] make 12812 child_copy: dll data - hp 0x6D4 low 0x610FB000, high 0x610FFB00, res 1 697570 697824 [main] make 12812 child_copy: dll bss - hp 0x6D4 low 0x61138000, high 0x61141690, res 1 235 698059 [main] make 12812 child_copy: user heap - hp 0x6D4 low 0x440000, high 0x470000, res 1 25 698084 [main] make 12812 child_copy: done 34 698118 [main] make 12812 child_copy: data - hp 0x6D4 low 0x424000, high 0x4249F0, res 1 30 698148 [main] make 12812 child_copy: bss - hp 0x6D4 low 0x426000, high 0x426770, res 1 25 698173 [main] make 12812 child_copy: done 23 698196 [main] make 12812 fixup_mmaps_after_fork: succeeded 43 698239 [main] make 12812 events_init: windows_system_directory 'C:\WINDOWS\system32\', windows_system_directory_length 20 42 698281 [main] make 12812 dll_crt0_0: finished dll_crt0_0 initialization 136 698417 [main] make 12812 frok::child: child is running. pid 12812, ppid 7488, stack here 0x22DF28 25 698442 [main] make 12812 sync_with_parent: signalling parent: after longjmp 28 698470 [main] make 12812 child_info::ready: signalled 0x6E4 that I was ready 4964 698475 [main] make 7488 child_info::sync: process 12812 synchronized, WFMO returned 0 44 698519 [main] make 7488 frok::parent: child is alive (but stopped) 44 698563 [main] make 7488 child_copy: stack - hp 0x6C0 low 0x22DF30, high 0x230000, res 1 27 698590 [main] make 7488 child_copy: done 23 698613 [main] make 7488 frok::parent: copying data/bss of a linked dll 40 698653 [main] make 7488 child_copy: linked dll data - hp 0x6C0 low 0x6B344000, high 0x6B344010, res 1 33 698686 [main] make 7488 child_copy: linked dll bss - hp 0x6C0 low 0x6B41E000, high 0x6B41E3B0, res 1 27 698713 [main] make 7488 child_copy: done 23 698736 [main] make 7488 frok::parent: copying data/bss of a linked dll 36 698772 [main] make 7488 child_copy: linked dll data - hp 0x6C0 low 0x6B2D9000, high 0x6B2D9070, res 1 34 698806 [main] make 7488 child_copy: linked dll bss - hp 0x6C0 low 0x6B2DB000, high 0x6B2DB4C0, res 1 25 698831 [main] make 7488 child_copy: done 24 698855 [main] make 7488 resume_child: signalled child 389 698859 [main] make 12812 sync_with_parent: awake 23 698878 [main] make 7488 child_info::sync: n 2, waiting for subproc_ready(0x6E4) and child process(0x6C0) 28 698887 [main] make 12812 sync_with_parent: no problems 23 698910 [main] make 12812 frok::child: hParent 0x6D4, child 1 first_dll 0x6B430000, load_dlls 0 34 698944 [main] make 12812 set_privilege: 1 = set_privilege ((token 780) SeRestorePrivilege, 1) 26 698970 [main] make 12812 set_privilege: 1 = set_privilege ((token 780) SeBackupPrivilege, 1) 24 698994 [main] make 12812 set_privilege: 1 = set_privilege ((token 780) SeChangeNotifyPrivilege, 1) 33 699027 [main] make 12812 set_file_api_mode: File APIs set to ANSI 30 699057 [main] make 12812 dtable::fixup_after_fork: fd 3 () 24 699081 [main] make 12812 fhandler_base::fixup_after_fork: inheriting '' from parent 32 699113 [main] make 12812 sync_with_parent: signalling parent: performed fork fixup 24 699137 [main] make 12812 child_info::ready: signalled 0x6E4 that I was ready 265 699143 [main] make 7488 child_info::sync: process 12812 synchronized, WFMO returned 0 137 699274 [main] make 12812 sigproc_init: process/signal handling enabled, state 0x801 84 699358 [main] make 12812 pthread_mutex::_fixup_after_fork: mutex 441C48 in _fixup_after_fork 43 699401 [main] make 12812 pthread_mutex::_fixup_after_fork: mutex 440060 in _fixup_after_fork 27 699428 [main] make 12812 pthread_mutex::_fixup_after_fork: mutex 611411A8 in _fixup_after_fork 369 699512 [main] make 7488 sig_send: sendsig 0x704, pid 7488, signal -41, its_me 1 28 699540 [main] make 7488 sig_send: wakeup 0x6D0 31 699571 [main] make 7488 sig_send: Waiting for pack.wakeup 0x6D0 5 699576 [sig] make 7488 wait_sig: signalling pack.wakeup 0x6D0 56 699632 [main] make 7488 sig_send: returning 0x0 from sending signal -41 25 699657 [main] make 7488 fork: 12812 = fork() 67 699724 [main] make 7488 sig_send: sendsig 0x704, pid 7488, signal -34, its_me 1 30 699754 [main] make 7488 sig_send: wakeup 0x6D4 32 699786 [main] make 7488 sig_send: Waiting for pack.wakeup 0x6D4 390 699818 [main] make 12812 wait_for_sigthread: wait_sig_inited 0x6D0 50 699836 [sig] make 7488 wait_sig: signalling pack.wakeup 0x6D4 4 699822 [sig] make 12812 wait_sig: myself->dwProcessId 12812 28 699864 [main] make 7488 sig_send: returning 0x0 from sending signal -34 54 699876 [sig] make 12812 wait_sig: entering ReadFile loop, readsig 0x71C, myself->sendsig 0x718 20060313: ********************************************** Program name: C:\cygwin\bin\make.exe (pid 17884, ppid 1) App version: 1005.20, api: 0.155 DLL version: 1005.20, api: 0.155 DLL build: 20060313 16:23:56SNP OS version: Windows NT-5.2 Heap size: 402653184 Date/Time: 2006-05-14 15:56:33 ********************************************** 27 211 [main] make 17884 set_myself: myself->dwProcessId 17884 24 235 [main] make 17884 time: 1147647393 = time (0) 61 296 [main] make 17884 child_copy: dll data - hp 0x6D4 low 0x610FB000, high 0x610FFAF0, res 1 689204 689500 [main] make 17884 child_copy: dll bss - hp 0x6D4 low 0x61138000, high 0x61141690, res 1 221 689721 [main] make 17884 child_copy: user heap - hp 0x6D4 low 0x640000, high 0x670000, res 1 26 689747 [main] make 17884 child_copy: done 33 689780 [main] make 17884 child_copy: data - hp 0x6D4 low 0x424000, high 0x4249F0, res 1 30 689810 [main] make 17884 child_copy: bss - hp 0x6D4 low 0x426000, high 0x426770, res 1 26 689836 [main] make 17884 child_copy: done 23 689859 [main] make 17884 fixup_mmaps_after_fork: succeeded 52 689911 [main] make 17884 events_init: windows_system_directory 'C:\WINDOWS\system32\', windows_system_directory_length 20 45 689956 [main] make 17884 dll_crt0_0: finished dll_crt0_0 initialization 115 690071 [main] make 17884 wait_for_sigthread: wait_sig_inited 0x7D4 28556 718627 [sig] make 17884 wait_sig: myself->dwProcessId 17884 | 29 718656 [sig] make 17884 wait_sig: entering ReadFile loop, readsig 0x778, myself->sendsig 0x774 | *------------------- suspect (but only .05 secs in grand scheme), however I think this is a symptom of something | | 82 718738 [main] make 17884 frok::child: child is running. pid 17884, ppid 0, stack here 0x22DF28 | 27 718765 [main] make 17884 sync_with_parent: signalling parent: after longjmp | 29 718794 [main] make 17884 child_info::ready: signalled 0x6E4 that I was ready 31692 718796 [main] make 6380 child_info::sync: pid 17884, WFMO returned 0, res 1 64 718860 [main] make 6380 open_shared: name Global\cygwin1S4.cygpid.17884, n 17884, shared 0x18B60000 (wanted 0x0), h 0x6C8 33 718893 [main] make 6380 proc_subproc: args: 1, 2285296 47 718940 [main] make 6380 _pinfo::dup_proc_pipe: closed wr_proc_pipe 0x75C for pid 17884(17884) 146 719086 [main] make 6380 pinfo::wait: created tracking thread for pid 17884, winpid 0x45DC, rd_pipe 0x6CC 39 719125 [main] make 6380 proc_subproc: added pid 17884 to proc table, slot 0 27 719152 [main] make 6380 proc_subproc: returning 1 24 719176 [main] make 6380 frok::parent: child is alive (but stopped) # By the time we get to make.exe forking off sh.exe, the differences are not huge: 20060309: ********************************************** Program name: C:\cygwin\bin\sh.exe (pid 12812, ppid 7488) App version: 1005.20, api: 0.155 DLL version: 1005.20, api: 0.155 DLL build: 20060309 10:35:06SNP OS version: Windows NT-5.2 Heap size: 402653184 Date/Time: 2006-05-14 15:57:54 ********************************************** 25 193 [main] sh 12812 set_myself: myself->dwProcessId 14508 86 279 [main] sh 12812 open_shared: name Global\cygwin1S4.cygpid.14508, n 14508, shared 0x18490000 (wanted 0x0), h 0x798 33 312 [main] sh 12812 child_info::ready: signalled 0x6D0 that I was ready 6258 709061 [main] make 12812! child_info::sync: process 12812 synchronized, WFMO returned 0 20060313: ********************************************** Program name: C:\cygwin\bin\sh.exe (pid 17884, ppid 6380) App version: 1005.20, api: 0.155 DLL version: 1005.20, api: 0.155 DLL build: 20060313 16:23:56SNP OS version: Windows NT-5.2 Heap size: 402653184 Date/Time: 2006-05-14 15:56:33 ********************************************** 26 199 [main] sh 17884 set_myself: myself->dwProcessId 3200 96 295 [main] sh 17884 open_shared: name Global\cygwin1S4.cygpid.3200, n 3200, shared 0x18690000 (wanted 0x0), h 0x794 33 328 [main] sh 17884 child_info::ready: signalled 0x710 that I was ready 3578 726721 [main] make 17884! child_info::sync: pid 3200, WFMO returned 0, res 1 # 709061 vs 726721 - not exactly something that could account for 200%. # # Ensuing timings within sh.exe are similar for each, sans the following for 20060313, # which is similar to the previously mentioned: 22710 23503 [sig] sh 17884 wait_sig: myself->dwProcessId 3200 60 23563 [sig] sh 17884 wait_sig: entering ReadFile loop, readsig 0x770, myself->sendsig 0x76C # rm.exe has similar timings for each, although significant difference here: 20060309: 220 6340 [main] rm 18444 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0 16018 63779 [proc_waiter] sh 12812 pinfo::maybe_set_exit_code_from_windows: pid 18444, exit value - old 0x8000000, windows 0xDEADBEEF, cygwin 0x8000000 20060313: 217 26594 [main] rm 10364 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0 33460 123436 [proc_waiter] sh 17884 pinfo::maybe_set_exit_code_from_windows: pid 10364, exit value - old 0x8000000, windows 0xDEADBEEF, cygwin 0x8000000 # similar trend: 20060309: 241 68057 [main] sh 12812 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0 76759 777300 [proc_waiter] make 7488 pinfo::maybe_set_exit_code_from_windows: pid 12812, exit value - old 0x8000000, windows 0xDEADBEEF, cygwin 0x8000000 20060313: 248 127860 [main] sh 17884 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0 133734 854801 [proc_waiter] make 6380 pinfo::maybe_set_exit_code_from_windows: pid 17884, exit value - old 0x8000000, windows 0xDEADBEEF, cygwin 0x8000000 # back to make.exe again # timing differences are still not large: 20060309: 23 167 [main] make 19720 set_myself: myself->dwProcessId 19720 52 219 [main] make 19720 child_copy: dll data - hp 0x6C8 low 0x610FB000, high 0x610FFB00, res 1 782196 782415 [main] make 19720 child_copy: dll bss - hp 0x6C8 low 0x61138000, high 0x61141690, res 1 20060313: 53 226 [main] make 18368 set_myself: myself->dwProcessId 18368 24 250 [main] make 18368 time: 1147647393 = time (0) 54 304 [main] make 18368 child_copy: dll data - hp 0x6C8 low 0x610FB000, high 0x610FFAF0, res 1 859038 859342 [main] make 18368 child_copy: dll bss - hp 0x6C8 low 0x61138000, high 0x61141690, res 1 # more of the same, delays in the same places but nothing outstanding, although there seems to be a # trend of the delays (not surprising). # # back to another sh.exe child: 20060309: ********************************************** 21 284 [main] sh 9016 set_myself: myself->dwProcessId 9016 83 367 [main] sh 9016 child_copy: dll data - hp 0x6F4 low 0x610FB000, high 0x610FFB00, res 1 56963 57330 [main] sh 9016 child_copy: dll bss - hp 0x6F4 low 0x61138000, high 0x61141690, res 1 20060313: ********************************************** 26 199 [main] sh 13260 set_myself: myself->dwProcessId 13260 24 223 [main] sh 13260 time: 1147647394 = time (0) 61 284 [main] sh 13260 child_copy: dll data - hp 0x6F8 low 0x610FB000, high 0x610FFAF0, res 1 126656 126940 [main] sh 13260 child_copy: dll bss - hp 0x6F8 low 0x61138000, high 0x61141690, res 1 # seems a rather large timing difference there... # # by child return: 20060309: 19 73454 [main] sh 9016! child_info::sync: n 2, waiting for subproc_ready(0x714) and child process(0x6E8) ********************************************** 20060313: 19 164059 [main] sh 13260! child_info::sync: n 2, waiting for subproc_ready(0x704) and child process(0x6EC) ********************************************** # # now we're in a sed.exe child: # 20060309: 48 4192 [main] sed 9016 fhandler_base::write: binary write 39031 79183 [read_pipe] sh 19720 fhandler_base::read: read 0 bytes () 56 79239 [read_pipe] sh 19720 fhandler_base::read: returning 14, text mode 20060313: 49 33563 [main] sed 13260 fhandler_base::write: binary write 109318 199250 [read_pipe] sh 18368 fhandler_base::read: read 0 bytes () 61 199311 [read_pipe] sh 18368 fhandler_base::read: returning 14, text mode # seems very large for the exact same thing. # following with the previously seen: 20060309: 228 5787 [main] sed 9016 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0 17869 81148 [proc_waiter] sh 9204 pinfo::maybe_set_exit_code_from_windows: pid 9016, exit value - old 0x8000000, windows 0xDEADBEEF, cygwin 0x8000000 20060313: 239 35206 [main] sed 13260 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0 47260 201253 [proc_waiter] sh 6100 pinfo::maybe_set_exit_code_from_windows: pid 13260, exit value - old 0x8000000, windows 0xDEADBEEF, cygwin 0x8000000 # by the time we've gotten to an actual rm of a file: 20060309: rm -f "./so_locations" 1440 95074 [main] sh 19720 stat64: entering 20060313: rm -f "./so_locations" 1449 215023 [main] sh 18368 stat64: entering # ~120000us difference, still only ~0.12s in grand scheme. # # more of the same from sh.exe again (twice as long to do the same op): # 20060309: 25 190 [main] sh 2500 set_myself: myself->dwProcessId 2500 56 246 [main] sh 2500 child_copy: dll data - hp 0x6E4 low 0x610FB000, high 0x610FFB00, res 1 104592 104838 [main] sh 2500 child_copy: dll bss - hp 0x6E4 low 0x61138000, high 0x61141690, res 1 100 104938 [main] sh 2500 child_copy: user heap - hp 0x6E4 low 0x490000, high 0x4A0000, res 1 20060313: 57 314 [main] sh 6008 child_copy: dll data - hp 0x6E4 low 0x610FB000, high 0x610FFAF0, res 1 224727 225041 [main] sh 6008 child_copy: dll bss - hp 0x6E4 low 0x61138000, high 0x61141690, res 1 92 225133 [main] sh 6008 child_copy: user heap - hp 0x6E4 low 0x690000, high 0x6A0000, res 1 # another later down: 20060309: ********************************************** Program name: C:\cygwin\bin\sh.exe (pid 4852, ppid 7368) App version: 1005.20, api: 0.155 DLL version: 1005.20, api: 0.155 DLL build: 20060309 10:35:06SNP OS version: Windows NT-5.2 Heap size: 402653184 Date/Time: 2006-05-14 15:57:54 ********************************************** 25 191 [main] sh 4852 set_myself: myself->dwProcessId 4852 54 245 [main] sh 4852 child_copy: dll data - hp 0x6D8 low 0x610FB000, high 0x610FFB00, res 1 141066 141311 [main] sh 4852 child_copy: dll bss - hp 0x6D8 low 0x61138000, high 0x61141690, res 1 99 141410 [main] sh 4852 child_copy: user heap - hp 0x6D8 low 0x490000, high 0x4A0000, res 1 20060313: ********************************************** Program name: C:\cygwin\bin\sh.exe (pid 13204, ppid 1) App version: 1005.20, api: 0.155 DLL version: 1005.20, api: 0.155 DLL build: 20060313 16:23:56SNP OS version: Windows NT-5.2 Heap size: 402653184 Date/Time: 2006-05-14 15:56:34 ********************************************** 26 200 [main] sh 13204 set_myself: myself->dwProcessId 13204 24 224 [main] sh 13204 time: 1147647394 = time (0) 61 285 [main] sh 13204 child_copy: dll data - hp 0x6DC low 0x610FB000, high 0x610FFAF0, res 1 316199 316484 [main] sh 13204 child_copy: dll bss - hp 0x6DC low 0x61138000, high 0x61141690, res 1 # later down sed.exe displays similar read() behavior of 3x magnitude. # sh.exe's however are now starting to display significant delays: 20060309: ********************************************** 27 198 [main] sh 15612 set_myself: myself->dwProcessId 15612 57 255 [main] sh 15612 child_copy: dll data - hp 0x6A8 low 0x610FB000, high 0x610FFB00, res 1 194811 195066 [main] sh 15612 child_copy: dll bss - hp 0x6A8 low 0x61138000, high 0x61141690, res 1 20060313: ********************************************** 28 233 [main] sh 8816 set_myself: myself->dwProcessId 8816 24 257 [main] sh 8816 time: 1147647394 = time (0) 60 317 [main] sh 8816 child_copy: dll data - hp 0x6B0 low 0x610FB000, high 0x610FFAF0, res 1 439826 440143 [main] sh 8816 child_copy: dll bss - hp 0x6B0 low 0x61138000, high 0x61141690, res 1 # this continues to scale in a linear fashion for both, i.e. they're both increasing, however # 20060313 is always more than 2x the delay of 20060309 # # which eventually starts to become ridiculous: 20060309: ********************************************** 27 200 [main] sh 6496 set_myself: myself->dwProcessId 6496 56 256 [main] sh 6496 child_copy: dll data - hp 0x6FC low 0x610FB000, high 0x610FFB00, res 1 376829 377085 [main] sh 6496 child_copy: dll bss - hp 0x6FC low 0x61138000, high 0x61141690, res 1 20060313: ********************************************** 26 202 [main] sh 13276 set_myself: myself->dwProcessId 13276 25 227 [main] sh 13276 time: 1147647394 = time (0) 61 288 [main] sh 13276 child_copy: dll data - hp 0x6AC low 0x610FB000, high 0x610FFAF0, res 1 877493 877781 [main] sh 13276 child_copy: dll bss - hp 0x6AC low 0x61138000, high 0x61141690, res 1 # I don't think it should take ~0.87s to do that, but one is never sure I guess. # but by the time we start making it back to make.exe, timing differences are obvious: 20060309: 242 398723 [main] sh 19720 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0 404791 1189823 [proc_waiter] make 7488 pinfo::maybe_set_exit_code_from_windows: pid 19720, exit value - old 0x8000000, windows 0xDEADBEEF, cygwin 0x8000000 34 1189857 [proc_waiter] make 7488 sig_send: sendsig 0x704, pid 7488, signal 20, its_me 1 20060313: 226 939326 [main] sh 18368 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0 945059 1822358 [proc_waiter] make 6380 pinfo::maybe_set_exit_code_from_windows: pid 18368, exit value - old 0x8000000, windows 0xDEADBEEF, cygwin 0x8000000 31 1822389 [proc_waiter] make 6380 sig_send: sendsig 0x730, pid 6380, signal 20, its_me 1 # and by exit entirely: 20060309: 131 1386979 [main] make 7488 __to_clock_t: dwHighDateTime 0, dwLowDateTime 1875000 27 1387006 [main] make 7488 __to_clock_t: total 00000000 000000BB 25 1387031 [main] make 7488 __to_clock_t: dwHighDateTime 0, dwLowDateTime 625000 25 1387056 [main] make 7488 __to_clock_t: total 00000000 0000003E 232 1387288 [main] make 7488 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0 20060313: 117 2212491 [main] make 6380 __to_clock_t: dwHighDateTime 0, dwLowDateTime 1875000 27 2212518 [main] make 6380 __to_clock_t: total 00000000 000000BB 25 2212543 [main] make 6380 __to_clock_t: dwHighDateTime 0, dwLowDateTime 1875000 24 2212567 [main] make 6380 __to_clock_t: total 00000000 000000BB 215 2212782 [main] make 6380 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0 # # 1387288us vs 2212782us # There just seems to be a general trend of 2-2.5x magnitude in certain ops from 20060313 vs 20060309. This is definitely no hand-picked case either - I could run these same tests over and over and see a similar result: overall a 200% difference between 20060313 compared to 20060309 in operations involving multiple forks (be it compilation, building, scripts, whatever). This continues even until the most recent snapshot. -cl -- Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple Problem reports: http://cygwin.com/problems.html Documentation: http://cygwin.com/docs.html FAQ: http://cygwin.com/faq/