Re: [PATCH v12 4/5] cachefiles: Don't rely on backing fs storage map for most use cases

[David Howells <dhowells@redhat.com>]

Petr Chmelar <petr.chmelar@innovatrics.com> wrote:

> Reproducer: random 64 KiB reads covering half of a 256 MiB file of
> random data, then a full read after dropping the page cache, compared
> with the original per 64 KiB block:
> 
>   fio --name=half --filename=/mnt/part.bin --rw=randread --bs=64k \
>       --ioengine=psync --fadvise_hint=random --size=256m --io_size=128m \
>       --randrepeat=1
>   sync; echo 3 > /proc/sys/vm/drop_caches
>   cmp /mnt/part.bin /path/to/original

Unfortunately, I can't reproduce this.  Can you get me some tracing?

echo 65536 >/sys/kernel/tracing/buffer_size_kb
echo 1 >/sys/kernel/tracing/events/netfs/netfs_read/enable
echo 1 >/sys/kernel/tracing/events/netfs/netfs_write/enable
echo 1 >/sys/kernel/tracing/events/netfs/netfs_rreq/enable
echo 1 >/sys/kernel/tracing/events/netfs/netfs_sreq/enable
echo 1 >/sys/kernel/tracing/events/netfs/netfs_failure/enable
echo 1 >/sys/kernel/tracing/events/cachefiles/cachefiles_coherency/enable

before running, then after running do:

cat /sys/kernel/tracing/trace | bzip2 -9 >/tmp/cachefiles-bug.trace.bz2

When I do this and grep the trace output for 'WRITEBACK\|WRIT TERM\|cachefiles'
it all looks reasonable, looking something like:

fio-5895 : netfs_write: R=00001301 WRITEBACK c=00000006 o=00000004 i=c6a742 by=0-ffffffffffffffff
fio-5895 : netfs_sreq: R=00001301[2] WRIT TERM  f=100 s=0 100000/100000 s=7 e=0
fio-5895 : netfs_sreq: R=00001301[4] WRIT TERM  f=100 s=100000 100000/100000 s=15 e=0
fio-5895 : netfs_sreq: R=00001301[6] WRIT TERM  f=100 s=200000 100000/100000 s=23 e=0
fio-5895 : netfs_sreq: R=00001301[8] WRIT TERM  f=100 s=300000 100000/100000 s=0 e=0
fio-5895 : netfs_sreq: R=00001301[a] WRIT TERM  f=100 s=400000 100000/100000 s=8 e=0
fio-5895 : netfs_sreq: R=00001301[c] WRIT TERM  f=100 s=500000 100000/100000 s=16 e=0
fio-5895 : netfs_sreq: R=00001301[e] WRIT TERM  f=100 s=600000 100000/100000 s=24 e=0
...
fio-5895 : netfs_sreq: R=00001301[1f4] WRIT TERM  f=100 s=f900000 100000/100000 s=15 e=0
fio-5895 : netfs_sreq: R=00001301[1f6] WRIT TERM  f=100 s=fa00000 100000/100000 s=23 e=0
fio-5895 : netfs_sreq: R=00001301[1f8] WRIT TERM  f=100 s=fb00000 100000/100000 s=0 e=0
fio-5895 : netfs_sreq: R=00001301[1fa] WRIT TERM  f=100 s=fc00000 100000/100000 s=8 e=0
fio-5895 : netfs_sreq: R=00001301[1fc] WRIT TERM  f=100 s=fd00000 100000/100000 s=16 e=0
fio-5895 : netfs_sreq: R=00001301[1fe] WRIT TERM  f=100 s=fe00000 100000/100000 s=24 e=0
fio-5895 : netfs_sreq: R=00001301[200] WRIT TERM  f=100 s=ff00000 100000/100000 s=1 e=0
 kworker : cachefiles_coherency: o=00000004 SET ok   B=46012e oz=10000000 c=2 aux=0 dsk=0

You can see the writes to the cache terminating and then the cache is set c=2
which is CACHEFILES_CONTENT_ALL indicating that the cache file has no holes in
it.

That happens pretty much as soon as fio lays out its file and then all future
accesses are just reads from the cache.

Looking at the UPLD lines is interesting:

fio-5895 : netfs_sreq: R=00001301[185] UPLD TERM  f=110 s=c1fedd0 fffe8/fffe8 s=8 e=0
fio-5895 : netfs_sreq: R=00001301[187] UPLD TERM  f=110 s=c2fedb8 fffe8/fffe8 s=16 e=0
fio-5895 : netfs_sreq: R=00001301[189] UPLD TERM  f=110 s=c3feda0 fffe8/fffe8 s=24 e=0
fio-5895 : netfs_sreq: R=00001301[18b] UPLD TERM  f=110 s=c4fed88 fffe8/fffe8 s=1 e=0

I guess 9P can't quite squeeze 1M of data in a packet as metadata has to go in
as well.

One further question occurs to me: does the entire 256M file fit in the test
VM's memory?

Thanks,
David