On Thu, 11 Nov 2010, Mark Riordan wrote:
> Last time, as I mentioned, uploads were quite slow regardless
> of whether logging was turned on.
> Now uploads are faster - 20 times faster - when logging
> is turned on than when logging is disabled!
Which also implies that something is seriously broken somwhere.
> For that reason, I didn't bother trying to speed up the logging. With the
> OS buffering writes to disk, I don't think it would have made much of a
> difference anyway.
I agree with that reasoning.
> Without logging turned on, the process uses about 100% of the CPU even
> though through is about 0.03 MB/sec (compared with about 6 MB/sec expected
> throughput).
That sounds like a busy-loop somewhere. When I do my tests on localhost, I
tend to look at the CPU-meter as a good judge of how well it performs. libssh2
1.2.7 used the CPU much less then than what curren git does, simply due to the
much higher throughput I get now.
BTW, that expected throughput, is that what you get when you upload to the
same server from the same machine using OpenSSH's or putty's sftp?
0.03 MB/sec is shockingly slow, but 0.7 MB/sec is not much better...
> I have a feeling that a lot of retransmitting is still going on. mitm-ssh
> reports a massive amount of retransmitting, but I think it's somehow making
> things worse. The above timings, and below log files, were directly to the
> SSH server.
>
> I did use Wireshark on one of the uploads. I processed the Wireshark dump
> with a script I wrote, and it indicated that 30517591 bytes were sent for
> the upload of a 120000-byte file. Granted, there is some overhead to SSH,
> but not that much overhead.
I checked your 'DebugFast.log' file. It shows:
$ grep "libssh2_transport_write send" DebugFast.log | tr -d '()' | awk
'{a+=$4} END {print a}'
541192
Judging from the log, it was a file with "Line 1" to "Line 40000" with CRLF
newlines. That makes it a 468894 byte file.
I'd say it looks about right. Also, it is interesting to see that your 32500
byte buffer perfectly consistently ends up as send() calls using the sizes
4292 bytes eight times and then a 644 bytes send() and then it loops again
until end of file.
I cannot explain where that extra data comes from that you see. libssh2
doesn't seem to log any, and I'm quite sure it logs all data it sends. In the
40000 lines case, how much does your script count?
> From a run without tracing turned on (and therefore a run which
> counter-intuitively was very slow) I have this much larger Wireshark
> capture, presumably showing a lot of retransmissions (though encrypted, of
> course): NoDebugSlow2010-11-11.zip
Right, we can't detect any retransmissions in the SSH layer there but as we
don't see any in the logging case I don't think they come from there in the
non-log case either.
When viewing that PCAP file with a column for delta time, it is obvious that
the longest times between packets are always when the server is supposed to
ACK a packet. Check out for example from number 11527 and onwards. All packets
have less than 100 us between them, and every time the server is about to ACK
a TCP seq, it takes 300+ us and then it doesn't send any data but only sends
an empty ACK.
If you send an SFTP file using another client, do the inter-packet timings
look the same? What transfers speeds do other clients get between these two
hosts?
-- / daniel.haxx.se _______________________________________________ libssh2-devel http://cool.haxx.se/cgi-bin/mailman/listinfo/libssh2-develReceived on 2010-11-12