Slow performance... possible delay between upload and file rename?

[jas8522]

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_requestsize(/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_requestsize(/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_requestsize(/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?

[romanrm]

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.

[jas8522]

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?

[romanrm]

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.

[jas8522]

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]

[romanrm]

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.

[jas8522]

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?

[romanrm]

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.

[TurboGit]

Nothing we can do on hubicfuse side. Closing.