(Resolved) Performance 3x ~ 8x slower than s5cmd (for large files) #338

cayolblake · 2021-04-16T22:54:27Z

cayolblake
Apr 16, 2021

While comparing basic read/write operations, it appears than s5cmd is 3x ~ 8x faster than juicefs

What happened:

#### WRITE IO ####

$ time cp 1gb_file.txt /mnt/juicefs0/
real	0m50.859s
user	0m0.016s
sys	0m1.365s

$ time s5cmd cp 1gb_file.txt s3://bucket/path/
real	0m20.614s
user	0m9.411s
sys	0m3.232s

#### READ IO ####

$ time cp /mnt/juicefs0/1gb_file.txt .
real	0m45.539s
user	0m0.014s
sys	0m1.578s

$ time s5cmd cp s3://bucket/path/1gb_file.txt .
real	0m6.074s
user	0m1.186s
sys	0m2.504s

Environment:

JuiceFS version or Hadoop Java SDK version: juicefs version 0.12.1 (2021-04-15T08:18:25Z 7b4df23)
Cloud provider or hardware configuration running JuiceFS: Linode 1 GB VM
OS: Fedora 33 (Server Edition)
Kernel: Linux 5.11.12-200.fc33.x86_64 #1 SMP Thu Apr 8 02:34:17 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
Object storage: Linode
Redis info: Redis 6.2.1
Network connectivity (JuiceFS to Redis, JuiceFS to object storage): redis (local), S3 Object Storage (Linode)

davies · 2021-04-17T02:56:57Z

davies
Apr 17, 2021
Maintainer

The result is much slower then expected, can you also post the result of 'juicefs benchmark /mnt/juicrfs0'?

0 replies

davies · 2021-04-17T03:06:09Z

davies
Apr 17, 2021
Maintainer

juicefs sync is tool similar to s5cmd, can you also try that?

0 replies

davies · 2021-04-17T03:53:15Z

davies
Apr 17, 2021
Maintainer

I tried above in a 1G VM in Linode Singapore region, here is the result:

[root@localhost ~]# ./juicefs sync 1g s3://$AK:[email protected]/1g
2021/04/17 03:21:41.361903 juicefs[25604] <INFO>: Syncing from file:///root/1g to s3://jfs-test/1g
2021/04/17 03:21:55.979087 juicefs[25604] <INFO>: Found: 1, copied: 1, deleted: 0, failed: 0, transferred: 1024.000 MiB

[root@localhost ~]# ./juicefs sync s3://$AK:[email protected]/1g 1g.1
2021/04/17 03:26:04.310520 juicefs[25619] <INFO>: Syncing from s3://jfs-test/1g to file:///root/1g.1
2021/04/17 03:26:10.605906 juicefs[25619] <INFO>: Found: 1, copied: 1, deleted: 0, failed: 0, transferred: 1024.000 MiB

[root@localhost ~]# ./juicefs benchmark /jfs
Written a big file (1024.00 MiB): (104.33 MiB/s)
Read a big file (1024.00 MiB): (157.37 MiB/s)
Written 100 small files (102.40 KiB): 46.9 files/s, 21.3 ms for each file
Read 100 small files (102.40 KiB): 1909.2 files/s, 0.5 ms for each file
Stated 100 files: 7402.9 files/s, 0.1 ms for each file

[root@localhost ~]# time cp 1g /jfs/1g

real	0m9.493s
user	0m0.004s
sys	0m0.528s
[root@localhost ~]# time cp /jfs/1g /1g.2

real	0m8.868s
user	0m0.004s
sys	0m0.781s

