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 fork()


On Fri, Sep 01, 2006 at 10:33:47AM -0400, Igor Peshansky wrote:
> While Cygwin is an *emulation* layer, and emulation is inherently slower
> than straight execution, there are other potential reasons for the
> slowness.  Check your anti-virus and firewall software settings.  If
> possible, exclude the Cygwin filesystem from checking by those tools...
> Even little things (like making the tool aware of the often-used Cygwin
> programs and telling it to not check "outbound email messages" (!) sent by
> those programs) can help speed up Cygwin...

It's definitely none of those as I don't run any firewall or antivirus
software whatsoever on this box. Windows 2003 Server, minimal set of
services. The machine literally sits at 0% CPU unless I'm using it.

> A one-sentence rant: even with those changes, whenever I run a Cygwin
> shell script, the stupid vsmon process takes up 100% of the CPU.  No known
> solution.  Sigh...

Don't know what vsmon is.. A likely solution sounds to get rid of vsmon ;).

Also, not to break out the ole Linux vs Cygwin time comparisons type
deal, because we all know hot it's apples and oranges, in this case it's
a bit absurd a difference and I kinda have to. On a Celeron 2gz Linux
box w/512M RAM (which is WAY slower than a dual core Opteron 180
w/ 4GB of RAM):

real    0m11.507s
user    0m9.100s
sys     0m2.320s

11s! For the same "make -j1" vs the 2m20s I got with "make -j1" on my
20060718 Cygwin box. 11s is about 1/4th the time of the best I could get
my opteron to do with 'make -j8'. This is with all the exact same code.
Now we know libtool is intensive, but the libtool being used is the exact
same script (the build script is running a local generated version e.g.
"/bin/sh ../libtool <etc>"). All I did was copy the exact same build
directory to my linux host, cleaned it out, and ran the tests.

Yes apples to oranges for sure, but let's look at some figures here:

Linux 2.6.17.11, Celeron 2ghz/512MB/IDE drive,    11.507s (make -j1)
Cygwin 20060718, Opteron 180@2.8ghz/4GB/U320SCSI, 2m20s   (make -j1)
Cygwin 20060718, Opteron 180@2.8ghz/4GB/U320SCSI, 45.654s (make -j8)

This is what specifically makes me wonder what is up. Just one small
segment of the build which I copied the commands from one to the other:


Linux (Celeron):
[clayne@ns1 lib]$ time if /bin/sh ../libtool --tag=CC --mode=compile gcc -DHAVE_CONFIG_H -I. -I. -I.. -I../lib    -march=pentium4 -mtune=pentium4 -mcpu=pentium4 -Os -MT network.lo -MD -MP -MF ".deps/network.Tpo" -c -o network.lo network.c; then mv -f ".deps/network.Tpo" ".deps/network.Plo"; else rm -f ".deps/network.Tpo"; exit 1; fi
 gcc -DHAVE_CONFIG_H -I. -I. -I.. -I../lib -march=pentium4 -mtune=pentium4 -mcpu=pentium4 -Os -MT network.lo -MD -MP -MF .deps/network.Tpo -c network.c  -fPIC -DPIC -o .libs/network.o
 gcc -DHAVE_CONFIG_H -I. -I. -I.. -I../lib -march=pentium4 -mtune=pentium4 -mcpu=pentium4 -Os -MT network.lo -MD -MP -MF .deps/network.Tpo -c network.c -o network.o >/dev/null 2>&1

real    0m1.254s
user    0m1.140s
sys     0m0.110s
[clayne@ns1 lib]$ time gcc -DHAVE_CONFIG_H -I. -I. -I.. -I../lib -march=pentium4 -mtune=pentium4 -mcpu=pentium4 -Os -MT network.lo -MD -MP -MF .deps/network.Tpo -c network.c  -fPIC -DPIC -o .libs/network.o

real    0m0.549s
user    0m0.520s
sys     0m0.030s
[clayne@ns1 lib]$ time gcc -DHAVE_CONFIG_H -I. -I. -I.. -I../lib -march=pentium4 -mtune=pentium4 -mcpu=pentium4 -Os -MT network.lo -MD -MP -MF .deps/network.Tpo -c network.c -o network.o >/dev/null 2>&1

real    0m0.522s
user    0m0.510s
sys     0m0.010s



