Operations become much slower after the process runs a few minutes

[wsu13]

Version: Hadoop FileSystem SDK juicefs-hadoop-0.12.0.jar which is manually compiled from source.

I run a test workload to create thousands of files. At first it's very quick, but after a few minutes it becomes slower and slower. You can see the operations takes 10ms+ average at first. Then it comes to 1s+ after process runs a few minutes.

2021\.xx\.xx 19:15:31.040914 [uid:1001,gid:0,pid:11692025] Write (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Leland/_tmp.001273_0,13786): (13786,OK) <0.000036>
2021\.xx\.xx 19:15:31.042224 [uid:1001,gid:0,pid:14500025] Write (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Leon/_tmp.000008_0,10517): (10517,OK) <0.000043>
2021\.xx\.xx 19:15:31.042442 [uid:1001,gid:0,pid:13467025] Close (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Royal/_tmp.001007_0): OK <0.043820>
2021\.xx\.xx 19:15:31.044183 [uid:1001,gid:0,pid:14930025] Write (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Sutton/_tmp.001024_0,28568): (28568,OK) <0.000043>
2021\.xx\.xx 19:15:31.051767 [uid:1001,gid:0,pid:10600025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Five Forks/_tmp.001716_0): no such file or directory <0.059436>
2021\.xx\.xx 19:15:31.074538 [uid:1001,gid:0,pid:11469025] Close (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Plainview/_tmp.001541_0): OK <0.049327>
2021\.xx\.xx 19:15:31.082921 [uid:1001,gid:0,pid:6410025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Lone Oak/_tmp.002468_0): no such file or directory <0.069572>
2021\.xx\.xx 19:15:31.083012 [uid:1001,gid:0,pid:14500025] Close (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Leon/_tmp.000008_0): OK <0.040770>
2021\.xx\.xx 19:15:31.083080 [uid:1001,gid:0,pid:13191025] Rename (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Springdale/_tmp.001162_0,/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_tmp.-ext-10000/ss_city=Springdale/001162_0): OK <0.160570>


2021\.xx\.xx 19:17:50.885546 [uid:1001,gid:0,pid:3698025] Rename (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Hamilton/_tmp.000261_0,/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_tmp.-ext-10000/ss_city=Hamilton/000261_0): OK <1.406678>
2021\.xx\.xx 19:17:50.885572 [uid:1001,gid:0,pid:14500025] Rename (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Franklin/_tmp.000998_0,/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_tmp.-ext-10000/ss_city=Franklin/000998_0): OK <1.374612>
2021\.xx\.xx 19:17:50.897041 [uid:1001,gid:0,pid:14500025] Write (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Florence/_tmp.000998_0,17229): (17229,OK) <0.000062>
2021\.xx\.xx 19:17:50.902033 [uid:1001,gid:0,pid:3698025] Write (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Plainview/_tmp.000261_0,45378): (45378,OK) <0.000046>
2021\.xx\.xx 19:17:50.998608 [uid:1001,gid:0,pid:2658025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Lakeview/_tmp.002451_0): no such file or directory <0.553439>
2021\.xx\.xx 19:17:50.998688 [uid:1001,gid:0,pid:3397025] Rename (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Belleview/_tmp.002124_0,/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_tmp.-ext-10000/ss_city=Belleview/002124_0): OK <1.724322>
2021\.xx\.xx 19:17:50.998881 [uid:1001,gid:0,pid:11971025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_tmp.-ext-10000/ss_city=Gary): OK <0.481577>
2021\.xx\.xx 19:17:51.007403 [uid:1001,gid:0,pid:3397025] Write (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Millbrook/_tmp.002124_0,12009): (12009,OK) <0.000593>
2021\.xx\.xx 19:17:51.036254 [uid:1001,gid:0,pid:12312025] Close (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Longwood/_tmp.002715_0): OK <0.292357>
2021\.xx\.xx 19:17:51.036293 [uid:1001,gid:0,pid:14142025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Walnut/_tmp.002314_0): no such file or directory <0.591126>
2021\.xx\.xx 19:17:51.081204 [uid:1001,gid:0,pid:13467025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Sleepy Hollow/_tmp.002304_0): no such file or directory <0.598372>
2021\.xx\.xx 19:17:51.081397 [uid:1001,gid:0,pid:9826025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_tmp.-ext-10000/ss_city=Concord): OK <0.491785>
2021\.xx\.xx 19:17:51.081396 [uid:1001,gid:0,pid:11182025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_tmp.-ext-10000/ss_city=Sweetwater): OK <0.491822>



2021\.xx\.xx 19:32:22.784723 [uid:1001,gid:0,pid:9826025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Sutton/_tmp.000736_0): no such file or directory <1.054469>
2021\.xx\.xx 19:32:22.863192 [uid:1001,gid:0,pid:13823025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_tmp.-ext-10000/ss_city=Arthur): OK <0.990133>
2021\.xx\.xx 19:32:22.863627 [uid:1001,gid:0,pid:4213025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Rockwood/_tmp.001364_0): no such file or directory <1.071472>
2021\.xx\.xx 19:32:22.949300 [uid:1001,gid:0,pid:14500025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_tmp.-ext-10000/ss_city=Forest Hills): OK <0.996582>
2021\.xx\.xx 19:32:22.949951 [uid:1001,gid:0,pid:2658025] Create (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Blanchard/_tmp.000220_0,640): OK <1.564832>
2021\.xx\.xx 19:32:23.036111 [uid:1001,gid:0,pid:11182025] Create (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Wright/_tmp.000762_0,640): OK <1.564301>
2021\.xx\.xx 19:32:23.037278 [uid:1001,gid:0,pid:12867025] Lookup (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Holt/_tmp.000551_0): no such file or directory <1.077059>
2021\.xx\.xx 19:32:23.121745 [uid:1001,gid:0,pid:10042025] Create (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Ashland/_tmp.001770_0,640): OK <1.564281>
2021\.xx\.xx 19:32:23.121818 [uid:1001,gid:0,pid:13467025] Rename (/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_task_tmp.-ext-10000/ss_city=Howell/_tmp.001151_0,/tpcds/etlout/warehouse/orc/100/etlout/.hive-staging_hive_2021-04-14_19-10-59_852_15538566282519xxxx-1/_tmp.-ext-10000/ss_city=Howell/001151_0): OK <2.811900>

[wsu13]

I find out that when test workload starts, the redis CPU goes up to 100%, and qps drops down. That causes meta request becomes slow. Why Juicefs consumes so much redis CPU?

[davies]

@wsu13 This is an known issue fixed in latest main branch [1], please upgrade it.

[1] 6358e38

[wsu13]

It worked. thanks.