Abysmal performance of Net::SFTP (and I have GMP & Pari)

[usenet]

Greetings.

I am having terrible problems with very poor performance when using
Net::SFTP. Specifically, it takes about 10 seconds for a machine to
transfer a 1 MB file to itself (localhost), and this is a brand new,
very FAST, lightly loaded server (and I can replicate this problem on
other machines as well). Using ordinary FTP takes 0.4 seconds, and
doing the same thing with commandline sftp completes the task in the
blink of an eye.

I ***DO*** have Math::GMP::BigInt installed (as well as
Math:ari::BigInt), and a diagnostic dump of %INC indicates these are
being called (see below). Enabling SFTP debug mode shows that I am not
experiencing any long pauses (ie, I get a handle in 0.8 seconds, and
transfers occur at a steady - though slow - pace without any pauses).

It is doubtful that I have the option to use Net::SSH2 (because the
servers do not have libssh2 and I probably won't be able to do anything
about that). I really need to figure out why Net::SFTP is behaving so
poorly. I really appreciate any insight anyone can offer.

Here is my test script:

#!/usr/bin/perl
use strict; use warnings;
use Net::SFTP;

#Create with: dd if=/dev/urandom of=/tmp/1mb.junk bs=1024 count=1024
my $testfile = "/tmp/1mb.junk";

my %comm = (
user => 'myuserid',
password => 'mypassword',
ssh_args => [ cipher => 'blowfish-cbc' ],
debug => 0,
);

my $sftp = Net::SFTP->new('localhost', %comm) or die "oops: $@";

$sftp->put ($testfile, "$testfile.test")
or die("ftp put failed ", $sftp->message);

END{
print map{"$_\n"} sort keys %INC; #check for GMP/Pari
}

__END__


The blowfish cipher is indeed the "fastest" (as the docs indicate). I
tried the other available ciphers with inferior results:
arcfour 14 seconds
3des-cbc 22 seconds


The "interesting" parts of the %INC dump (in the END block of the test
script) look like this (and validate that GMP/Pari are being called):

Convert/ASN1 MIME/Base64
Convert/ASN1/IO Math/BigInt
Convert/ASN1/_decode Math/BigInt/GMP
Convert/ASN1/_encode Math/GMP
Convert/ASN1/parser Math/Pari
Convert/PEM Net/SFTP
Convert/PEM/CBC Net/SFTP/Attributes
Convert/PEM/ErrorHandler Net/SFTP/Buffer
Crypt/Blowfish Net/SFTP/Constants
Crypt/DH Net/SFTP/Util
Crypt/DSA Net/SSH/Perl
Crypt/DSA/Key Net/SSH/Perl/Agent
Crypt/DSA/Key/PEM Net/SSH/Perl/Auth
Crypt/DSA/KeyChain Net/SSH/Perl/Auth/Password
Crypt/DSA/Signature Net/SSH/Perl/Auth/PublicKey
Crypt/DSA/Util Net/SSH/Perl/AuthMgr
Crypt/Random Net/SSH/Perl/Buffer
Crypt/Random/Generator Net/SSH/Perl/Channel
Crypt/Random/Provider/File Net/SSH/Perl/ChannelMgr
Crypt/Random/Provider/devurandom Net/SSH/Perl/Cipher
Digest/HMAC Net/SSH/Perl/Cipher/Blowfish
Digest/HMAC_MD5 Net/SSH/Perl/Cipher/CBC
Digest/HMAC_SHA1 Net/SSH/Perl/Comp
Digest/MD5 Net/SSH/Perl/Config
Digest/SHA1 Net/SSH/Perl/Constants
Digest/base Net/SSH/Perl/Kex
Encode Net/SSH/Perl/Kex/DH1
Encode/Alias Net/SSH/Perl/Key
Encode/Config Net/SSH/Perl/Key/DSA
Encode/Encoding Net/SSH/Perl/Mac
Fcntl Net/SSH/Perl/Packet
IO Net/SSH/Perl/SSH2
IO/Handle Net/SSH/Perl/Util
IO/Select Net/SSH/Perl/Util/Hosts
IO/Socket Net/SSH/Perl/Util/SSH2MP
IO/Socket/INET Net/SSH/Perl/Util/Term
IO/Socket/UNIX


