Directory listing caching issue

hacktek · May 3, 2019, 8:15pm

Hi there. I have a pretty annoying issue that I’m hoping to get some feedback on. It looks like my entire directory listing is getting cache busted every so often, causing unnecessary API calls. I’m running rclone 1.47.

Take this sample path. It has 200+ folders:

$ find /mnt/pcs/Movies-Remux/Movies -maxdepth 1 -path '*'  | wc -l
228

I’m running the following every 60 seconds to check how long it takes. Note the first run took longer than the next few runs with what I assume was a nearly fully cache busted structure:

root@ftvplex01 ~ # while [ 1 ]; do date && time ls -laR "/mnt/pcs/Movies-Remux/Movies" 1>/dev/null; sleep 60; done
Fri May  3 12:35:44 CST 2019
real	0m53.241s
user	0m0.027s
sys	0m0.064s

Then minutes later it looks like the entire structure busted:

Fri May  3 12:45:38 CST 2019
real	1m0.809s
user	0m0.025s
sys	0m0.075s

And the next cycle also took a while:

Fri May  3 12:47:38 CST 2019
real	0m35.579s
user	0m0.014s
sys	0m0.054s

Mount settings:

/usr/bin/rclone mount pcs:Media /mnt/pcs --dir-cache-time=160h --cache-info-age=168h --buffer-size 1G --vfs-read-chunk-size 32M --vfs-read-chunk-size-limit off --allow-other --allow-non-empty --attr-timeout=1s --syslog --umask 002 --drive-chunk-size 32M --log-level INFO

Anything I can do to fix this?

Animosity022 · May 3, 2019, 8:22pm

Run all those tests and include the debug logs for the mount. Add -vv and share them after repeating the test. With logs, we can identify the why.

hacktek · May 3, 2019, 8:36pm

I mounted it on a different location and logged with debug level.

Two subsequent attempts scanned the entire thing.

root@ftvplex01 ~ # while [ 1 ]; do date && time ls -laR "/mnt/test/Movies-Remux/Movies" 1>/dev/null; sleep 60; done
Fri May  3 14:30:30 CST 2019

real	1m0.011s
user	0m0.024s
sys	0m0.075s
Fri May  3 14:32:30 CST 2019

real	1m3.560s
user	0m0.030s
sys	0m0.076s
^C

The lines right around the second run (actually slightly before) just show it busting the entire structure, unclear why.

