X-Recipient: archive-cygwin AT delorie DOT com
X-Spam-Check-By: sourceware.org
Date: Fri, 9 Jan 2009 13:48:15 +0100
From: Corinna Vinschen <corinna-cygwin AT cygwin DOT com>
To: cygwin AT cygwin DOT com
Subject: Re: SSH V.5.1 with Cygwin1.dll 1.7.0(0.189/5/3) 2008-12-09: Very 	large  logon times...
Message-ID: <20090109124815.GB400@calimero.vinschen.de>
Reply-To: cygwin AT cygwin DOT com
Mail-Followup-To: cygwin AT cygwin DOT com
References: <OFB9B7CEEA DOT 015F9FE3-ONC1257520 DOT 003D6956-C1257520 DOT 003D749A AT nbg DOT sdv DOT spb DOT de> <20081215135047 DOT GU32197 AT calimero DOT vinschen DOT de> <OF9DDDB5A1 DOT 3FF00E83-ONC1257520 DOT 004F6858-C1257520 DOT 005163AC AT nbg DOT sdv DOT spb DOT de> <20081215161824 DOT GA6830 AT calimero DOT vinschen DOT de> <OF6D20C83E DOT 49D8B517-ONC1257521 DOT 002CB578-C1257521 DOT 002F8773 AT nbg DOT sdv DOT spb DOT de> <20081216100805 DOT GB15438 AT calimero DOT vinschen DOT de> <OF5B291560 DOT 62E11A59-ONC1257537 DOT 00348EA0-C1257537 DOT 003725B7 AT nbg DOT sdv DOT spb DOT de>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <OF5B291560.62E11A59-ONC1257537.00348EA0-C1257537.003725B7@nbg.sdv.spb.de>
User-Agent: Mutt/1.5.17 (2007-11-01)
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 Jan  7 11:02, Carsten DOT Porzler AT spb DOT de wrote:
> I just compiled the cygwin sources from the latest snapshot for testing. 
> It seems to be working...
> 
> So, please tell me the debugging statements I have to insert into the 
> source code to figure out where the logon process takes the time.

The idea is to add statements along these lines

  debug_printf ("CHECKPOINT 1");
  debug_printf ("CHECKPOINT 2");
  debug_printf ("CHECKPOINT 3");
  [...]

liberally across the functions in the winsup/cygwin/sec_auth.cc file,
with the starting point being the function lsaauth(), line 912 in recent
sources, so that we can track down where exactly the time is wasted.
After you added these statements all over the place, stop sshd, install
this new DLL and then, before starting sshd again, tweak the following
registry entries:

  HKLM\SYSTEM\CurrentControlSet\Services\sshd\Parameters

  AppPath  ==>  "/bin/strace"
  AppArgs  ==>  "-o C:/sshd-strace.out /usr/sbin/sshd -d"

Note the old entries before so you can restore them afterwards.

Now log in exactly once and log out again.  Afterwards, the sshd process
will have stopped automatically (that's what the lowercase -d does).
Note that it takes *much* longer to login when running under strace.  Be
(even more) patient.

After each run, examine the CHECKPOINTs in the C:/sshd-strace.out file.
The left two columns show times in milliseconds which denotes the time
it took to get to this statement, relative to the last debug output and
relative to the process start.  At one point you will see that these
numbers between two CHECKPOINTs are unusual high.  That means, the
culprit of the delay is somewhere between these two CHECKPOINTs.  Now
let's play stepwise refinement and add more of these CHECKPOINTs between
the other two and reiterate the steps above, until you think you nailed
it down to a certain part of the DLL, or even a single Windows function
call.

For a start, add these, relative to the current code in CVS:

  syscalls.cc, line 2616:

    debug_printf ("CHECKPOINT 9999");

  sec_auth.cc, line 945:

    debug_printf ("CHECKPOINT 0");

  sec_auth.cc, line 1177:

    debug_printf ("CHECKPOINT 9998");

I assume the delay occurs either when trying to get the logon server
information (function get_logon_server, line 180), or when connecting
the logon server to fetch group information (function get_user_groups,
line 225 and function get_user_local_groups, line 313), so it might be a
good idea to add more CHECKPOINTs there.

When you think you found it, I'll take another look into it and
hopefully this can be fixed easily.


HTH,
Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Project Co-Leader          cygwin AT cygwin DOT com
Red Hat

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