X-Spam-Check-By: sourceware.org
Date: Mon, 19 Feb 2007 13:28:17 -0800
From: Christopher Layne <clayne AT anodized DOT com>
To: cygwin AT cygwin DOT com
Subject: Re: xargs problem
Message-ID: <20070219212817.GB25468@ns1.anodized.com>
References: <1171899485 DOT 45d9c45d44ef0 AT www DOT domainfactory-webmail DOT de> <BAY112-F18CDF858AF31B16E2F01D4C58A0 AT phx DOT gbl> <20070219163431 DOT GX4158 AT calimero DOT vinschen DOT de> <20070219182014 DOT GA25468 AT ns1 DOT anodized DOT com> <erd3d9$7q3$1 AT sea DOT gmane DOT org>
Mime-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <erd3d9$7q3$1@sea.gmane.org>
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-Assp-Intended-For: cygwin AT cygwin DOT com
X-IsSubscribed: yes
Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm
Precedence: bulk
List-Id: <cygwin.cygwin.com>
List-Unsubscribe: <mailto:cygwin-unsubscribe-archive-cygwin=delorie DOT com AT cygwin DOT com>
List-Subscribe: <mailto:cygwin-subscribe AT cygwin DOT com>
List-Archive: <http://sourceware.org/ml/cygwin/>
List-Post: <mailto:cygwin AT cygwin DOT com>
List-Help: <mailto:cygwin-help AT cygwin DOT com>, <http://sourceware.org/ml/#faqs>
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 Mon, Feb 19, 2007 at 01:04:38PM -0800, Shankar Unni wrote:
> Christopher Layne wrote:
> 
> >$ uname -a; uptime; time echo 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 
> >18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 
> >43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 
> >68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 
> >93 94 95 96 97 98 99 100 | xargs -n1 >/dev/null
> >CYGWIN_NT-5.2 opteron 1.7.0s(0.165/4/2) 20070215 07:41:32 i686 Cygwin
> > 10:05:57 up 1 day, 11:10,  0 users,  load average: 0.00, 0.00, 0.00
> >
> >real    0m5.185s
> >user    0m0.150s
> >sys     0m0.573s
> 
> [OT]
> 
> On an Opteron?! I get 1.1 seconds on a low-end Core 2 Duo with WinXP. 
> Something else also the matter at your end.  (Of course, my Linux box, 
> on an older Core Duo, also does this in 0.085 seconds, so your Linux box 
> is slow, too :-) ).

The Linux box is only a Prescott Celeron-D. It's not that bad when it isn't
loaded, under .1s, but those comparisons aren't even the issue really.

> But process creation is well-known to be slow in Cygwin, for completely 
> unavoidable reasons (having to emulate a nearly full layer of POSIX 
> semantics *on top of* Windows processes, which are already slow(er) to 
> start with).

Absolutely. I don't disagree with this. The issue is the magnitude.
The opteron box has 4gigs of ram, scsi 320 disks, and is running water cooled
at 2.8 ghz. Nothing *normal* can explain such a reason why a Celeron-D can
fork the same /bin/echo's 15 times faster than that box, except for the OS
difference. Even then, the difference is insane.

I'm running the latest snapshot, no funky virus or other crap that could
get in the way, 7 items in my path (might as well handle stat() while we're
there), I've tried pointing out in the past that I believe something is
going awry here:

   70     288 [main] xargs 5956 child_copy: dll data - hp 0x6C8 low 0x61118000, high 0x6111D040, res 1
75657   75945 [main] xargs 5956 child_copy: dll bss - hp 0x6C8 low 0x61175000, high 0x6117EC30, res 1
^ 903   76848 [main] xargs 5956 child_copy: user heap - hp 0x6C8 low 0xA20000, high 0xA40000, res 1
|  44   76892 [main] xargs 5956 child_copy: done
|  44   76936 [main] xargs 5956 child_copy: data - hp 0x6C8 low 0x406000, high 0x406050, res 1
|  29   76965 [main] xargs 5956 child_copy: bss - hp 0x6C8 low 0x409000, high 0x4093A0, res 1
|  21   76986 [main] xargs 5956 child_copy: done
|
|__ not normal

10569   98670 [main] xargs 5956 wait_for_sigthread: process/signal handling enabled, state 0x41
[...]
 8850  107734 [sig] xargs 5956 wait_sig: signalling pack.wakeup 0x664
 6149  113883 [main] xargs 5956 sig_send: returning 0x0 from sending signal -34
   89  113972 [main] xargs 5956 open: open (/dev/null, 0x0)
  220  114192 [main] xargs 5956 normalize_posix_path: src /dev/null
25649  114298 [main] xargs 9760 proc_subproc: finished processing terminated/stopped child
25kusec to handle that?

Other stuff as welll that just plain sticks out:
  314   94499 [main] echo 5956 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
124272  240263 [proc_waiter] xargs 9760 pinfo::maybe_set_exit_code_from_windows: pid 5956, exit value - old 0x8000000, windows 0xDEADBEEF, cygwin 0x8000000

The costs may appear small, but they snowball down the chain. If it takes 75kusec to fire
off a bss copy, times 100 = 7500kusec in the worst case. Even if I was hitting 20kusec
per each, it's still 2 seconds.

Here, try yours:

echo 0 1 2 3 4 5 6 9 > bogue
strace xargs -n1 < bogue | egrep 'child_copy:'

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