I ran the script thorough Devel:rofile (perl -drofile test.pl); the
top results (> 1.0%) are:

time elapsed (wall): 12.8377
time running program: 9.6744 (75.36%)
time profiling (est.): 3.1633 (24.64%)
number of calls: 361634
number of exceptions: 11

%Time Sec. #calls sec/call name
28.05 2.714 131970 0.000021 Crypt::Blowfish::encrypt
23.32 2.256 139 0.016228 Net::SSH:erl::Cipher::CBC::encrypt
10.08 0.975 282 0.003458 IO::Select::select
5.53 0.535 32 0.016733 IO::Select::can_read
4.51 0.437 132840 0.000003 Crypt::Blowfish::crypt
2.78 0.269 59 0.004553 Net::SSH:erl::Util::SSH2MP::bin2mp
2.52 0.244 144 0.001693 Net::SSH:erl::Util::SSH2MP::mp2bin
1.47 0.142 1035 0.000137 Net::SSH:erl::Buffer::new
1.25 0.121 449 0.000269 Net::SSH:erl:acket::read_poll_ssh2
1.12 0.109 1041 0.000104 Net::SSH:erl::Util::import

So the machine is definitely spending most of its time with the crypto
stuff (not I/O stuff), which is to be expected, but it is taking a LONG
time to do the crypto stuff.

I know that Math::BigInt::GMP (or Pari) is very important for SFTP
performance. But I have both libraries and their BigInt modules
installed. Is there ANOTHER math module that I need???

I'm happy to entertain any "try this and see what happens" ideas.

Thanks!

 

[zentara]

So the machine is definitely spending most of its time with the crypto
stuff (not I/O stuff), which is to be expected, but it is taking a LONG
time to do the crypto stuff.

I know that Math::BigInt::GMP (or Pari) is very important for SFTP
performance. But I have both libraries and their BigInt modules
installed. Is there ANOTHER math module that I need???

Did you rebuild the Net::SFTP and the Net::SSH:erl module
after you installed the Math modules? And I mean rebuild them
from scratch, not just install some premade package?

When things don't work, usually the best bet is to upgrade to
the latest versions of all modules, and Perl version, AND build
them yourself so you can see any warnings.

 

[Sisyphus]

..
..

I ***DO*** have Math::GMP::BigInt installed (as well as
Math:ari::BigInt), and a diagnostic dump of %INC indicates these are
being called (see below).

I would still entertain the possibility that Math::BigInt is being called
somehow. To check that's *not* the case I would rename Math/BigInt.pm to
(eg) Math/BigInt_hide.pm, re-run the script and see if performance improves.
If it makes no difference then we can assume that Math::BigInt is *not* to
blame - but if either the script croaks, or it runs significantly faster,
then there's your culprit.

I note that Math::BigInt *is* listed in %INC .... hence my suspicions about
it.

Cheers,
Rob

 

[usenet]

I would still entertain the possibility that Math::BigInt is being called
somehow. To check that's *not* the case I would rename Math/BigInt.pm to
(eg) Math/BigInt_hide.pm, re-run the script and see if performance improves.