2019/05/03 14:32:00 DEBUG : Movies-Remux: invalidating directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies-Anime: forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies: invalidating directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Vox Lux (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Venom (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/White Boy Rick (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Vice (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Welcome Home (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Tully (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Under the Silver Lake (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Whitney (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Unfriended Dark Web (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Triple Threat (2019): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Widows (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Tomb Raider (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Wildling (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Uncle Drew (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Unsane (2018): forgetting directory cache
...

Log file here: https://drive.google.com/file/d/17jAQsVOX8iJkl9tYdtXMxKOSoq-bdXAy/view?usp=sharing

Animosity022 · May 3, 2019, 8:44pm

Are you making changes to the mount at the same time someplace else?

2019/05/03 14:31:45 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:31:46 DEBUG : Movies-Remux/Movies/12 Strong (2018): invalidating directory cache

and

2019/05/03 14:32:00 DEBUG : Movies-Remux: invalidating directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies-Anime: forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies: invalidating directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Vox Lux (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Venom (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/White Boy Rick (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Vice (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Welcome Home (2018): forgetting directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/Tully (2018): forgetting directory cache

and

2019/05/03 14:32:17 DEBUG : Movies-Remux/Movies/Avengers - Infinity War (2018): forgetting directory cache
2019/05/03 14:32:17 DEBUG : Movies-Remux/Movies/BlacKkKlansman (2018): forgetting directory cache

The invalidates are coming in, which is causing the cache to be read cold.

hacktek · May 3, 2019, 8:50pm

Those paths are constantly changing, yes, but only individual items change (say an episode gets added on a single season of a show or a single movie, etc). There aren’t enough changes to invalidate the entire structure from one minute to the next.

To add, nothing in that path changed between 14:30 and 14:32 which is when I ran the test:

root@ftvplex01 ~ # grep 'Movies-Remux' /opt/plex_autoscan/plex_autoscan.log | grep '14:3[0-2]'
root@ftvplex01 ~ #

Also note plex_autoscan isn’t doing anything with this test mount (/mnt/test), so I don’t think it’s related to the issue.

Animosity022 · May 3, 2019, 8:54pm

What does your rclone.conf look like for that? You have cache backend command in there, but doesn’t seem like you using the cache backend.

hacktek · May 3, 2019, 8:55pm

Exactly the same. I just copied the systemd file and changed the paths. I’ll remove that cache command, maybe it’s messing something up.

Animosity022 · May 3, 2019, 8:56pm

Can you share your actual rclone.conf without keys/passwords?

hacktek · May 3, 2019, 9:02pm

Same thing taking -dir-cache-time=160h --cache-info-age=168h out.

The exact same behavior too:

2019/05/03 14:58:15 DEBUG : Movies-Remux/Movies/7 Days in Entebbe (2018): invalidating directory cache
2019/05/03 14:58:15 DEBUG : : Statfs:
2019/05/03 14:58:15 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:58:16 DEBUG : : Statfs:
2019/05/03 14:58:16 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:58:17 DEBUG : : Statfs:
2019/05/03 14:58:17 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:58:18 DEBUG : : Statfs:
2019/05/03 14:58:18 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:58:19 DEBUG : : Statfs:
2019/05/03 14:58:19 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:58:20 DEBUG : : Statfs:
2019/05/03 14:58:20 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:58:21 DEBUG : : Statfs:
2019/05/03 14:58:21 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:58:22 DEBUG : : Statfs:
2019/05/03 14:58:22 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:58:23 DEBUG : : Statfs:
2019/05/03 14:58:23 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:58:24 DEBUG : : Statfs:
2019/05/03 14:58:24 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:58:25 DEBUG : Movies-Remux: invalidating directory cache
2019/05/03 14:58:25 DEBUG : Movies-Remux/Movies-Anime: forgetting directory cache
2019/05/03 14:58:25 DEBUG : Movies-Remux/Movies: invalidating directory cache
2019/05/03 14:58:25 DEBUG : Movies-Remux/Movies/Vox Lux (2018): forgetting directory cache
2019/05/03 14:58:25 DEBUG : Movies-Remux/Movies/Venom (2018): forgetting directory cache
2019/05/03 14:58:25 DEBUG : Movies-Remux/Movies/White Boy Rick (2018): forgetting directory cache
2019/05/03 14:58:25 DEBUG : Movies-Remux/Movies/Vice (2018): forgetting directory cache
2019/05/03 14:58:25 DEBUG : Movies-Remux/Movies/Welcome Home (2018): forgetting directory cache
2019/05/03 14:58:25 DEBUG : Movies-Remux/Movies/Tully (2018): forgetting directory cache

Rclone config is as simple as it gets.

[pcs]
type = drive
client_id = xxxxx
client_secret = xxxxx
scope = drive
token = xxxx
team_drive = xxxxx

Animosity022 · May 3, 2019, 9:08pm

Are you 100% sure no one else is using the drive and making any changes to the files? I can recreate majority of your invalidations but only by dropping new files in outside of the mount or making changes outside of the mount as that invalidates items.

Animosity022 · May 3, 2019, 9:39pm

Trying to see a pattern, but a few observations.

It seems to have a poll not at a minute interval:

2019/05/03 14:31:11 DEBUG : Google drive root 'Media': Checking for changes on remote
2019/05/03 14:32:42 DEBUG : Google drive root 'Media': Checking for changes on remote
2019/05/03 14:33:11 DEBUG : Google drive root 'Media': Checking for changes on remote
2019/05/03 14:34:11 DEBUG : Google drive root 'Media': Checking for changes on remote

That seems odd.

I used Front Runner as my example to look through and can see it invalidates it and forgets it.

2019/05/03 14:30:31 DEBUG : Movies-Remux/Movies/: Lookup: name="The Front Runner (2018)"
2019/05/03 14:30:31 DEBUG : Movies-Remux/Movies/: >Lookup: node=Movies-Remux/Movies/The Front Runner (2018)/, err=<nil>
2019/05/03 14:30:31 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: Attr:
2019/05/03 14:30:31 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/05/03 14:31:18 DEBUG : Movies-Remux/Movies/: Lookup: name="The Front Runner (2018)"
2019/05/03 14:31:18 DEBUG : Movies-Remux/Movies/: >Lookup: node=Movies-Remux/Movies/The Front Runner (2018)/, err=<nil>
2019/05/03 14:31:18 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: Attr:
2019/05/03 14:31:18 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/05/03 14:31:18 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: ReadDirAll:
2019/05/03 14:31:19 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: >ReadDirAll: item=1, err=<nil>
2019/05/03 14:31:19 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: Lookup: name="The.Front.Runner.2018.BluRay.1080p.DTS-HD.MA.5.1.AVC.REMUX-FraMeSToR.mkv"
2019/05/03 14:31:19 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: >Lookup: node=Movies-Remux/Movies/The Front Runner (2018)/The.Front.Runner.2018.BluRay.1080p.DTS-HD.MA.5.1.AVC.REMUX-FraMeSToR.mkv, err=<nil>
2019/05/03 14:31:19 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/The.Front.Runner.2018.BluRay.1080p.DTS-HD.MA.5.1.AVC.REMUX-FraMeSToR.mkv: Attr:
2019/05/03 14:31:19 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/The.Front.Runner.2018.BluRay.1080p.DTS-HD.MA.5.1.AVC.REMUX-FraMeSToR.mkv: >Attr: a=valid=1s ino=0 size=24478766819 mode=-rw-rw-r--, err=<nil>
2019/05/03 14:31:19 DEBUG : Movies-Remux/Movies/The Front Runner (2018): invalidating directory cache
2019/05/03 14:32:00 DEBUG : Movies-Remux/Movies/The Front Runner (2018): forgetting directory cache

The odd part is that the directory to me looks the same before and after but it’s a bit hard to tell as there is a lot of other stuff going on out of order, which also makes little sense to me.

The ls -alR should always list out the same order of files over and over again, yet your debug output is out of order frequently and stuff pops up in the wrong order.

Like the Front Runner starts here:

2019/05/03 14:30:31 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: Attr:
2019/05/03 14:30:31 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/05/03 14:30:31 DEBUG : Movies-Remux/Movies/: Lookup: name="The Girl in the Spider's Web (2018)"
2019/05/03 14:30:31 DEBUG : Movies-Remux/Movies/: >Lookup: node=Movies-Remux/Movies/The Girl in the Spider's Web (2018)/, err=<nil>
2019/05/03 14:30:31 DEBUG : Movies-Remux/Movies/The Girl in the Spider's Web (2018)/: Attr:

but doesn’t list out the files till much later

2019/05/03 14:31:18 DEBUG : Movies-Remux/Movies/: Lookup: name="The Front Runner (2018)"
2019/05/03 14:31:18 DEBUG : Movies-Remux/Movies/: >Lookup: node=Movies-Remux/Movies/The Front Runner (2018)/, err=<nil>
2019/05/03 14:31:18 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: Attr:
2019/05/03 14:31:18 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/05/03 14:31:18 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: ReadDirAll:
2019/05/03 14:31:18 DEBUG : : Statfs:
2019/05/03 14:31:18 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/05/03 14:31:19 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: >ReadDirAll: item=1, err=<nil>
2019/05/03 14:31:19 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: Lookup: name="The.Front.Runner.2018.BluRay.1080p.DTS-HD.MA.5.1.AVC.REMUX-FraMeSToR.mkv"
2019/05/03 14:31:19 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/: >Lookup: node=Movies-Remux/Movies/The Front Runner (2018)/The.Front.Runner.2018.BluRay.1080p.DTS-HD.MA.5.1.AVC.REMUX-FraMeSToR.mkv, err=<nil>
2019/05/03 14:31:19 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/The.Front.Runner.2018.BluRay.1080p.DTS-HD.MA.5.1.AVC.REMUX-FraMeSToR.mkv: Attr:
2019/05/03 14:31:19 DEBUG : Movies-Remux/Movies/The Front Runner (2018)/The.Front.Runner.2018.BluRay.1080p.DTS-HD.MA.5.1.AVC.REMUX-FraMeSToR.mkv: >Attr: a=valid=1s ino=0 size=24478766819 mode=-rw-rw-r--, err=<nil>

I tried multiple times on my movie dir that is similar to yours with your exact mount settings minus the log path being different on the same version as well.

My output is always and debug is always matching in alphabetical order.

hacktek · May 3, 2019, 9:45pm

ikr? This hasn’t really made sense to me for a while and I’ve tried to debug it but it doesn’t make sense.

Good observation about poll internal, default is supposed to be 1 minute yet it’s polling every 30s? That’s weird. Now, I tried changing that to 2m and the pattern essentially changed to bad/good/bad/good:

root@ftvplex01 ~ # while [ 1 ]; do date && time ls -laR "/mnt/test/Movies-Remux/Movies" 1>/dev/null; sleep 60; done
Fri May  3 15:12:14 CST 2019

real	0m57.009s
user	0m0.032s
sys	0m0.066s
Fri May  3 15:14:11 CST 2019

real	0m0.041s
user	0m0.000s
sys	0m0.010s
Fri May  3 15:15:11 CST 2019

real	0m57.620s
user	0m0.036s
sys	0m0.066s
Fri May  3 15:17:09 CST 2019

real	0m22.391s
user	0m0.006s
sys	0m0.033s
Fri May  3 15:18:31 CST 2019

real	0m57.500s
user	0m0.041s
sys	0m0.053s
Fri May  3 15:20:29 CST 2019

real	0m0.056s
user	0m0.000s
sys	0m0.014s
Fri May  3 15:21:29 CST 2019

real	0m57.298s
user	0m0.036s
sys	0m0.063s
Fri May  3 15:23:26 CST 2019

real	0m0.076s
user	0m0.008s
sys	0m0.012s
Fri May  3 15:24:26 CST 2019

real	0m55.916s
user	0m0.031s
sys	0m0.058s
Fri May  3 15:26:22 CST 2019

real	0m0.045s
user	0m0.002s
sys	0m0.008s

But even if it polls every 1-2-10-5000 minutes, whenever it polls it should only invalidate/refetch things that have changed, right? It appears to just be pulling everything at every poll interval, which seems wrong to me. I guess I might be able to work around this somewhat by increasing poll interval a little bit but that won’t solve the problem.

EDIT: I don’t control the other end of this mount (where files are added) so maybe that has something to do with it. I will inquire how the files get changed, it’s possible they’re doing something that causes this.

Animosity022 · May 3, 2019, 9:53pm

It depends on your level of access, you can check the GSuite admin log for drive activity as it is called the “Drive Audit Report”.

You might be able to see in the Google Drive Web UI in the activity log there too.

The really strange part to me is that if you have a Directory and read all the dirs under that, it should walk them in order with the “ls -alR” every time and being out of order baffles me.

I don’t have a team drive though and my drive has only me using it so I have a much more controlled setup.

system · August 1, 2019, 9:59pm

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.