s3sync performance testing: Slow Downloads

[bdixon]

Hello:

I've done some performance testing on s3sync and s3cmd. The quick summary is that relative to wget the s3sync and s3cmd "get" operations are about 5 times slower. The get operations spend about 40% of their time in userspace code which, to me, may indicate a hot spot caused by a possibly inefficient procedure.

"put" operations seem about the same speed as wget "get" operations so I didn't do additional testing on "puts".

My data:

http://spreadsheets.google.com/pub?key=pQFDXIemKG2G5YG2T-_T1eg

All testing was done between EC2 and S3 so network performance should be optimal. Files were erased between runs to ensure that the results reflected network performance and not hash matches.

Let me know if you have more questions or need other data. Maybe if I can figure out how to profile ruby code I can lend some advice or a patch.

Brad

[ferrix]

Ruby comes with tracing and debugging available, though I haven't used it too much myself.

It would certainly be helpful if we found a way to get performance boosted substantially!  I find it equally likely that the problem is within the Ruby library code somewhere, but if we can learn where we might still be able to patch around the inefficiency.

It could also be something such as the default read/write chunk size might be too small.

[lowflyinghawk]

when I GET with the ruby lib stuff set up to stream I get up to about 700KB/s, the same maximum that my ISP's speed test shows.  I watched the process while downloading a 22M test file (this is on linux).  the only time the ruby process even registered 1% of the cpu was the last second or so when calculating the etag check (which I do after the download finishes).  altogether this makes me think the ruby libraries, certainly on linux, are not likely to be the problem area.

you should be able to run the ruby profiler by
    ruby -r profile s3sync ...

notice I didn't mention PUTs?  that's because my DSL connection limits them to around 40KB/s.  for what it's worth the cpu consumption never is even visible except for when calculating the etag, but this speed is so low as to hardly be a challenge.

during the GETs the segments I'm getting back are usually 1024 or 436 bytes, but they can be other lengths.  don't ask me why, I don't control it.

[lowflyinghawk]

for what it's worth, here is the profiler output from a GET of a 22M file (I removed any calls below 1%).  remember, during a normal run without the profiler, the cpu never gets above 1% except calculating the etag, my guess is because the ruby lib just calls down to the socket library which uses hardly any cpu.  you can see the call that generates the etag down near the bottom.

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 17.33    14.13     14.13    21662     0.65     0.93  Thread#kill
 15.43    26.71     12.58    21664     0.58     1.76  Timeout.timeout
 14.19    38.28     11.57        1 11570.00 76470.00  Net::BufferedIO#read
  7.28    44.22      5.94    21661     0.27     0.39  Net::ReadAdapter#call_block
  4.84    48.17      3.95    21664     0.18     1.95  Object#timeout
  4.52    51.86      3.69    21687     0.17     0.26  Net::BufferedIO#rbuf_consume
  4.14    55.24      3.38    21662     0.16     0.16  Thread#start
  3.00    57.69      2.45        5   490.00 16106.00  IO#open
  2.53    59.75      2.06    21661     0.10     0.49  Net::ReadAdapter#<<
  2.43    61.73      1.98    21662     0.09     2.04  Net::BufferedIO#rbuf_fill
  2.32    63.62      1.89    21687     0.09     0.09  String#slice!
  2.29    65.49      1.87    21682     0.09     0.09  String#<<
  2.16    67.25      1.76    21661     0.08     0.08  Fixnum#<
  2.10    68.96      1.71    21661     0.08     0.12  IO#<<
  1.99    70.58      1.62    65010     0.02     0.02  String#size
  1.85    72.09      1.51    21676     0.07     0.10  Fixnum#==
  1.55    73.35      1.26    43469     0.03     0.03  Fixnum#+
  1.25    74.37      1.02    21662     0.05     0.05  IO#sysread
  1.16    75.32      0.95    21660     0.04     0.04  Digest::Base#<<
  1.13    76.24      0.92    21662     0.04     0.04  Kernel.sleep
  1.04    77.09      0.85    21665     0.04     0.04  IO#write