My result looks good, juicefs sync is close to s5cmd, writing into JuiceFS is faster, but reading is slower (we don't tune the default options for reading single large file).

0 replies

cayolblake · 2021-04-17T11:43:19Z

cayolblake
Apr 17, 2021
Author

@davies

Results from juicefs benchmark/mnt/juicefs0/ is...

Written a big file (1024.00 MiB): (46.13 MiB/s)
Read a big file (1024.00 MiB): (15.67 MiB/s)
Written 100 small files (102.40 KiB): 151.9 files/s, 6.6 ms for each file
Read 100 small files (102.40 KiB): 356.9 files/s, 2.8 ms for each file
Stated 100 files: 4569.8 files/s, 0.2 ms for each file

I also redid the same tests on a different machine with similar specs and got the same exact results.

I did not yet try juicefs sync which I can do later today.

0 replies

davies · 2021-04-17T13:50:15Z

davies
Apr 17, 2021
Maintainer

Written a big file (1024.00 MiB): (46.13 MiB/s)
Read a big file (1024.00 MiB): (15.67 MiB/s)
Written 100 small files (102.40 KiB): 151.9 files/s, 6.6 ms for each file

there should be something wrong here, the latency to object store can not be so low.

Read 100 small files (102.40 KiB): 356.9 files/s, 2.8 ms for each file

0 replies

cayolblake · 2021-04-17T23:48:40Z

cayolblake
Apr 17, 2021
Author

Here's the best I can get so far...

$ ping -c 4 eu-central-1.linodeobjects.com

PING eu-central-1.linodeobjects.com(osproxy4-fra1.linode.com (2a01:7e01::f03c:92ff:fee2:1f17)) 56 data bytes
64 bytes from osproxy4-fra1.linode.com (2a01:7e01::f03c:92ff:fee2:1f17): icmp_seq=1 ttl=64 time=0.416 ms
64 bytes from osproxy4-fra1.linode.com (2a01:7e01::f03c:92ff:fee2:1f17): icmp_seq=2 ttl=64 time=0.415 ms
64 bytes from osproxy4-fra1.linode.com (2a01:7e01::f03c:92ff:fee2:1f17): icmp_seq=3 ttl=64 time=0.397 ms
64 bytes from osproxy4-fra1.linode.com (2a01:7e01::f03c:92ff:fee2:1f17): icmp_seq=4 ttl=64 time=0.343 ms

$ mtr -r eu-central-1.linodeobjects.com

Start: 2021-04-17T23:36:26+0000
HOST: cortico-nd726-fra01         Loss%   Snt   Last   Avg  Best  Wrst StDev
  1.|-- osproxy4-fra1.linode.com   0.0%    10    0.4   0.4   0.4   0.5   0.0

$ tracepath eu-central-1.linodeobjects.com

 1?: [LOCALHOST]                        0.006ms pmtu 1500
 1:  osproxy4-fra1.linode.com                              0.443ms reached
 1:  osproxy4-fra1.linode.com                              0.243ms reached
     Resume: pmtu 1500 hops 1 back 1

Having this said, I tried strace'ing all juicefs related threads found through pstree and I can notice a huge number of statfs() calls on the jfsCache dir, /var/jfsCache/2722f291-1282-4dc4-bfbd-554a5a560968/ in my case. Not saying its related to my issue however I guess it should introduce an overhead at least somewhere along the whole app execution.

Still, given the condition of my environment, why s5cmd outperforms juicefs by that much?! Is it related to the fact that juicefs breaks big files into 4 MB chunks?

0 replies

davies · 2021-04-19T02:57:08Z

davies
Apr 19, 2021
Maintainer

Having this said, I tried strace'ing all juicefs related threads found through pstree and I can notice a huge number of statfs() calls on the jfsCache dir, /var/jfsCache/2722f291-1282-4dc4-bfbd-554a5a560968/ in my case. Not saying its related to my issue however I guess it should introduce an overhead at least somewhere along the whole app execution.

The overhead is not significant unless your system is overloaded.

Still, given the condition of my environment, why s5cmd outperforms juicefs by that much?! Is it related to the fact that juicefs breaks big files into 4 MB chunks?

s5cmd is doing similar things with multipart-upload, so this should not be the cause.

Have you tried juicefs sync ?

0 replies

davies · 2021-04-19T02:59:31Z

davies
Apr 19, 2021
Maintainer

Can you double check the setting by

$ redis-cli
127.0.0.1:6379> get setting
"{\n\"Name\": \"dev\",\n\"UUID\": \"619ba184-3f01-4466-8dda-f2ab7881d4d0\",\n\"Storage\": \"file\",\n\"Bucket\": \"/Users/davies/.juicefs/local/\",\n\"AccessKey\": \"\",\n\"SecretKey\": \"\",\n\"BlockSize\": 4096,\n\"Compression\": \"lz4\",\n\"Partitions\": 0,\n\"EncryptKey\": \"\"\n}"

Please REMOVE the secret key before posting here.

0 replies

davies · 2021-04-20T07:20:16Z

davies
Apr 20, 2021
Maintainer

ping @cayolblake

0 replies

cayolblake · 2021-04-20T19:01:02Z

cayolblake
Apr 20, 2021
Author

@davies Sorry, been taken reading the juicefs interesting code base :)