Cygwin (Opteron):
$ time if /bin/sh ../libtool --tag=CC --mode=compile gcc -DHAVE_CONFIG_H -I. -I. -I.. -I../lib    -march=pentium4 -mtune=pentium4 -mcpu=pentium4 -Os -MT network.lo -MD -MP -MF ".deps/network.Tpo" -c -o network.lo network.c; then mv -f ".deps/network.Tpo" ".deps/network.Plo"; else rm -f ".deps/network.Tpo"; exit 1; fi
 gcc -DHAVE_CONFIG_H -I. -I. -I.. -I../lib -march=pentium4 -mtune=pentium4 -mcpu=pentium4 -Os -MT network.lo -MD -MP -MF .deps/network.Tpo -c network.c  -DPIC -o .libs/network.o
 gcc -DHAVE_CONFIG_H -I. -I. -I.. -I../lib -march=pentium4 -mtune=pentium4 -mcpu=pentium4 -Os -MT network.lo -MD -MP -MF .deps/network.Tpo -c network.c -o network.o >/dev/null 2>&1

real    0m8.032s
user    0m1.166s
sys     0m2.216s

$ time gcc -DHAVE_CONFIG_H -I. -I. -I.. -I../lib -march=pentium4 -mtune=pentium4 -mcpu=pentium4 -Os -MT network.lo -MD -MP -MF .deps/network.Tpo -c network.c  -DPIC -o .libs/network.o

real    0m0.506s
user    0m0.249s
sys     0m0.061s

$ time gcc -DHAVE_CONFIG_H -I. -I. -I.. -I../lib -march=pentium4 -mtune=pentium4 -mcpu=pentium4 -Os -MT network.lo -MD -MP -MF .deps/network.Tpo -c network.c -o network.o >/dev/null 2>&1

real    0m0.506s
user    0m0.233s
sys     0m0.062s


Obviously it's not gcc, or the execution of binary code that is slow, Same libtool,
different systems, 8 times slower.

Just as a crude test, I dumped the output of that same libtool command but with
/bin/sh -x piped into awk '{print systime(),$0}' to try and see any possible
obvious violators. Everything moving and then:

1157123322 + echo blah1
1157123322 blah1
<3 seconds of doing absolutely nothing here>
1157123325 + test -z ''
1157123325 + echo blah2
1157123325 blah2

The literal script (with my added echos) is:

<-- snip -->
exec_cmd=
echo blah1

if test -z "$show_help"; then
echo blah2
<-- snip -->

Truely bizarre. 

I straced the entire thing and this is what I see:

+ echo blah1
  235 8809138 [main] sh 3344 sig_send: sendsig 0x6E8, pid 3344, signal -34, its_me 1
   28 8809166 [main] sh 3344 sig_send: wakeup 0x660
   28 8809194 [main] sh 3344 sig_send: Waiting for pack.wakeup 0x660
    4 8809198 [sig] sh 3344 wait_sig: signalling pack.wakeup 0x660
   55 8809253 [main] sh 3344 sig_send: returning 0x0 from sending signal -34
   47 8809300 [main] sh 3344 fhandler_base::write: binary write
blah1
  523 8809823 [main] sh 3344 sig_send: sendsig 0x6E8, pid 3344, signal -34, its_me 1
   29 8809852 [main] sh 3344 sig_send: wakeup 0x660
   28 8809880 [main] sh 3344 sig_send: Waiting for pack.wakeup 0x660
    3 8809883 [sig] sh 3344 wait_sig: signalling pack.wakeup 0x660
   54 8809937 [main] sh 3344 sig_send: returning 0x0 from sending signal -34
   27 8809964 [main] sh 3344 sig_send: sendsig 0x6E8, pid 3344, signal -34, its_me 1
   27 8809991 [main] sh 3344 sig_send: wakeup 0x660
   27 8810018 [main] sh 3344 sig_send: Waiting for pack.wakeup 0x660
    4 8810022 [sig] sh 3344 wait_sig: signalling pack.wakeup 0x660
   53 8810075 [main] sh 3344 sig_send: returning 0x0 from sending signal -34