[bdixon]

you should be able to run the ruby profiler by
    ruby -r profile s3sync ...

Here is my profiling data.

100 MB PUT

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 34.61    80.95     80.95   102402     0.79     1.41  Net::BufferedIO#writing
 20.77   129.53     48.58   102402     0.47     0.62  Net::BufferedIO#write0
 14.45   163.33     33.80   153601     0.22     0.22  IO#read
  8.28   182.70     19.37   102402     0.19     1.60  Net::BufferedIO#write
  6.94   198.93     16.23        1 16233.33 208266.67  Net::HTTPGenericRequest#send_request_with_body_stream
  5.24   211.18     12.25        1 12250.00 24216.67  S3sync::LocalNode#initialize
  3.29   218.88      7.70   102404     0.08     0.08  IO#write
  3.14   226.23      7.35   102431     0.07     0.07  Fixnum#+
  1.40   229.52      3.28    51200     0.06     0.06  Digest::Base#<<
  1.26   232.47      2.95    51201     0.06     0.06  IO#eof?
  0.19   232.92      0.45      122     3.69    27.46  Kernel.require
  0.08   233.10      0.18      162     1.13     1.65  Array#each
  0.04   233.20      0.10     1941     0.05     0.05  Module#method_added
  0.04   233.30      0.10       21     4.76     7.14  REXML::Parsers::BaseParser#pull
  0.02   233.35      0.05        1    50.00   116.67  IO#each_line
  0.01   233.38      0.03        2    16.67    25.00  Net::HTTPResponse#each_response_header
  0.01   233.42      0.03        1    33.33    33.33  GC.start
  0.01   233.45      0.03       18     1.85     3.70  Hash#each
  0.01   233.47      0.02        2     8.33 104183.33  Net::HTTP#_HTTPStremaing_request

100 MB GET

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 18.08   141.62    141.62   102406     1.38     4.00  Timeout.timeout
 15.51   263.10    121.48   102405     1.19     1.90  Thread#kill
 11.84   355.80     92.70        5 18540.00 156196.67  Net::BufferedIO#read
  7.39   413.65     57.85   102405     0.56     0.56  Thread#start
  7.37   471.33     57.68   102406     0.56     4.56  Object#timeout
  5.04   510.77     39.43   102405     0.39     4.95  Net::BufferedIO#rbuf_fill
  5.00   549.95     39.18   102440     0.38     0.38  String#slice!
  4.02   581.43     31.48   102440     0.31     0.69  Net::BufferedIO#rbuf_consume
  3.87   611.77     30.33   102401     0.30     0.36  Net::ReadAdapter#call_block
  3.85   641.92     30.15   307348     0.10     0.10  String#size
  3.28   667.63     25.72   102401     0.25     0.62  Net::ReadAdapter#<<
  3.14   692.22     24.58   102445     0.24     0.24  String#<<
  1.85   706.73     14.52   102728     0.14     0.20  Fixnum#==
  1.53   718.68     11.95   204861     0.06     0.06  Fixnum#+
  1.34   729.18     10.50   102404     0.10     0.10  Kernel.sleep
  0.95   736.62      7.43   102405     0.07     0.07  IO#sysread
  0.89   743.57      6.95   102406     0.07     0.07  IO#write
  0.86   750.27      6.70   102405     0.07     0.07  Fixnum#zero?
  0.84   756.88      6.62   102405     0.06     0.06  Thread#critical
  0.82   763.28      6.40   102405     0.06     0.06  Thread#alive?
  0.77   769.30      6.02   102411     0.06     0.06  Thread#current
  0.76   775.25      5.95   102484     0.06     0.06  Fixnum#<
  0.74   781.05      5.80   102596     0.06     0.06  Kernel.==
  0.05   781.47      0.42      123     3.39    26.69  Kernel.require
  0.02   781.63      0.17      185     0.90  4229.28  Array#each
  0.02   781.78      0.15       72     2.08     5.09  REXML::Parsers::BaseParser#pull
  0.01   781.87      0.08      588     0.14     0.14  String#==
  0.01   781.93      0.07     1941     0.03     0.03  Module#method_added

