codehosting connection time is load dependent

I'm attaching the script I was using for load testing. It basically does:
  echo hello | ssh $HOST bzr serve --inet --directory=/ --allow-writes

In as many parallel processes as you ask it to. (by using --load=$X,)

On 17 December 2010 03:31, John A Meinel <email address hidden> wrote:
> Public bug reported:
>
> It appears that the twisted SSH server takes significantly longer to ssh
> handshake when there are multiple simultaneous requests.
>
> I don't fully understand what is going on here, but I'll give the
> symptoms.

Given that this is twisted code, this sounds to me a lot like it's
doing some kind of blocking operation inline.

--
Martin

What Martin said. My first guess is that Conch is almost certainly doing all the crypto in the same thread that runs the event loop, so if that takes non-negligible time then it will delay processing of the next connection. Some profiling of that code will probably find the culprit fairly easily.

I can rule out one possibility: I'm fairly sure that the XML-RPC call to the Launchpad database for SSH keys for that username is not blocking in that code; at least it wasn't when I wrote it :)

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 12/19/2010 7:45 PM, Andrew Bennetts wrote:
> What Martin said. My first guess is that Conch is almost certainly
> doing all the crypto in the same thread that runs the event loop, so if
> that takes non-negligible time then it will delay processing of the next
> connection. Some profiling of that code will probably find the culprit
> fairly easily.
>
> I can rule out one possibility: I'm fairly sure that the XML-RPC call to
> the Launchpad database for SSH keys for that username is not blocking in
> that code; at least it wasn't when I wrote it :)
>

How do you profile the twisted server, though?

John
=:->

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAk0iQZEACgkQJdeBCYSNAAMvggCgw9iobknbf9tHpKe/aHgzaQRN
388AnR/6lHRb9ccMMwkXgTSulEEgJoyN
=lGs1
-----END PGP SIGNATURE-----

Andrew may know a better way but I would just use a poor man's profiler:

Look at whether the server is spending its time in user space or in
system calls (and if so, which system call.) If spiv's guess is right
and it's doing too much blocking crypto work, it will be in userspace.
 Then we could use strace or gdb attachment to narrow it down.

John A Meinel wrote:
[...]
> How do you profile the twisted server, though?

It's just Python, which you know how to profile, so I guess you're
specifically asking how to profile something run via twistd(1)? Add
--profile=profile.stats (and maybe --profiler=cprofiler) to the twistd
invocation.

(If you're invoking reactor.run() directly for some reason, then
obviously you can just use the usual profiling APIs.)

Also, you could rig the process to enable/disable profiling when poked
by a signal or similar, regardless of how it was started. I think
something like this would work, but I haven't tested:

import cProfile, signal
profile = cProfile.Profile()
profiling = False
def toggle_profiler(*ignored):
    global profiling
    if not profiling:
       profile.enable()
    else:
       profile.disable()
       profile.dump_stats('/tmp/profile.stats')
signal.signal(signal.SIGUSR1, toggle_profiler)

Also, along the lines of Martin's suggestion, I'd expect “perf record
twistd ...” followed by “perf report” would probably show if a
significant proportion of the time is spent in crypto libraries, generic
Python, or something else entirely. (Conch uses PyCrypto, which should
be doing the hard work in C functions, unless somehow the packaging is
broken, which seems unlikely.)

Andrew and I poked at this a bit, and found that installing python-gmpy is actually a good way to reduce startup overhead. (publickey crypto does a lot of large-integer math, and gmpy is about 6x faster than python's builtin pow())

It also turns out that the perceived scaling isn't as bad on production as it is on the other machines I tested. Specifically, on my local single-cpu instance:

--load=1
time 0.28s

--load=10
time 2.80s

(or about linear scaling)

On qa-staging I also see
5.4s => 13.5s

going from a load of 1 to a load of 10. So a 2.5x scaling for a 10x load factor.

On production, though, I see:
3.0s => 4.0s

So a 25% increase at a 10x load factor.

My guess is that some of the scaling is just being CPU bound on my local machine. So the fact that bazaar.launchpad.net has better and more CPUs means it can finish one of the connections fast enough to avoid it affecting another connection.

Note that the load dependence is also much more apparent when the lp-forking-service is active, because the total time to run becomes much lower. So a 1s overhead is a much larger fraction of total time.