wal-e/wal-e — pull request #78 by tsilen (2014-01-07 15:09:46+00:00)
Title: Fix timings

Fixes KiB per second calculations that gave incorrectly high values.

time.clock() uses processor time, excluding the time spent doing I/O, but I/O is what we want to measure when timing uploads, etc. Due to that the KiB/s values were quite a bit higher than the actual transfer speeds.

E.g:
wal_e.worker.upload INFO MSG: begin uploading a base backup volume
DETAIL: Uploading to "s3://x/basebackups_005/base_000000050000055D00000034_00000040/tar_partitions/part_0.tar.lzo".
STRUCTURED: time=2014-01-07T13:27:54.881763-00 pid=26012
wal_e.worker.upload INFO MSG: finish uploading a base backup volume
DETAIL: Uploading to "s3://x/basebackups_005/base_000000050000055D00000034_00000040/tar_partitions/part_0.tar.lzo" complete at 74008.1KiB/s.
STRUCTURED: time=2014-01-07T13:29:24.855229-00 pid=26012

The file size here was about 54768 Kb and the actual upload speed was actually only about 609 KiB/s and not 74008.1KiB/s.

Noticed this when trying to figure out why the uploads were very slow, although the log line suggested that they were fast.

Still haven't found out why it's so slow, though.