Readahead reordering causes prefetcher resets

[jamesbornholt]

Mountpoint for Amazon S3 version

mount-s3 1.0.0-unofficial+09f556e

AWS Region

No response

Describe the running environment

EC2

What happened?

I ran this command against my mount:

cat ~/mnt/test20MiB > /dev/null & cat ~/mnt/test20MiB2 > /dev/null & cat ~/mnt/test20MiB3 > /dev/null &

i.e., reading three separate files concurrently.

In the logs, I see:

2023-08-30T03:04:41.030144Z  INFO mountpoint_s3::metrics: prefetch.out_of_order: 6 (n=6)

so the prefetcher is resetting even though each cat is reading sequentially.

It looks like what we're seeing is readahead and multithreading conflicting. For example:

2023-08-30T03:04:39.541005Z DEBUG fuser::request: FUSE( 42) ino 0x0000000000000003 READ fh FileHandle(2), offset 131072, size 262144
2023-08-30T03:04:39.541049Z DEBUG fuser::request: FUSE( 44) ino 0x0000000000000003 READ fh FileHandle(2), offset 393216, size 262144
2023-08-30T03:04:39.541118Z TRACE read{req=44 ino=3 fh=2 offset=393216 size=262144}: mountpoint_s3::fs: fs:read with ino 3 fh 2 offset 393216 size 262144
2023-08-30T03:04:39.541144Z TRACE read{req=44 ino=3 fh=2 offset=393216 size=262144}: mountpoint_s3::prefetch: read offset=393216 length=262144 next_seq_offset=131072
2023-08-30T03:04:39.541153Z TRACE read{req=42 ino=3 fh=2 offset=131072 size=262144}: mountpoint_s3::fs: fs:read with ino 3 fh 2 offset 131072 size 262144
2023-08-30T03:04:39.541168Z TRACE read{req=44 ino=3 fh=2 offset=393216 size=262144}: mountpoint_s3::prefetch: out-of-order read, resetting prefetch expected=131072 actual=393216
2023-08-30T03:04:39.541213Z TRACE read{req=44 ino=3 fh=2 offset=393216 size=262144}: mountpoint_s3::prefetch: spawning request range=393216..1572864 size=1179648
[... 80 ms pass ...]
2023-08-30T03:04:39.624656Z TRACE read{req=42 ino=3 fh=2 offset=131072 size=262144}: mountpoint_s3::prefetch: read offset=131072 length=262144 next_seq_offset=655360
2023-08-30T03:04:39.624695Z TRACE read{req=42 ino=3 fh=2 offset=131072 size=262144}: mountpoint_s3::prefetch: out-of-order read, resetting prefetch expected=655360 actual=131072
2023-08-30T03:04:39.624731Z TRACE read{req=42 ino=3 fh=2 offset=131072 size=262144}: mountpoint_s3::prefetch: spawning request range=131072..1310720 size=117964

Here, the kernel issued two adjacent READ operations on the file handle, without waiting for the response to the first READ (this is the readahead part). Request 42 arrived first, but request 44 was served first, because we have at least two threads available for serving FUSE requests thanks to the auto-scaling from #411, and 44 won the race. So we reset the prefetcher for 44 because it was further along in the object than expected, and then when we finally got to serve 42 we had to reset it again because now it looks like we're seeking backwards. This reduces sequential read performance.

Separate but related issue: it also looks like we aren't actually telling the CRT to cancel the inflight GET request when this reset happens, so those requests are still running (and using bandwidth) even though we're never going to use the result.

Relevant log output

No response