Hi, Lisa
Thanks for taking a look at this. Some comments
On 24 Jul, 2006, at 12:46, Lisa Dusseault wrote:
I wanted to take a look at the performance of sharing. I started
from "the bottom", looking at TCP and SSL connection
characteristics before looking at WebDAV usage patterns or
performance within either the client or server codebase. Since I
had a May 21 version of Chandler handy I used it from home, talking
to cosmo-demo, and some random data (22 events). I captured the
Chandler "Publish" interaction only.
The publish took five minutes. Ekr helped analyze the trace with
[[http://www.rtfm.com/ssldump/][SSLDump]] (you can use it too, it's
under BSD license).
The summary is that there are a bunch of TCP/SSL issues to
investigate on the Chandler side first.
1) There are 7 separate SSL connections during Publish. Only 1
should really be needed. An ignorant guess is we'd be using
PyOpenSSL classes in different places, instantiating new and
separate objects rather than passing one around (or looking one up)
to handle the sharing traffic.
1 extra connection occurs because Chandler uses separate connections
for the CalDAV (all the .ics files) & Chandler-specific
(the .chandler subdirectory) shares. This isn't necessary, and also
adds roundtrips because we're not using information learned earlier
(like, the fact that .chandler/ exists).
2 more result from the fact that, on some valid requests, Cosmo
returns a 501 and closes the connection. This currently covered by
bug 5340 (though 6048 is the specific case you saw). The others all
appear to be cases where the client thinks the server has closed the
connection (the twisted.log entries about
"twisted.internet.error.ConnectionDone: Connection was closed
cleanly."). I'm not sure what exactly is going on there.
2) Even within one SSL connection, traffic is slow. Between
establishing the TCP connection and starting the SSL handshake, the
log shows a 0.5 second delay. The handshake takes another 0.2
second. The actual transaction takes only 0.1 seconds.
3) There's something weird going on with the connection that
starts at 9:35:15 in the trace. After opening the connection, it's
two minutes before the client sends any data. This is rather
aberrant.
It is weird. From what I can tell, Chandler is writing the data as
soon as it finds out that the connection succeeded: I'm not sure
where the delay is coming from (I certainly don't see it using
openssl from the command line).
4) The client hung up on one of its own connections, the same one
where it delays 2 minutes. Why?
I'm not sure I understand the ssldump output correctly (in
particularly, the timestamps), but it looks as if very soon after
sending the TLS handshake, the client tried to close the connection.
I'm wondering if M2Crypto (the TLS implementation) and twisted (TCP)
aren't in some way out of sync with one another w.r.t. the state of
the connection.
--Grant
More details, raw tcpdump file, tcpdump text output, ssldump text
output, chandler.log and twisted.log are all attached to the Wiki:
http://wiki.osafoundation.org/bin/view/Journal/
PublishConnectionAnalysis
I hope this is useful to developers, even though the older version
of Chandler and working from home may make the data a little
rough. I'll be in the office tomorrow and online today if anybody
wants to discuss.
Lisa
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
Open Source Applications Foundation "chandler-dev" mailing list
http://lists.osafoundation.org/mailman/listinfo/chandler-dev
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
Open Source Applications Foundation "chandler-dev" mailing list
http://lists.osafoundation.org/mailman/listinfo/chandler-dev
