gcsfuse: unbearable slowness of directory listings

500 files in a directory. the instance is in us-east and the storage is there as well (regional).

> time gsutil ls gs:\\mybucketdir | wc -l

500
real	0m0.974s
user	0m0.484s
sys	0m0.156s

When running ls /mnt/mymountpoint

I get the following timings

gcs: Req             0x98: -> ListObjects() (199.70033ms): OK
gcs: Req             0x9a: <- ListObjects()
gcs: Req             0x9a: -> ListObjects() (203.140236ms): OK
gcs: Req             0x9b: <- ListObjects()
gcs: Req             0x9b: -> ListObjects() (197.373822ms): OK
gcs: Req             0x9c: <- ListObjects()
gcs: Req             0x9c: -> ListObjects() (184.619554ms): OK
gcs: Req             0x9d: <- ListObjects()
gcs: Req             0x9d: -> ListObjects() (764.47926ms): OK
gcs: Req             0x9e: <- ListObjects()
gcs: Req             0x9e: -> ListObjects() (150.530204ms): OK
gcs: Req             0x9f: <- ListObjects()
gcs: Req             0x9f: -> ListObjects() (199.542155ms): OK
gcs: Req             0xa0: <- ListObjects()
gcs: Req             0xa0: -> ListObjects() (181.239533ms): OK
gcs: Req             0xa1: <- ListObjects()
gcs: Req             0xa1: -> ListObjects() (215.307041ms): OK
gcs: Req             0xa2: <- ListObjects()
gcs: Req             0xa2: -> ListObjects() (205.366617ms): OK
gcs: Req             0xa3: <- ListObjects()
gcs: Req             0xa3: -> ListObjects() (197.569194ms): OK
gcs: Req             0xa4: <- ListObjects()
gcs: Req             0xa4: -> ListObjects() (197.323209ms): OK
gcs: Req             0xa5: <- ListObjects()
gcs: Req             0xa5: -> ListObjects() (200.654838ms): OK
gcs: Req             0xa6: <- ListObjects()
gcs: Req             0xa6: -> ListObjects() (163.866557ms): OK
gcs: Req             0xa7: <- ListObjects()
gcs: Req             0xa7: -> ListObjects() (217.490382ms): OK
gcs: Req             0xa8: <- ListObjects()
gcs: Req             0xa8: -> ListObjects() (225.55158ms): OK
gcs: Req             0xa9: <- ListObjects()
gcs: Req             0xa9: -> ListObjects() (188.412506ms): OK
gcs: Req             0xaa: <- ListObjects()
gcs: Req             0xaa: -> ListObjects() (201.611923ms): OK
gcs: Req             0xab: <- ListObjects()
gcs: Req             0xab: -> ListObjects() (203.075812ms): OK

it’s mounted with these options: --foreground --limit-ops-per-sec -1 --implicit-dirs -o ro -o allow_other --uid 1001 --gid 1002 --debug_gcs Is there any way to make it faster? it takes few minutes to run ls compared to gsutil that takes few seconds.

About this issue

Original URL
State: closed
Created 7 years ago
Reactions: 1
Comments: 27 (14 by maintainers)

Most upvoted comments

Thanks for sending the log. With the --debug_fuse output I can now see what’s going on. For the sake of posterity, I’m posting the leading portion of the log below, with directory and file names redacted.

This is for running ls --color=auto /mntpoint/parent1/parent2/parent3/, with gcsfuse mounted using --implicit-dirs.