<--- point of repetition --->
   25 8810100 [main] sh 3344 readv: readv (255, 0x22BFC0, 1) blocking, sigcatchers 1
   26 8810126 [main] sh 3344 readv: no need to call ready_for_read
   28 8810154 [main] sh 3344 fhandler_base::read: read 0 bytes ()
   25 8810179 [main] sh 3344 fhandler_base::read: returning 1, text mode
   26 8810205 [main] sh 3344 readv: 1 = readv (255, 0x22BFC0, 1), errno 0
  112 8810317 [main] sh 3344 sig_send: sendsig 0x6E8, pid 3344, signal -34, its_me 1
   27 8810344 [main] sh 3344 sig_send: wakeup 0x660
   28 8810372 [main] sh 3344 sig_send: Waiting for pack.wakeup 0x660
    4 8810376 [sig] sh 3344 wait_sig: signalling pack.wakeup 0x660
   52 8810428 [main] sh 3344 sig_send: returning 0x0 from sending signal -34
   27 8810455 [main] sh 3344 sig_send: sendsig 0x6E8, pid 3344, signal -34, its_me 1
   27 8810482 [main] sh 3344 sig_send: wakeup 0x660
   27 8810509 [main] sh 3344 sig_send: Waiting for pack.wakeup 0x660
    4 8810513 [sig] sh 3344 wait_sig: signalling pack.wakeup 0x660
   53 8810566 [main] sh 3344 sig_send: returning 0x0 from sending signal -34
<--- endless repetition continues until --->
+ test -z ''
  182 56491808 [main] sh 3344 sig_send: sendsig 0x6E8, pid 3344, signal -34, its_me 1
   30 56491838 [main] sh 3344 sig_send: wakeup 0x660
   28 56491866 [main] sh 3344 sig_send: Waiting for pack.wakeup 0x660
    4 56491870 [sig] sh 3344 wait_sig: signalling pack.wakeup 0x660
   52 56491922 [main] sh 3344 sig_send: returning 0x0 from sending signal -34
   28 56491950 [main] sh 3344 sig_send: sendsig 0x6E8, pid 3344, signal -34, its_me 1
   27 56491977 [main] sh 3344 sig_send: wakeup 0x660
   27 56492004 [main] sh 3344 sig_send: Waiting for pack.wakeup 0x660
    4 56492008 [sig] sh 3344 wait_sig: signalling pack.wakeup 0x660
   53 56492061 [main] sh 3344 sig_send: returning 0x0 from sending signal -34
   25 56492086 [main] sh 3344 set_signal_mask: oldmask 0x0, newmask 0x0, mask_bits 0x0
   27 56492113 [main] sh 3344 set_signal_mask: not calling sig_dispatch_pending
 1761 56493874 [main] sh 3344 sig_send: sendsig 0x6E8, pid 3344, signal -34, its_me 1
   28 56493902 [main] sh 3344 sig_send: wakeup 0x660
   28 56493930 [main] sh 3344 sig_send: Waiting for pack.wakeup 0x660
    4 56493934 [sig] sh 3344 wait_sig: signalling pack.wakeup 0x660
   53 56493987 [main] sh 3344 sig_send: returning 0x0 from sending signal -34
   47 56494034 [main] sh 3344 fhandler_base::write: binary write
+ echo blah2
  222 56494256 [main] sh 3344 sig_send: sendsig 0x6E8, pid 3344, signal -34, its_me 1
   29 56494285 [main] sh 3344 sig_send: wakeup 0x660
   28 56494313 [main] sh 3344 sig_send: Waiting for pack.wakeup 0x660
    4 56494317 [sig] sh 3344 wait_sig: signalling pack.wakeup 0x660
   56 56494373 [main] sh 3344 sig_send: returning 0x0 from sending signal -34
   47 56494420 [main] sh 3344 fhandler_base::write: binary write
blah2

I counted up the number of bytes that section of repetition took in the strace
output, and divided it by a single rep's size:

It does that same readv() blocking, sig_send, wait_sig loop about 115,012 times.

--



Back in May, I did these timed runs for a similar build (albeit a larger
directory) and arrrived at these figures for a make -j1:

The dates are the cygwin snapshot version.
Actual times seen:

20060309:
real    1m47.328s
user    0m17.074s
sys     0m59.145s

20060318:
real    3m20.953s
user    0m11.703s
sys     0m45.895s

20060314:
real    3m21.594s
user    0m11.713s
sys     0m45.894s

20060313:
real    3m21.594s
user    0m11.715s
sys     0m46.134s


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


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