Thanks for the suggestion, Rob (I was hoping you would notice and reply
to this thread; you've been very helpful to me on other SSH-ish issues,
and I've been grateful for your help).

I tried your suggestion and the test program blew up with:

Can't locate Math/BigInt.pm in @INC ... Crypt/DH.pm line 6

and further complained:

Compilation failed in require .../Net/SSH/Perl/Kex/DH1.pm line 13.
Compilation failed in require .../Net/SSH/Perl/Kex.pm line 6.
Compilation failed in require .../Net/SSH/Perl/SSH2.pm line 6.
Compilation failed in require .../Net/SSH/Perl.pm line 54.

Line 6 of Crypt:H (version 0.06) says:
use Math::BigInt lib => "GMP,Pari";

which looks OK to me and would seem to account for the Math::BigInt
call in %INC (but, hey, what do I know?). FWIW, I tried to take GMP
out (leaving only Pari) but it made no noticeable difference.

 

[Sisyphus]

..
..

improves.

I tried your suggestion and the test program blew up with:

Can't locate Math/BigInt.pm in @INC ... Crypt/DH.pm line 6

Same culprit as last time.

Line 6 of Crypt:H (version 0.06) says:
use Math::BigInt lib => "GMP,Pari";

Yes ... that's what it says alright .... but I sort of expected it should
be:

use Math::BigInt lib => "GMP","Pari";

I could be wrong about that.

You have Math::BigInt::GMP, so just change the above line to:

use Math::BigInt lib => "GMP";

I'm assuming that Math::BigInt::GMP is fully functional ... ??

Cheers,
Rob

 

[salva]

Greetings.

I am having terrible problems with very poor performance when using
Net::SFTP. Specifically, it takes about 10 seconds for a machine to
transfer a 1 MB file to itself (localhost), and this is a brand new,
very FAST, lightly loaded server (and I can replicate this problem on
other machines as well). Using ordinary FTP takes 0.4 seconds, and
doing the same thing with commandline sftp completes the task in the
blink of an eye.

have you tried Net::SFTP::Foreign? it is much faster, similar to the
sftp command.

Cheers,

- Salva

 

[Ben Morrow]

.
.

Same culprit as last time.

This I would not expect to work, as Math::BigInt loads the various
libraries for you. You could try moving Math::BigInt::Calc out of the
way, though.

The next version of Math::BigInt is supposed to let you insist on
loading a specific library (see
http://groups.google.co.uk/group/perl.perl5.porters/browse_frm/
thread/7eda1c02e4a92be/ee2a9bbb4e5a160d
(URL broken)).

Ben

 

[Sisyphus]

This I would not expect to work, as Math::BigInt loads the various
libraries for you.

Doh ... you're right. Crypt/DH.pm will inevitably try to load Math::BigInt -
which doesn't necessarily mean that the slow Math::BigInt pure perl routines
will be used.

You could try moving Math::BigInt::Calc out of the
way, though.

Much smarter idea .... might actually test out what I was intending to test


The absence of Math::BigInt::Calc in the op's listing of %INC would suggest
that the slow Math::BigInt pure perl routines are *not* to blame in this
instance, after all.

Cheers,
Rob

 

[xhoster]

Here is my test script:

#!/usr/bin/perl
use strict; use warnings;
use Net::SFTP;

#Create with: dd if=/dev/urandom of=/tmp/1mb.junk bs=1024 count=1024
my $testfile = "/tmp/1mb.junk";

my %comm = (
user => 'myuserid',
password => 'mypassword',
ssh_args => [ cipher => 'blowfish-cbc' ],
debug => 0,
);

my $sftp = Net::SFTP->new('localhost', %comm) or die "oops: $@";

$sftp->put ($testfile, "$testfile.test")
or die("ftp put failed ", $sftp->message);

END{
print map{"$_\n"} sort keys %INC; #check for GMP/Pari
}

__END__

The blowfish cipher is indeed the "fastest" (as the docs indicate). I
tried the other available ciphers with inferior results:
arcfour 14 seconds
3des-cbc 22 seconds

The "interesting" parts of the %INC dump (in the END block of the test
script) look like this (and validate that GMP/Pari are being called):

So it appears that GMP/Pari are installed, but from the profile it appears
they aren't doing anything.

I ran the script thorough Devel:rofile (perl -drofile test.pl); the
top results (> 1.0%) are:

Can you get Profile to give you *all* of the subs and look through that
for GMP/Pari calls?

%Time Sec. #calls sec/call name
28.05 2.714 131970 0.000021 Crypt::Blowfish::encrypt
23.32 2.256 139 0.016228 Net::SSH:erl::Cipher::CBC::encrypt
10.08 0.975 282 0.003458 IO::Select::select
5.53 0.535 32 0.016733 IO::Select::can_read
4.51 0.437 132840 0.000003 Crypt::Blowfish::crypt

Crypt::Blowfish::encrypt doesn't do anything other than rearrange
it's args and pass them on to the XS code Crypt::Blowfish::crypt.
Yet it takes over 6 times longer than the code that does the real
work? My gut feeling is that the bottleneck here is simply the fact
that you make 2 function calls for every 8 bytes to be encrypted.

I don't see how this could be possibly be fast. Could someone who *does*
find this to be fast on their machines please DProf this example and
post the results?

I'm happy to entertain any "try this and see what happens" ideas.

The first two things I'd try, would be to use DProf rather than Profile,
and see if you get similar results. And to "strace" the run (I think you
are on Linux, right?), and see if anything pops out that way.

Xho