X-Recipient: archive-cygwin AT delorie DOT com
DomainKey-Signature: a=rsa-sha1; c=nofws; d=sourceware.org; h=list-id
	:list-unsubscribe:list-subscribe:list-archive:list-post
	:list-help:sender:date:from:to:subject:message-id:reply-to
	:references:mime-version:content-type:in-reply-to; q=dns; s=
	default; b=j04xK92LuauJJkytGlYCg+RCWrVB5yPTDN4KbhZisn0DHw68UEilW
	zUbyXB6c/3LSj90fGbLw4JXqiZL35ZLw8ec5WHcYuLJ6ABe7fthRFbbqOcN/gZx+
	cvA8oXujymR9ws6ORDScBFgYhb+G8V/5ijEbRXlT7OI97AOcGthltI=
DKIM-Signature: v=1; a=rsa-sha1; c=relaxed; d=sourceware.org; h=list-id
	:list-unsubscribe:list-subscribe:list-archive:list-post
	:list-help:sender:date:from:to:subject:message-id:reply-to
	:references:mime-version:content-type:in-reply-to; s=default;
	 bh=fyiOOdY5ddFoP4Mx6RT4ys4gwkI=; b=bzfUSXePYoRFtKzfq5tfATleukZ5
	kn9Pt1ksaq1u2+++k16p/VeaSlYLMnUFkr+AD3vHjJTpqDsfDzObWqxM7J0+kXAf
	W09Mnh0ut3XR8puzHnz7oUJS1axAvsFVS7OUgXan22NrjTZBemwVz+4KOBhvDoZK
	UXoFEbVNYcldKx8=
Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm
List-Id: <cygwin.cygwin.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
Authentication-Results: sourceware.org; auth=none
X-Virus-Found: No
X-Spam-SWARE-Status: No, score=-5.9 required=5.0 tests=AWL,BAYES_00 autolearn=ham version=3.3.2
X-HELO: calimero.vinschen.de
Date: Fri, 20 Feb 2015 17:20:24 +0100
From: Corinna Vinschen <corinna-cygwin AT cygwin DOT com>
To: cygwin AT cygwin DOT com
Subject: Re: Very slow Cygwin startup on Windows 7
Message-ID: <20150220162024.GZ26084@calimero.vinschen.de>
Reply-To: cygwin AT cygwin DOT com
Mail-Followup-To: cygwin AT cygwin DOT com
References: <87mw4nugdx DOT fsf AT Rainer DOT invalid> <3FEEC3A37A0B0A48AA326075128C32EE4DC9F137 AT xmb-rcd-x01 DOT cisco DOT com> <869208266 DOT 20150210030528 AT yandex DOT ru> <3FEEC3A37A0B0A48AA326075128C32EE4EE263B8 AT xmb-rcd-x01 DOT cisco DOT com> <20150218111515 DOT GL8493 AT calimero DOT vinschen DOT de> <3FEEC3A37A0B0A48AA326075128C32EE4EE26DE4 AT xmb-rcd-x01 DOT cisco DOT com> <20150218125429 DOT GN8493 AT calimero DOT vinschen DOT de> <3FEEC3A37A0B0A48AA326075128C32EE4EE275A7 AT xmb-rcd-x01 DOT cisco DOT com> <20150219103235 DOT GD26084 AT calimero DOT vinschen DOT de> <3FEEC3A37A0B0A48AA326075128C32EE4EE27AEC AT xmb-rcd-x01 DOT cisco DOT com>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha1;	protocol="application/pgp-signature"; boundary="6pjpgtPchv3bUQQn"
Content-Disposition: inline
In-Reply-To: <3FEEC3A37A0B0A48AA326075128C32EE4EE27AEC@xmb-rcd-x01.cisco.com>
User-Agent: Mutt/1.5.23 (2014-03-12)

--6pjpgtPchv3bUQQn
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On Feb 19 19:04, Dennis Hagarty (dehagart) wrote:
> >It would be pretty helpful to get an idea what's so slow in your case.
> >Either you get ADInsight working, or...  is it ok if I send you a link
> >to a debug-augmented DLL via PM?
>=20
> Sure.

Thanks for helping debugging, Dennis.

=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
tl;dr synopsis:  There are new snaphots at https://cygwin.com/snapshots/
which introduce a restriction of the time fetching group information
at startup is allowed to take (300ms).  Please give'em a try.
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D

I asked Dennis to run Cygwin's "echo" three times from CMD, no cygserver
running, to get some timing values and to be able to observer OS caching
effects.

