#1183 curl FTP upload performance degration version 7.28.1

[Daniel Theron]

Hi There,

I am in the process upgrading curl from version 7.19.6 to version 7.28.1 on our Solaris 10 servers. I have written a unix script to do file upload tests with ftp & sftp, and with different file types like binary and ascii (dos and unix).

With the script I noticed ftp uploads take about 2 to 3 times longer with version 7.28.1 compared to 7.19.6. sftp upload speeds seems to be ok.

Here is the technical details:
$ uname -a
SunOS M3000-dev-1 5.10 Generic_147440-25 sun4u sparc SUNW,SPARC-Enterprise

CURL latest version - slow with ftp uploads
$ curl --version
curl 7.28.1 (sparc-sun-solaris2.10) libcurl/7.28.1 OpenSSL/1.0.1c zlib/1.2.7 libidn/1.25 libssh2/1.4.3
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp scp sftp smtp smtps telnet tftp
Features: IDN IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP

CURL older version - fast ftp upload speeds
$ curl --version
curl 7.19.6 (sparc-sun-solaris2.10) libcurl/7.19.6 OpenSSL/0.9.8x zlib/1.2.7 libidn/1.25 libssh2/1.4.3
Protocols: tftp ftp telnet dict http file https ftps scp sftp
Features: IDN IPv6 Largefile NTLM SSL libz

I will attach the script, it uploads 3x 250K binary files with sftp&ftp, 3x 25K ascii (dos & unix) with sftp&ftp

Let me know if you need more info

Thanks,
Daniel

[Daniel Stenberg]

On Thu, 17 Jan 2013, Daniel Theron wrote:

I am in the process upgrading curl from version 7.19.6 to version 7.28.1 on
our Solaris 10 servers. I have written a unix script to do file upload tests
with ftp & sftp, and with different file types like binary and ascii (dos
and unix).

With the script I noticed ftp uploads take about 2 to 3 times longer with
version 7.28.1 compared to 7.19.6. sftp upload speeds seems to be ok.

Wow. How big transfer are you trying with? Does using --trace and --trace-time
help you identify a specific part that runs slowly?

Does a -v run using both reveal any differences in how the transfers are being
made, ftp command wise?

--

/ daniel.haxx.se

[Daniel Theron]

Hi Daniel,

To sum it up in short, the one part of the test case uploads(ftp) 3 files using one connection to the ftp server. (Not one connection per file). All 3 files are 25KB in size.

I have run the trace and I determined 7.28.1 does a double "Checking for server connect", there is a second delay between the 2x "Checking for server connect" - this occurs for every file transferred.
11:45:51.050153 > STOR ascii_unix_file3
11:45:51.052122 < 150 File OK.
11:45:51.052376 * Preparing for accepting server on data port
11:45:51.052547 * Checking for server connect
11:45:52.052794 * Checking for server connect
11:45:52.053068 * Ready to accept data connection from server

See attached for full trace for both 7.19.6 and 7.28.1

Thanks,
Daniel

[Daniel Stenberg]

Hm, but surely you then see this for downloads as well?

And secondly, would it be possible for you to get a recent git version/daily snapshot to see if this still behaves this way?

[Daniel Stenberg]

I've seen this reported by other sources as well. I think it is about time we start to bisect down to when exactly this degradation started so that we can get a better understanding of it.

It is either that or some detailed profiling of where the time is wasted...

[Daniel Theron]

Hi Daniel,

I have tested downloading multiple files and the same 1 second pause occur per file.

I think I have found where the bug resides (by using curl v7.28.1).
Here is the command & parameters I have used:
curl --connect-timeout 10 -B --retry 3 --retry-max-time 6 --ftp-port - --crlf -# -T "{ascii_unix_file1,ascii_unix_file2,ascii_unix_file3}" -u athed:Helpme12 ftp://172.21.2.232/test_case_dir/
This will pause 1 second per file when uploading. (but with v7.29.1-20130302 snapshot it will hang then error curl: (25) Failed FTP upload: 451)

But when removing the "--ftp-port -" parameters, it uploads each file without doing a 1 second pause per file. (v7.28.1 & v7.29.1-20130302)

I have tested the previous versions of curl and finally got to the version where this bug came in: 7.24.0

Hope you can find the bug easily now :)

Thanks
Daniel

[Daniel Stenberg]

Can you run the command line with "--trace-ascii trace.txt --trace-time" and attach such a trace log here? (edit out sensitive data before you do) I'd like to see where that second is lost.

If you can include a log for the "it will hang then error curl: (25) Failed FTP upload: 451" it'll be good too as I take it you're saying that a current dev version of curl fails on your command line that worked before?

[Daniel Theron]

Hi Daniel,

Please find trace logs attached. I added some comments and the command I have run in the trace log as well.

Test cases:
v7.28.1 with "--ftp-port - --crlf"
v7.28.1 without "--ftp-port - --crlf"
v7.29.1-20130302 with "--ftp-port - --crlf"
v7.29.1-20130302 without "--ftp-port - --crlf"
v7.23.1 with "--ftp-port - --crlf" (Last curl version where "--ftp-port - --crlf" worked fine)

[Daniel Theron]

attachment

[Daniel Theron]

attachment

[Daniel Theron]

attachment

[Daniel Theron]

attachment

[Daniel Theron]

This also seems to be broken from the stable 7.29.0 release.
Tested this last week.

[Daniel Stenberg]

I can't repeat it on my linux box with curl 7.29.0

