Menu

#662 Efficiency loss in 7.16.2

closed-fixed
http (206)
8
2014-08-19
2007-06-20
No

When using config files with lots of URLs (I tested with ~230), cURL seems to be much less efficient since 7.15.5.

Previous version that worked OK:
curl 7.15.5 (i386-pc-win32) libcurl/7.15.5 OpenSSL/0.9.7g zlib/1.2.3
Protocols: tftp ftp telnet dict ldap http file https ftps
Features: Largefile NTLM SSL libz

Current version showing signs of inefficiency:
curl 7.16.2 (i586-pc-mingw32msvc) libcurl/7.16.2 OpenSSL/0.9.7g zlib/1.2.2
Protocols: tftp ftp telnet dict ldap http file https ftps
Features: Largefile NTLM SSL SSPI libz

Config file contents:
--globoff
--url http://192.168.1.1:8080/index.htm
<repeat --url many times>

Using 7.15.5 it took 4 seconds to dispatch 235 HTTP requests to a local HTTP server, using 0.54 seconds of CPU time.

7.16.2 took 30 seconds and 18.8 seconds of CPU time with the same list of URLs.

I found this as I use cURL to dispatch large lists of URLs to a local HTTP filtering proxy, and noticed that using 7.16.2 the request speed gets progressively slower.

Discussion

  • Daniel Stenberg

    Daniel Stenberg - 2007-06-20

    Logged In: YES
    user_id=1110
    Originator: NO

    30 seconds sounds excessive indeed. Did you try -v or --trace-ascii togetether with --trace-time to see if you can detect what might differ?

    I've not seen anyone else report this and I don't know of anything in particular that would explain this.

     
  • Anonymous

    Anonymous - 2007-06-20

    Logged In: YES
    user_id=1611181
    Originator: YES

    Taking times from each quarter-way though the log files it's evident the newer version is taking cumulatively longer as time goes on. I've done these tests on my laptop which is a different OS (Windows XP Pro vs 2000) and machine, so it seems to rule out the set-up of my desktop machine.
    File Added: cURL fetch stats2.txt

     
  • Anonymous

    Anonymous - 2007-06-20

    Stats on log timings

     
  • Anonymous

    Anonymous - 2007-06-20

    Logged In: YES
    user_id=1611181
    Originator: YES

    File Added: tracelogs.zip

     
  • Anonymous

    Anonymous - 2007-06-20

    Log files from both sessions

     
  • Daniel Stenberg

    Daniel Stenberg - 2007-06-20

    Logged In: YES
    user_id=1110
    Originator: NO

    I can confirm it and repeat it with the current CVS...

    I wrote up two perl scripts for this. The first one (stamdiff.pl) is good to show relative times in the log:

    #!/usr/bin/perl

    while(<STDIN>) {
    if(/^(\d\d):(\d\d):(\d\d)\.(\d\d\d\d\d\d) (.*)/) {
    my ($h, $m, $s, $ms, $rest)=($1, $2, $3, $4, $5);
    my $now = $h*3600 + $m+60 + $s + $ms/1000000;

    printf "REL: %.3f %s\n", $now-$prev, $rest;

    $prev = $now;
    }
    else {
    print $_;
    }
    }

    And the other for running a test with 500 URLs:

    #!/usr/bin/perl

    $a = sprintf "localhost " x 500;
    print "$a\n";

    system("curl --trace-time --trace-ascii dump $a");

    Then, after having run the script we can see the increasing delta-times with this simple grep:

    ./stampdiff.pl < dump | grep Re-using

    Using your dumps as input also shows that a fine relative time should be very small, 0 or 1 millisecond, while the more recent curl versions start there and then just increase over time...

     
  • Daniel Stenberg

    Daniel Stenberg - 2007-06-20
    • priority: 5 --> 8
     
  • Daniel Stenberg

    Daniel Stenberg - 2007-06-20

    Logged In: YES
    user_id=1110
    Originator: NO

    Thanks for the report, this was now found and is fixed in CVS.

     
  • Daniel Stenberg

    Daniel Stenberg - 2007-06-20
    • status: open --> closed-fixed