however brad didn't say what platform he's running on.

I was running this on the Amazon provided Fedora Core 4 image. I hacked it up a little but not tons.


# uname -a
Linux domU-12-31-34-00-02-27 2.6.16-xenU #1 SMP Thu Oct 26 08:41:26 SAST 2006 i686 athlon i386 GNU/Linux
# ruby -v
ruby 1.8.4 (2005-12-24) [i386-linux]

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

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

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