Using mount point: /ubimo/east
Opening GCS connection...
Opening bucket...
gcs: Req              0x0: <- ListObjects()
gcs: Req              0x0: -> ListObjects() (254.550252ms): OK
Mounting file system...
fuse_debug: Op 0x00000001        connection.go:395] <- init
fuse_debug: Op 0x00000001        connection.go:474] -> OK ()
File system has been successfully mounted.
fuse_debug: Op 0x00000002        connection.go:395] <- GetInodeAttributes (inode 1)
fuse_debug: Op 0x00000002        connection.go:474] -> OK ()
fuse_debug: Op 0x00000003        connection.go:395] <- LookUpInode (parent 1, name "parent1")
gcs: Req              0x1: <- ListObjects()
gcs: Req              0x2: <- StatObject("parent1")
gcs: Req              0x3: <- StatObject("parent1/")
gcs: Req              0x2: -> StatObject("parent1") (49.033757ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req              0x3: -> StatObject("parent1/") (72.178894ms): OK
gcs: Req              0x1: -> ListObjects() (254.907424ms): OK
fuse_debug: Op 0x00000003        connection.go:474] -> OK (inode 2)
fuse_debug: Op 0x00000004        connection.go:395] <- LookUpInode (parent 2, name "parent2")
gcs: Req              0x4: <- ListObjects()
gcs: Req              0x5: <- StatObject("parent1/parent2")
gcs: Req              0x6: <- StatObject("parent1/parent2/")
gcs: Req              0x5: -> StatObject("parent1/parent2") (52.982038ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req              0x6: -> StatObject("parent1/parent2/") (69.350561ms): OK
gcs: Req              0x4: -> ListObjects() (162.533908ms): OK
fuse_debug: Op 0x00000004        connection.go:474] -> OK (inode 3)
fuse_debug: Op 0x00000005        connection.go:395] <- LookUpInode (parent 3, name "parent3")
gcs: Req              0x7: <- StatObject("parent1/parent2/parent3")
gcs: Req              0x8: <- ListObjects()
gcs: Req              0x9: <- StatObject("parent1/parent2/parent3/")
gcs: Req              0x7: -> StatObject("parent1/parent2/parent3") (54.228636ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req              0x9: -> StatObject("parent1/parent2/parent3/") (62.542072ms): OK
gcs: Req              0x8: -> ListObjects() (239.473957ms): OK
fuse_debug: Op 0x00000005        connection.go:474] -> OK (inode 4)
fuse_debug: Op 0x00000006        connection.go:395] <- LookUpInode (parent 1, name "parent1")
gcs: Req              0xa: <- ListObjects()
gcs: Req              0xa: -> ListObjects() (167.671106ms): OK
fuse_debug: Op 0x00000006        connection.go:474] -> OK (inode 2)
fuse_debug: Op 0x00000007        connection.go:395] <- LookUpInode (parent 2, name "parent2")
gcs: Req              0xb: <- ListObjects()
gcs: Req              0xb: -> ListObjects() (220.816242ms): OK
fuse_debug: Op 0x00000007        connection.go:474] -> OK (inode 3)
fuse_debug: Op 0x00000008        connection.go:395] <- LookUpInode (parent 3, name "parent3")
gcs: Req              0xc: <- ListObjects()
gcs: Req              0xc: -> ListObjects() (200.543335ms): OK
fuse_debug: Op 0x00000008        connection.go:474] -> OK (inode 4)
fuse_debug: Op 0x00000009        connection.go:395] <- OpenDir (inode 4)
fuse_debug: Op 0x00000009        connection.go:474] -> OK ()
fuse_debug: Op 0x0000000a        connection.go:395] <- ReadDir (inode 4)
gcs: Req              0xd: <- ListObjects()
gcs: Req              0xd: -> ListObjects() (1.852518768s): OK
fuse_debug: Op 0x0000000a        connection.go:474] -> OK ()
fuse_debug: Op 0x0000000b        connection.go:395] <- LookUpInode (parent 1, name "parent1")
gcs: Req              0xe: <- ListObjects()
gcs: Req              0xe: -> ListObjects() (251.362257ms): OK
fuse_debug: Op 0x0000000b        connection.go:474] -> OK (inode 2)
fuse_debug: Op 0x0000000c        connection.go:395] <- LookUpInode (parent 2, name "parent2")
gcs: Req              0xf: <- ListObjects()
gcs: Req              0xf: -> ListObjects() (187.784336ms): OK
fuse_debug: Op 0x0000000c        connection.go:474] -> OK (inode 3)
fuse_debug: Op 0x0000000d        connection.go:395] <- LookUpInode (parent 3, name "parent3")
gcs: Req             0x10: <- ListObjects()
gcs: Req             0x10: -> ListObjects() (228.835581ms): OK
fuse_debug: Op 0x0000000d        connection.go:474] -> OK (inode 4)
fuse_debug: Op 0x0000000e        connection.go:395] <- LookUpInode (parent 4, name "file-0000")
fuse_debug: Op 0x0000000e        connection.go:474] -> OK (inode 5)
fuse_debug: Op 0x0000000f        connection.go:395] <- LookUpInode (parent 1, name "parent1")
gcs: Req             0x11: <- ListObjects()
gcs: Req             0x11: -> ListObjects() (188.495048ms): OK
fuse_debug: Op 0x0000000f        connection.go:474] -> OK (inode 2)
fuse_debug: Op 0x00000010        connection.go:395] <- LookUpInode (parent 2, name "parent2")
gcs: Req             0x12: <- ListObjects()
gcs: Req             0x12: -> ListObjects() (171.51587ms): OK
fuse_debug: Op 0x00000010        connection.go:474] -> OK (inode 3)
fuse_debug: Op 0x00000011        connection.go:395] <- LookUpInode (parent 3, name "parent3")
gcs: Req             0x13: <- ListObjects()
gcs: Req             0x13: -> ListObjects() (228.927968ms): OK
fuse_debug: Op 0x00000011        connection.go:474] -> OK (inode 4)
fuse_debug: Op 0x00000012        connection.go:395] <- LookUpInode (parent 4, name "file-0001")
fuse_debug: Op 0x00000012        connection.go:474] -> OK (inode 6)
fuse_debug: Op 0x00000013        connection.go:395] <- LookUpInode (parent 1, name "parent1")
gcs: Req             0x14: <- ListObjects()
gcs: Req             0x14: -> ListObjects() (161.306221ms): OK
fuse_debug: Op 0x00000013        connection.go:474] -> OK (inode 2)
fuse_debug: Op 0x00000014        connection.go:395] <- LookUpInode (parent 2, name "parent2")
gcs: Req             0x15: <- ListObjects()
gcs: Req             0x15: -> ListObjects() (305.978979ms): OK
fuse_debug: Op 0x00000014        connection.go:474] -> OK (inode 3)
fuse_debug: Op 0x00000015        connection.go:395] <- LookUpInode (parent 3, name "parent3")
gcs: Req             0x16: <- ListObjects()
gcs: Req             0x16: -> ListObjects() (192.817882ms): OK
fuse_debug: Op 0x00000015        connection.go:474] -> OK (inode 4)
fuse_debug: Op 0x00000016        connection.go:395] <- LookUpInode (parent 4, name "file-0002")
fuse_debug: Op 0x00000016        connection.go:474] -> OK (inode 7)
fuse_debug: Op 0x00000017        connection.go:395] <- LookUpInode (parent 1, name "parent1")
gcs: Req             0x17: <- ListObjects()
gcs: Req             0x17: -> ListObjects() (200.761433ms): OK
fuse_debug: Op 0x00000017        connection.go:474] -> OK (inode 2)
fuse_debug: Op 0x00000018        connection.go:395] <- LookUpInode (parent 2, name "parent2")