$ curl -P - --crlf -T [PNG] --trace-ascii dump --trace-time ftp://user:password@localhost/tmp/test/removeme

(I tried this with a faked added latency of 250 ms to localhost but it made no difference)

17:12:24.056400 == Info: About to connect() to localhost port 21 (#0)
17:12:24.056659 == Info: Trying 127.0.0.1...
17:12:24.556773 == Info: Connected to localhost (127.0.0.1) port 21 (#0)
17:12:25.059123 <= Recv header, 20 bytes (0x14)
0000: 220 (vsFTPd 3.0.2)
17:12:25.059200 => Send header, 13 bytes (0xd)
0000: USER user
17:12:25.559288 <= Recv header, 34 bytes (0x22)
0000: 331 Please specify the password.
17:12:25.559340 => Send header, 15 bytes (0xf)
0000: PASS password
17:12:26.226634 <= Recv header, 23 bytes (0x17)
0000: 230 Login successful.
17:12:26.226699 => Send header, 5 bytes (0x5)
0000: PWD
17:12:26.726807 <= Recv header, 20 bytes (0x14)
0000: 257 "/home/daniel"
17:12:26.726853 == Info: Entry path is '/home/daniel'
17:12:26.726883 => Send header, 9 bytes (0x9)
0000: CWD tmp
17:12:27.226992 <= Recv header, 37 bytes (0x25)
0000: 250 Directory successfully changed.
17:12:27.227045 => Send header, 10 bytes (0xa)
0000: CWD test
17:12:27.727155 <= Recv header, 37 bytes (0x25)
0000: 250 Directory successfully changed.
17:12:27.727295 => Send header, 26 bytes (0x1a)
0000: EPRT |1|127.0.0.1|52001|
17:12:28.227489 <= Recv header, 51 bytes (0x33)
0000: 200 EPRT command successful. Consider using EPSV.
17:12:28.227533 == Info: Connect data stream actively
17:12:28.227914 => Send header, 8 bytes (0x8)
0000: TYPE I
17:12:28.728030 <= Recv header, 31 bytes (0x1f)
0000: 200 Switching to Binary mode.
17:12:28.728083 => Send header, 15 bytes (0xf)
0000: STOR removeme
17:12:29.728941 <= Recv header, 22 bytes (0x16)
0000: 150 Ok to send data.
17:12:29.728982 == Info: Preparing for accepting server on data port
17:12:29.728989 == Info: Checking for server connect
17:12:29.728994 == Info: Ready to accept data connection from server
17:12:29.729019 == Info: Connection accepted from server
17:12:29.729473 => Send data, 16386 bytes (0x4002)
0000: .PNG.
0007: .
000a: ....IHDR...X...@......i......IDATx....Tz........................
004a: ................................................................
008a: ................................................................
00ca: ................................................................

[Daniel Theron]

Hi Daniel,

I used this command to do some more testing:
/usr/local/bin/curl --connect-timeout 10 -B -P - --crlf -# -T "{testfile1,testfile2,testfile3}" -u athed:Helpme12 ftp://172.21.2.232/test_case_dir/

With curl 7.29.0 I ftp'd 3 files to a solaris FTP server and worked perfectly - it transferred the 3 files without doing a 1 second pause for each file

But from 7.29.0 curl breaks when transferring files to the type of FTP Server we use. Jscape MFT Server

It still works perfectly with (7.19.6 & 7.23.1) and still works for (7.24.0 & 7.28.1) with 1 second delay bug per file sent

If you wish to see/test for yourself, I have given you access to our external jscape server. I will email the host details to you (daniel at haxx dot se)

Thanks,
Daniel

[Daniel Stenberg]

Thanks for the test account, it is very helpful. Can you check and see if the following patch fixes the problem for you? It seems to do it in my tests...

diff --git a/lib/ftp.c b/lib/ftp.c
index dec4800..f0df719 100644
--- a/lib/ftp.c
+++ b/lib/ftp.c
@@ -886,6 +886,7 @@ static int ftp_domore_getsock(struct connectdata *conn, curl

   switch(ftpc->state) {
   case FTP_STOP:

+  case FTP_STOR:
     break;
   default:
     return Curl_pp_getsock(&conn->proto.ftpc.pp, socks, numsocks);

[Daniel Theron]

Hi Daniel,

Thanks a lot.
Im trying to copy the patch but it seems the "@@ -886,6 +886,7 @@ static int ftp_domore_getsock(struct connectdata *conn, curl" line's end was cut off you posted above.

Mind attaching the ftp.c file that contains the patch?

Thanks,
Daniel

[Daniel Stenberg]

Sure, attached is the ftp.c file WITH the patch applied. I'm using the very latest git here (head is e7c56a8406d0d75 atm) so you may need to as well to use this file without problems. If you can't/doesn't want to use git, it should also work fine with a recent daily snapshot.

[Daniel Stenberg]

and here's the patch stand-alone and with a full commit message

[Daniel Theron]

Thanks Daniel! I will test and revert back next week

[Daniel Theron]

Hi Daniel,

I have tested the fix and I am happy to say that the fix is working, plus it works just like it used to prior v7.24.0 (no 1 second pause per file transferred).

Can you please commit the fix?

Thanks,
Daniel

[Daniel Stenberg]

Thanks for verifying! I've committed and pushed this change now, available in master as commit 57aeabcc1a20ff8ed.

This issue is hereby closed. Thanks!

[Daniel Theron]

Thanks again for your help! :)