I'll be able to run this in a few hours.

0 replies

cayolblake · 2021-04-20T22:10:27Z

cayolblake
Apr 20, 2021
Author

127.0.0.1:6379[1]> GET setting

"{\n\"Name\": \"17D0CC249E8F\",\n\"UUID\": \"f4f32e95-4218-4389-aa02-d1b2c81ef48b\",\n\"Storage\": \"s3\",\n\"Bucket\": \"https://some-bucket-name.eu-central-1.linodeobjects.com\",\n\"AccessKey\": \"OMITTED\",\n\"SecretKey\": \"OMITTED\",\n\"BlockSize\": 4096,\n\"Compression\": \"none\",\n\"Partitions\": 0,\n\"EncryptKey\": \"\"\n}"

Will try juicefs sync and update back shortly.

0 replies

cayolblake · 2021-04-21T00:06:15Z

cayolblake
Apr 21, 2021
Author

$ time juicefs sync 800mb_file s3://omitted:[email protected]/123123

2021/04/21 00:00:05.488424 juicefs[3968106] <INFO>: Syncing from file:///root/800mb_file to s3://some-bucket-name/123123
2021/04/21 00:00:22.612074 juicefs[3968106] <INFO>: Found: 1, copied: 1, deleted: 0, failed: 0, transferred: 800.000 MiB

real	0m17.164s
user	0m5.561s
sys	0m1.169s

$ time s5cmd cp 800mb_file s3://omitted/omitted/

cp 800mb_file s3://omitted/omitted/800mb_file

real	0m10.572s
user	0m5.425s
sys	0m1.416s

0 replies

davies · 2021-04-21T04:17:59Z

davies
Apr 21, 2021
Maintainer

It seems that juicefs sync has similar behavior than s5cmd. It's still unknown why JuiceFS is slow.

0 replies

cayolblake · 2021-04-21T15:47:32Z

cayolblake
Apr 21, 2021
Author

Btw I also tried with formatting with 8 MB chunks and got the same behavior.

0 replies

davies · 2021-04-22T02:49:57Z

davies
Apr 22, 2021
Maintainer

It looks like to be a issue with --writeback and --cache-size 128, moving this issue into discussion.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

(Resolved) Performance 3x ~ 8x slower than s5cmd (for large files) #338

{{title}}

Replies: 15 comments

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

(Resolved) Performance 3x ~ 8x slower than s5cmd (for large files) #338

cayolblake Apr 16, 2021

Replies: 15 comments

davies Apr 17, 2021 Maintainer

davies Apr 17, 2021 Maintainer

davies Apr 17, 2021 Maintainer

cayolblake Apr 17, 2021 Author

davies Apr 17, 2021 Maintainer

cayolblake Apr 17, 2021 Author

davies Apr 19, 2021 Maintainer

davies Apr 19, 2021 Maintainer

davies Apr 20, 2021 Maintainer

cayolblake Apr 20, 2021 Author

cayolblake Apr 20, 2021 Author

cayolblake Apr 21, 2021 Author

davies Apr 21, 2021 Maintainer

cayolblake Apr 21, 2021 Author

davies Apr 22, 2021 Maintainer

cayolblake
Apr 16, 2021

davies
Apr 17, 2021
Maintainer

davies
Apr 17, 2021
Maintainer

davies
Apr 17, 2021
Maintainer

cayolblake
Apr 17, 2021
Author

davies
Apr 17, 2021
Maintainer

cayolblake
Apr 17, 2021
Author

davies
Apr 19, 2021
Maintainer

davies
Apr 19, 2021
Maintainer

davies
Apr 20, 2021
Maintainer

cayolblake
Apr 20, 2021
Author

cayolblake
Apr 20, 2021
Author

cayolblake
Apr 21, 2021
Author

davies
Apr 21, 2021
Maintainer

cayolblake
Apr 21, 2021
Author

davies
Apr 22, 2021
Maintainer