Re: Slow compile issue with cygwin make since v1.5.17

["Dan Shumuk" <dshumuk at gmail dot com>]

Thanks Jason,

I've ruled out norton AV as the source of the problem.  A  little more
investigation using a very simple make file revealed that the slowdown
was happening when make calls the compiler in a new shell.

I can replicate the problem without incorperating make at all using a
simple script that calls an empty .sh file a number of times (ie. "sh
./donothing.sh") .  The VMware cygwin install does this very fast and
the problem machine takes ~10x longer.

Using strace I can see the slowdown is occurring when the secondary sh
process is ending:

   84 1051407 [main] sh 2248 __to_clock_t: dwHighDateTime 0,
dwLowDateTime 625000
  28 1051435 [main] sh 2248 __to_clock_t: total 00000000 0000003E
  27 1051462 [main] sh 2248 __to_clock_t: dwHighDateTime 0,
dwLowDateTime 156250
  23 1051485 [main] sh 2248 __to_clock_t: total 00000000 0000000F
 484 1051969 [sig] sh 2248 wait_sig: saw __SIGEXIT
  34 1052003 [sig] sh 2248 wait_sig: signal thread exiting
 599 1052602 [main] sh 2248 pinfo::exit: Calling ExitProcess n 0x0,
exitcode 0x0
3573851 4750835 [proc_waiter] sh 1684
pinfo::maybe_set_exit_code_from_windows: pid 2248, exit value - old
0x8000000, windows 0xDEADBEEF, cygwin 0x8000000
  89 4750924 [proc_waiter] sh 1684 sig_send: sendsig 0x6F0, pid 1684,
signal 20, its_me 1
  36 4750960 [proc_waiter] sh 1684 sig_send: Not waiting for
sigcomplete.  its_me 1 signal 20
  27 4750987 [proc_waiter] sh 1684 sig_send: returning 0x0 from
sending signal 20
  25 4751012 [proc_waiter] sh 1684 proc_waiter: exiting wait thread
for pid 2248


The same capture on the VMware machine:

 173  136041 [main] sh 968 __to_clock_t: dwHighDateTime 0,
dwLowDateTime 1406250
  71  136112 [main] sh 968 __to_clock_t: total 00000000 0000008C
  66  136178 [main] sh 968 __to_clock_t: dwHighDateTime 0, dwLowDateTime 156250
  66  136244 [main] sh 968 __to_clock_t: total 00000000 0000000F
 775  137019 [main] sh 968 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
171051  439865 [proc_waiter] sh 1372
pinfo::maybe_set_exit_code_from_windows: pid 968, exit value - old
0x8000000, windows 0xDEADBEEF, cygwin 0x8000000
 145  440010 [proc_waiter] sh 1372 sig_send: sendsig 0x6F4, pid 1372,
signal 20, its_me 1
  90  440100 [proc_waiter] sh 1372 sig_send: Not waiting for
sigcomplete.  its_me 1 signal 20
  75  440175 [proc_waiter] sh 1372 sig_send: returning 0x0 from
sending signal 20
  72  440247 [proc_waiter] sh 1372 proc_waiter: exiting wait thread for pid 968


I am not sure what the significance of this is, but on entry to the
secondary sh process there is a difference in the spawn_guts trace.

The slow call appears as:

  26 1177519 [main] sh 2248 spawn_guts: null_app_name 0
(C:\cygwin\bin\sh.exe, (null))

Whereas the fast call appears as:

  71  271756 [main] sh 968 spawn_guts: null_app_name 0
(C:\cygwin\bin\sh.exe, C:\cygwin\bin\sh.exe ./donothing.sh)

I've attached both the slow, fast building strace files

Thanks in advance,

Dan

Attachment: bashcall_fast_all_one_iteration.txt
Description: Text document

Attachment: bashcall_slow_all_one_iteration.txt
Description: Text document

--
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/