Slow performance... possible delay between upload and file rename?
Closed this issue · 8 comments
Running this command:
rsync --progress /root/test.txt /mnt/hubic/default/Jordan
Results in this:
3 100% 0.00kB/s 0:00:00 (xfer#1, to-check=0/1)sent 75 bytes received 31 bytes 2.99 bytes/sec
total size is 3 speedup is 0.03
Which can't be the expected speed. I set hubicfuse to debug mode and it seems like the PUT command is normal speed, but then there's some unspecified delay between completing that command and renaming the file:
==DBG 1 [2016-07-08 21:44:25.]:5941==status: send_request_size(/default/Jordan/.test.txt.NrYJjQ) completed HTTP REQ:https://lb9911.hubic.ovh.net/v1/AUTH_{SNIPPED}/default/Jordan/.test.txt.NrYJjQ total_time=1.1 seconds
==DBG 0 [2016-07-08 21:44:25.]:5941==exit 0: send_request_size(/default/Jordan/.test.txt.NrYJjQ) speed=1.1 sec (PUT) [HTTP OK]
==DBG 1 [2016-07-08 21:44:25.]:5941==exit 1: cloudfs_object_read_fp(/default/Jordan/.test.txt.NrYJjQ)
==DBG 0 [2016-07-08 21:44:25.]:5941==exit 1: cfs_flush(/default/Jordan/.test.txt.NrYJjQ) result=11:Resource temporarily unavailable
unique: 36, success, outsize: 16
unique: 37, opcode: RELEASE (18), nodeid: 5, insize: 64, pid: 0
unique: 38, opcode: LOOKUP (1), nodeid: 3, insize: 57, pid: 6000
release[139942516900192] flags: 0x8002
LOOKUP /default/Jordan/.test.txt.NrYJjQ
getattr /default/Jordan/.test.txt.NrYJjQ==DBG 1 [2016-07-08 21:45:13.]:5942==status: send_request_size(/default/Jordan/test.txt) completed HTTP REQ:https://lb9911.hubic.ovh.net/v1/AUTH_{SNIP}/default/Jordan/test.txt total_time=48.0 seconds
==DBG 0 [2016-07-08 21:45:13.]:5942==exit 0: send_request_size(/default/Jordan/test.txt) speed=48.0 sec (PUT) [HTTP OK]
==DBG 1 [2016-07-08 21:45:13.]:5942==exit: cloudfs_copy_object(/default/Jordan/.test.txt.NrYJjQ,/default/Jordan/test.txt) response=201
==DBG 0 [2016-07-08 21:45:13.]:5942==cfs_unlink(/default/Jordan/.test.txt.NrYJjQ)
==DBG 1 [2016-07-08 21:45:13.]:5942==cloudfs_delete_object(/default/Jordan/.test.txt.NrYJjQ)
==DBG 1 [2016-07-08 21:45:13.]:5942==format_segments(/default/Jordan/.test.txt.NrYJjQ)
==DBG 1 [2016-07-08 21:45:13.]:5942==internal_is_segmented(/default/Jordan_segments)
==DBG 1 [2016-07-08 21:45:13.]:5942==check_path_info(/default/Jordan/.test.txt.NrYJjQ)
==DBG 1 [2016-07-08 21:45:13.]:5942==check_caching_list_directory(/default/Jordan)
==DBG 1 [2016-07-08 21:45:13.]:5942==exit 0: check_caching_list_directory(/default/Jordan) [CACHE-DIR-HIT]
==DBG 1 [2016-07-08 21:45:13.]:5942==exit 1: check_path_info(/default/Jordan/.test.txt.NrYJjQ) [CACHE-HIT]
==DBG 1 [2016-07-08 21:45:13.]:5942==internal_is_segmented: potentially segmented=0
==DBG 1 [2016-07-08 21:45:13.]:5942==exit 1: internal_is_segmented(/default/Jordan_segments) FALSE
==DBG 1 [2016-07-08 21:45:13.]:5942==exit 5: format_segments(/default/Jordan/.test.txt.NrYJjQ) not segmented?
==DBG 1 [2016-07-08 21:45:13.]:5942==send_request_size(DELETE) (%2Fdefault%2FJordan%2F.test.txt.NrYJjQ)
==DBG 1 [2016-07-08 21:45:13.]:5942==add_header(X-Auth-Token:6db7ca80bc1f4981af96745ecbf2405e)
==DBG 1 [2016-07-08 21:45:13.]:5942==check_path_info(/default/Jordan/.test.txt.NrYJjQ)
==DBG 1 [2016-07-08 21:45:13.]:5942==check_caching_list_directory(/default/Jordan)
==DBG 1 [2016-07-08 21:45:13.]:5942==exit 0: check_caching_list_directory(/default/Jordan) [CACHE-DIR-HIT]
==DBG 1 [2016-07-08 21:45:13.]:5942==exit 1: check_path_info(/default/Jordan/.test.txt.NrYJjQ) [CACHE-HIT]
==DBG 1 [2016-07-08 21:45:13.]:5942==send_request_size: catch_all ()
==DBG 1 [2016-07-08 21:45:13.]:5942==status: send_request_size(/default/Jordan/.test.txt.NrYJjQ) started HTTP REQ:https://lb9911.hubic.ovh.net/v1/AUTH_{SNIPPED}/default/Jordan/.test.txt.NrYJjQ
Thoughts as to what's up with the performance?
between completing that command and renaming the file:
Are you aware that renames do not exist in the underlying protocol, and a rename is nothing but a second upload under the new name?
ALWAYS use --inplace with rsync.
rsync --progress --inplace /root/test.txt /mnt/hubic/default/Jordan
test.txt
3 100% 0.00kB/s 0:00:00 (xfer#1, to-check=0/1)sent 75 bytes received 31 bytes 10.10 bytes/sec
total size is 3 speedup is 0.03
10.10 bytes/sec isn't too hot! Thoughts on how I can best troubleshoot this?
Thoughts on how I can best troubleshoot this?
Hubic isn't very fast on metadata operations in general (creation/deletion), try with a larger file, if you upload a 100 Mbyte file the speed should average out to much higher, even if there are any creation/end upload delays.
Don't try to store tons of very small files, it isn't fit for that. If you have to, compress them into a single file archive before upload.
Here it is on upload (great performance for transfer itself):
rsync --progress --inplace /root/onehundredmb /mnt/hubic/default/Jordan/
onehundredmb
104857600 100% 69.71MB/s 0:00:01 (xfer#1, to-check=0/1)
But then the process is hung right there. Terminal non-responsive. Is there something else I'm missing? The performance of the raw data transfer seems great, but then it never seems to complete the transaction. I had to ctrl-c rsync.
Here's my attempt to download the same file:
rsync --progress --inplace /mnt/hubic/default/Jordan/onehundredmb /root/download/
file has vanished: "/mnt/hubic/default/Jordan/onehundredmb"
sent 50 bytes received 31 bytes 3.18 bytes/sec
total size is 104857600 speedup is 1294538.27
rsync warning: some files vanished before they could be transferred (code 24) at main.c(1052) [sender=3.0.9]
But then the process is hung right there. Terminal non-responsive. Is there something else I'm missing?
It's not hung, it is actually uploading at this moment. In effect this very fast speed is copying the file into hubicfuse's temporary location (/tmp by default), then the entire file is sent to Hubic. After that completes, your rsync would unlock and most likely also update the speed reading to the realistic one.
Thanks romanrm.
Looks like I'm getting 3MB/sec upload and 1MB/sec download from an OVH VPS in Montreal to Hubic. Would you consider that normal from what you've seen?
Since about a month ago (http://travaux.ovh.net/?do=details&id=17305) they have enabled the 10 Mbit speed limit which is specified in the Hubic TOS. So if you get 3 MB/sec that's very good, and around 1 MB/sec is to be expected.
However the infrastructure is capable of much more than that, as before this change I used to get full 100 Mbit upload speeds, maxing out my home connection. We can look forward to when/if they decide to remove or upgrade the artificial limit.
Nothing we can do on hubicfuse side. Closing.