Concurrently deleting a massive directory content turns the whole filesystem inaccessible

[cayolblake]

What happened:

$ rm -rf go/pkg/mod/github.com/

rm: cannot remove 'go/pkg/mod/github.com/!data!dog/[email protected]/LICENSE': Permission denied
rm: cannot remove 'go/pkg/mod/github.com/!data!dog/[email protected]/README.md': Permission denied
rm: cannot remove 'go/pkg/mod/github.com/!data!dog/[email protected]/ZSTD_LICENSE': Permission denied
rm: cannot remove 'go/pkg/mod/github.com/!data!dog/[email protected]/bitstream.h': Permission denied
rm: cannot remove 'go/pkg/mod/github.com/!data!dog/[email protected]/compiler.h': Permission denied
rm: cannot remove 'go/pkg/mod/github.com/!data!dog/[email protected]/cover.c': Permission denied

... truncated ...

What you expected to happen:
Dir to be recursively removed.

Environment:

• JuiceFS version (use ./juicefs --version) or Hadoop Java SDK version: juicefs version 0.12.1-10 (2021-04-21 dadf18e)
• OS (e.g: cat /etc/os-release): Fedora 33
• Kernel (e.g. uname -a): 5.11.14-200.fc33.x86_64
• Object storage (cloud provider and region): DigitalOcean/S3
• Redis info (version, cloud provider managed or self maintained): Redis server v=6.2.2 sha=00000000:0 malloc=jemalloc-5.1.0 bits=64 build=c8cbd75df80c9803
• Network connectivity (JuiceFS to Redis, JuiceFS to object storage): Single machine setup

[davies]

@cayolblake I can't reproduce this issue:

root@localhost:/jfs/mod# ls github.com
alecthomas   cpuguy83    form3tech-oss   hungys         mattn                       pierrec     spaolacci
aliyun       !data!dog   go-asn1-ber     !i!b!m         matttproud                  pingcap     square
!arvintian   davecgh     gogo            imdario        miekg                       pkg         streadway
aws          davies      golang          jcmturner      minio                       prometheus  tencentyun
!azure       dchest      go-ldap         jmespath       mitchellh                   qiniu       tidwall
baidubce     deckarep    gomodule        josharian      modern-go                   rcrowley    tikv
bcicen       dgrijalva   google          json-iterator  montanaflynn                rjeczalik   tinylib
beevik       dgryski     googleapis      juicedata      mozillazg                   rs          upyun
beorn7       djherbis    go-redis        juju           nats-io                     russross    urfave
billziss-gh  dswarbrick  gorilla         klauspost      ncw                         ryanuber    valyala
ceph         dustin      go-sql-driver   kr             !net!ease-!object-!storage  satori      viki-org
cespare      eapache     grpc-ecosystem  ks3sdklib      nsqio                       secure-io   !vivid!cortex
cheggaaa     eclipse     hanwen          kurin          olivere                     shirou      wcharczuk
colinmarc    elazarl     hashicorp       lib            opentracing                 !shopify    willf
coredns      fatih       huandu          mailru         pengsrc                     shurcoo!l   xdg
coreos       felixge     huaweicloud     !masterminds   philhofer                   sirupsen    yunify
root@localhost:/jfs/mod# rm -rf github.com/
root@localhost:/jfs/mod#

It looks like do you have permission to remove these files, rather than something related to !

[cayolblake]

Confirmed. There's a corruption in the mount point not related to names and I'll report in a different issue.

[cayolblake]

@davies

It appears the problems is much bigger than expected.

I changed the title of the issue since I was able to track down what happened which is not a single file in the juicefs mount point is currently readable.

What I did was the following to reach the current state.

1. $ cd dir_with_70k_files_and_dirs
2. $ for i in *; do rm -rf $i & done
3. About a minute later I got a flood of errors saying Transport endpoint is not connected
4. The mount point was completely inaccessible.
5. Had to umount and remount the filesystem.
6. Attempting to read any file regardless small or large blocks.
7. Creating any new file and attempting to read its content succeeds tho.
8. Attempted to create a new cache dir and remounted and attempted to read any file still fails.
9. Tried to strace cat'ing a file, it appears its blocking in the read() syscall.
10. Also, after changing the cache dir, the new file that I created that was accessible is now inaccessible also.
11. I also tried strace on the juicefs process, and here's what I got (with some noise exclusion) after waiting for a couple of minutes while attempting to cat a small file.