[ferrix]

I don't see anything in those results that point to s3sync doing dumb looping or etc.

However both for you and for lfh's results (he is not using my software), the Thread#kill and Timeout.timeout seem to be taking over 30% of the time if I'm reading it right.

What I'm not sure of, is whether these results aggregate inner calls to the other inner functions, or whether the time is spent *just* and *only* executing code native to that function.

I would assume the former, which means this result isn't all that informative.  For example it might be spending time in "timeout" waiting for the network result to come back, etc.

I am *not* an expert in ruby by any stretch, so I'm probably not the most qualified to pursue these details.

[lowflyinghawk]

oh boy, I just love it when my login times out while writing a post...

here is a test we haven't tried: cut ruby out of the loop by downloading the same file using your browser.  there is a bit of fuzz because I have to click "save to disk" with firefox, but my time to download the link below is pretty much exactly the same as using ruby (30 seconds), which says neither my code nor the ruby libraries are likely to be doing anything stupid.

http://s3.amazonaws.com/1001/zero.bin

the file contains exactly 20,000,000 bytes and you should be able to download it for your own testing.

[bdixon]

here is a test we haven't tried: cut ruby out of the loop by downloading the same file using your browser.  there is a bit of fuzz because I have to click "save to disk" with firefox, but my time to download the link below is pretty much exactly the same as using ruby (30 seconds), which says neither my code nor the ruby libraries are likely to be doing anything stupid.

I did use a web browser as a control for the get operation. Take a look at my original data. The "wget" data uses the command line wget agent to fetch the same objects via HTTP. wget is about 6-7x faster than "s3cmd get".

Brad

[lowflyinghawk]

bdixon:  yes, I'm blind ;-).

greg: what happens when you do this?  I tried wget with the file above, and my times in ruby and wget are less than 1 second different (~29.5sec), well within the noise.  I could understand a bit of overhead, e.g. I do a HEAD call that wget doesn't and I do an extra etag check, but 6x-7x is way out of line.  platform may matter, I'm on fedora core 6, x86.

[ferrix]

I haven't tested that.  I think it's clear from the above that 1) it's something in ruby but 2) not in my code per se, and 3) it doesn't happen for everyone.

[lowflyinghawk]

not quite, from *my* tests it is clear that it is *nothing* in ruby, since ruby and wget take the same time.

however brad didn't say what platform he's running on.  you (greg) are on windows, right?  why don't you take a minute, click my link earlier, and find out how long your browser takes to get the file (I assume you don't have wget, although you could get it from http://www.christopherlewis.com/WGet/WGetFiles.htm) vs how long it takes to get it with s3sync?

brad: platform?

[ferrix]

all right all right.. it *is* the weekend, I suppose this counts as recreation ye?

[ferrix]

wget times are mostly within 43-45s
s3cmd are mostly within 46-48s

This is on Windows.  When I profile ruby here, it REALLY sucks the performance down though.. So instead I just clock timed it.

[lowflyinghawk]

right, the time when running the profiler is meaningless.  the profiler slows things down enough by itself that it could mask other issues, e.g. disk or network waits.  still, the profiler gives the raw counts which can be quite useful.

were you testing by grabbing the 20M link I provided?  if yes, then you are taking 50% or so more time than I do to get it.  my DSL connection is the bottleneck as far as I can tell, i.e. my download speed seems to be about the same no matter what tool I use.

brad:  what OS are you running?

[ferrix]

Yes I was testing with your file lfh.

The total time to get it is not of interest.. It just reflects my maximum available bandwidth to my home windows machine here.  In addition to having a cheap connection, I am also running freenet, which is a nearly constant drain on part of my available width.