Everything up to the ReadDir op looks sane. Strictly listing the directory is not particularly slow (as you confirmed before with ls -1).

But then ls goes to stat each object, and this results in a LookUpInode request for each of the three ancestor directories. (I don’t know why this is, but it’s the decision of the kernel’s VFS layer and is presumably for a sane reason.)

The type cache successfully avoids a lookup as a file, so we look up the inodes only as directories. Since you’re using --implicit-dirs, this involves a call to ListObjects to confirm that the implicit directory still exists. Once all of the directories are looked up, a LookUpInode is received for the file, and responded to from cache (since we have a backing object record in our cache from the earlier calls to ListObjects).

Therefore the 500 stat calls from ls turn into 1500 calls to ListObjects. This is in contrast to gsutil ls, which I believe does nothing but a single ListObjects request.

Unfortunately this is the cost of pretending to be a file system with directory inodes, but not actually having GCS objects to back them. The correct fix here is to not use --implicit-dirs.

jacobsa on Jun 27, 2017

I do not understand how to work with read-only mount without “–implicit-dirs” - it does not show me the directories and it gives me " No such file or directory" when I tried to ls them. This is why we used this option in the first place.

Surprisingly, now any option with gcsfuse works fast and the request listing is much shorter! I do not understand what happens. Full listing below with options: gcsfuse --foreground -o allow_other -o ro --implicit-dirs --uid 1001 --gid 1002 --limit-ops-per-sec -1 --debug_gcs ubieast /ubimo/east2

time ls  /ubimo/east2/mydataset/ym=2017-06/dd=03/ | wc -l
gcs: Req              0x1: <- StatObject("mydataset")
gcs: Req              0x3: <- StatObject("mydataset/")
gcs: Req              0x2: <- ListObjects()
gcs: Req              0x1: -> StatObject("mydataset") (40.065192ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req              0x3: -> StatObject("mydataset/") (43.995664ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req              0x2: -> ListObjects() (232.255188ms): OK
gcs: Req              0x4: <- ListObjects()
gcs: Req              0x5: <- StatObject("mydataset/ym=2017-06")
gcs: Req              0x6: <- StatObject("mydataset/ym=2017-06/")
gcs: Req              0x6: -> StatObject("mydataset/ym=2017-06/") (35.133425ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req              0x5: -> StatObject("mydataset/ym=2017-06") (39.872907ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req              0x4: -> ListObjects() (190.290325ms): OK
gcs: Req              0x7: <- StatObject("mydataset/ym=2017-06/dd=03")
gcs: Req              0x8: <- ListObjects()
gcs: Req              0x9: <- StatObject("mydataset/ym=2017-06/dd=03/")
gcs: Req              0x9: -> StatObject("mydataset/ym=2017-06/dd=03/") (31.486524ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req              0x7: -> StatObject("mydataset/ym=2017-06/dd=03") (45.052541ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req              0x8: -> ListObjects() (185.64592ms): OK
gcs: Req              0xa: <- ListObjects()
gcs: Req              0xa: -> ListObjects() (203.076368ms): OK
gcs: Req              0xb: <- ListObjects()
gcs: Req              0xb: -> ListObjects() (187.4465ms): OK
gcs: Req              0xc: <- ListObjects()
gcs: Req              0xc: -> ListObjects() (227.215982ms): OK
gcs: Req              0xd: <- ListObjects()
gcs: Req              0xd: -> ListObjects() (661.99406ms): OK
500


real	0m1.897s
user	0m0.000s
sys	0m0.000s

romange on Jun 23, 2017