[pid  1120] write(10, "<12>Apr 21 18:50:11 juicefs[846] juicefs[846] <WARNING>: fail to read chunkid 216812 (off:0, size:4, clen: 4): timeout after 1m0s\n", 131) = 131
[pid   959] write(2, "2021/04/21 18:50:11.203440 juicefs[846] <WARNING>: fail to read chunkid 216812 (off:0, size:4, clen: 4): timeout after 1m0s\n", 124) = -1 EBADF (Bad file descriptor)
[pid   959] write(2, "Failed to write to log, write /dev/stderr: bad file descriptor\n", 63) = -1 EBADF (Bad file descriptor)
[pid   959] write(14, "*4\r\n$6\r\nlrange\r\n$9\r\nc277492_0\r\n$1\r\n0\r\n$7\r\n1000000\r\n", 51 <unfinished ...>

[pid   969] write(10, "<12>Apr 21 18:50:38 juicefs[846] juicefs[846] <WARNING>: fail to read chunkid 111036 (off:0, size:431, clen: 431): timeout after 1m0s\n", 135) = 135
[pid   959] write(2, "2021/04/21 18:50:38.501985 juicefs[846] <WARNING>: fail to read chunkid 111036 (off:0, size:431, clen: 431): timeout after 1m0s\n", 128) = -1 EBADF (Bad file descriptor)
[pid   959] write(2, "Failed to write to log, write /dev/stderr: bad file descriptor\n", 63) = -1 EBADF (Bad file descriptor)
[pid   959] write(10, "<12>Apr 21 18:50:38 juicefs[846] juicefs[846] <WARNING>: fail to read chunkid 111036 (off:0, size:431, clen: 431): timeout after 1m0s\n", 135 <unfinished ...>
[pid   959] <... write resumed>)        = 135
[pid   969] write(2, "2021/04/21 18:50:38.503020 juicefs[846] <WARNING>: fail to read chunkid 111036 (off:0, size:431, clen: 431): timeout after 1m0s\n", 128) = -1 EBADF (Bad file descriptor)
[pid   959] write(2, "Failed to write to log, write /dev/stderr: bad file descriptor\n", 63) = -1 EBADF (Bad file descriptor)

[pid   969] write(10, "<12>Apr 21 18:50:39 juicefs[846] juicefs[846] <WARNING>: fail to read chunkid 176309 (off:0, size:27482, clen: 27482): timeout after 1m0s\n", 139 <unfinished ...>
[pid   969] <... write resumed>)        = 139
[pid   969] write(2, "2021/04/21 18:50:39.083408 juicefs[846] <WARNING>: fail to read chunkid 176309 (off:0, size:27482, clen: 27482): timeout after 1m0s\n", 132) = -1 EBADF (Bad file descriptor)
[pid   969] write(2, "Failed to write to log, write /dev/stderr: bad file descriptor\n", 63) = -1 EBADF (Bad file descriptor)

13. I took one of the chunkid values from the trace and attempted GET d111036 and got (error) WRONGTYPE Operation against a key holding the wrong kind of value sou assume it's not a string while some other let's starting with a d is accessible asa string, and doing GET i111036 returned "\x00!\xed\x00\x00\x03\xea\x00\x00\x03\xea\x00\x00\x00\x00`\x7ff\x83\x1a\xad\xdcd\x00\x00\x00\x00`\x7ff\x83\x1d\x1aL\x97\x00\x00\x00\x00`\x7f\x92)\x05\x0c=o\x00\x00\x00\x02\x00\x00\x00\x00\x00\x00\x10\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\xb1\xa4\x00"

That's all what happened. Not sure if I lost the content for good or not 🤔

[davies]

After looking at these together, there is what happpened:

1. When deleting many directories concurrently, the juicefs is killed by kernel (OOM), then you see Transport endpoint is not connected
2. When writeback is enabled, the blocks will written into the cache directory first. in the same time, the cache-size is set to 128MB, then some of the blocks can be read until it's uploaded into S3.
3. There could be lots of request to S3, especially after the deletions of many files, your S3 buckets may be flooded, and you see fail to read chunkid 111036 (off:0, size:431, clen: 431): timeout after 1m0s
4. After move the stagging blocks into current cache-dir and mount it again, all files become accessible.
5. After removing --writeback, the benchmark result looks reasonable, even still lower than the result from running in AWS.

[davies]

那是符合预期的，对大目录目前还不支持翻页操作，需要一次性把整个目录的数据加载到内存，会需要很多内存，否则 crash

[ForgQi]

但是为什么在设置GOGC=20这个问题会消失，默认设置下会OOM

[davies]

GOGC 是调整了 GC 回收内存的频率，默认情况下，GOGC=100，JuiceFS 需要 10G 内存时，进程使用内存会到 20G（高于可用内存），而将 GOGC改成 20后，JuiceFS 需要 10G 内存时，进程使用的内存只会到 12G（低于可用内存）。当并发访问多个目录时，会使得 JuiceFS 需要的内存增加到 20+G（已经高于可用内存）

[ForgQi]

感谢您的回复，这个问题未来有计划解决吗，或者文件系统返回一个错误也行，OOM比较难处理

[davies]

还没计划，能拆成多个子目录吗？