Re: slowness issue between 20060309 and 20060313

[clayne at anodized dot com]

On Sun, May 14, 2006 at 01:49:49PM -0700, clayne@anodized.com wrote:
> On Sun, May 14, 2006 at 01:24:04PM -0700, clayne@anodized.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/