First of all, the first call of echo took a bit longer than the followup
calls, because fetching the machine and domain info took longer.  The
info is supposed to be cached on the local machine, but the info is
refreshed in a 15 minute cycle or something like that.  This first call
to fetch this info took 0.3 secs, so maybe your local machine was just
in that refresh cycle.  The same thing in the followup echo calls only
took 9 and 7ms.  Clearly a caching effect.

However, fetching every single group from your token, information which
should be locally available or at least should be quickly available via
the global catalog, takes roughly 40 to 50 ms each.  This adds up quickly
to the 1.4 secs you see as delay running an echo here.

To explain, the idea to fetch all the group info from your user token
was to make sure that the first process in a process tree already had
the entire set of your groups available.  This was based on a complaint
that calling `id' could take a long time.

However, on second thought, this looks like a terrible idea.  40 to 50ms
per group is a hell of a lot of time when fetching lots of group info.
For comparison, in my tiny home network, fetching this info takes
between 2 and 5 ms per group :}

In a second test run I asked Dennis to give me the timing of a startup
and calling `id' with cygserver running.

The results:

- Without cygserver:

  Shell startup:       1.5s
  Calling `id':        0.1s
  Calling `id' again:  0.1s

- With cygserver:

  Shell startup:       0.1s
  Calling `id':        1.5s
  Calling `id' again:  0.1s

The reason for this behaviour is the difference in startup:

- When cygserver is not running, the startup fetches the information for
  all groups in the user token.  Thus the first process (mintty when
  clicking on the desktop icon) takes long, and followup processes have
  the cached information at their leisure.

- When cygserver is running, the startup does not fetch the group
  information (relying on cygserver instead).  Thus, the first call to
  `id' does it instead and takes the long time.  Afterwards, the
  information is cached in cygserver and the next call to `id' is fast.

The first idea was to stop fetching the group info at startup
completely.  But that has the side effect of having an always slow `id'
call, if cygserver isn't running, so it's not exactly clear to me if
that's not just frying pan =3D=3D> fire.

So what I did now for testing is to add a timer.  If cygserver is not
running, the startup procedure still fetches the group info from the
user's token... but if it couldn't finish the job within 300ms, it
just stops collecting this information and moves on.

That should have a "mixed" effect in slow scenarios.  The startup will
not take longer than about 300ms, so it's comparatively fast from a
human perspective, but it will not entirely give up on collecting group
information so subsequent calls fetching group info will be faster.

The value itself, 300ms, is disputable, of course.  I just chose it from
my gut feeling.  If this method is a usable compromise, maybe 400 or
500ms is good enough, I don't know.

I uploaded new developer snapshots containing this change to

  https://cygwin.com/snapshots/

Please give them a try.


Thanks,
Corinna

--=20
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

--6pjpgtPchv3bUQQn
Content-Type: application/pgp-signature

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2

iQIcBAEBAgAGBQJU517IAAoJEPU2Bp2uRE+g15sP/05fcAfpP+VsaKqg9OTshkKo
xidaFOQ28OMSnmNifPWMzRGtrG8+qwgl6TSYKE+fqxlmMe/rdA7A5U5P1vd0+lFH
HraKCL90NQSkqocM2NlsebrglbGM/UUANSx59RVUae4zho2/Wk+Oc2GpNX5OMw8P
1wPUK3RQ1P9Nk/0aK4SgAKGcR+es/OlBmtdm4pzl5keDJwyg4uFobYKqaEM11MSW
yTbLZl+fby04B/ww8wNHC586iUUpPmjmSkNLIHJyq7V2Gb8/dJDGkOHEPf1Oi9dw
VXq0C1qKBc2VljAqLOI68JZWo9O4YuAPaj9kQRI5xNCWs3qcohaAiE97Egr/3Co/
XNYPqFYy7GvgpLKoeSvwO5LfX6wfx2a/PMd4V3FCvn9SAHKdb3voLJwRccj4n3Yc
U9Y8wt3HvKwEJYIC0PIxqvfKSmx8nCw+ID1qOaRnPeSg06cZLZOwNZPPJ7eQBIzq
SH4izdG+72F+DJcRWk0XajfPiInUn2qDcJNaC0d6G3VkQPMVMlHyJps292dubHnS
xrE0b5LQv72JY/dcVM2MxFodRBUGvtfwFAE7onDKeAE5qkRLjev3tOxgNZQd+ZOL
ERaFxq8eryfU5GZa2g8m+ZaJA2JtK8Y3AjbLG/IMq/ynJgn6ijaiIS0ZCHgcNJSi
v5ysLn4/h3gpy684jYbX
=N0sD
-----END PGP SIGNATURE-----

--6pjpgtPchv3bUQQn--