NFS client tracepoint confusion

["Mkrtchyan, Tigran" <tigran.mkrtchyan@desy.de>]

[-- Attachment #1: Type: text/plain, Size: 2095 bytes --]


Dear NFS folk,


I am tracing one of our apps and want to match the correlation between application-level open/read/close and NFS-level open/read/close calls.
Here is a fio run that simulates one of our workloads:

fio --name bpftest --rw=randread --size=128k --bs=128k --filename=sample.h5 --loops=123 --openfiles=1 --output=/dev/null

As server issues delegation, I expect that I will see ~123 openat/pread64/close syscalls, ~123 nfs_reads, 1-2 nfs opens, and 1-2 nfs closes.
(The number of sys syscalls is a little bit polluted by open and read of shared libraries.

However, I see a different picture when I run bpftrace


bpftrace  -e 'tracepoint:nfs4:nfs4_pnfs_read,
      tracepoint:syscalls:sys_enter_openat,
      tracepoint:nfs4:nfs4_open_file,
      tracepoint:nfs4:nfs4_close,
      tracepoint:syscalls:
      sys_enter_pread64 /comm == "fio" || strncmp(comm,"kworker", 6) == 0 / { @[comm,probe] = count(); }' 
      -c "fio --name bpftest --rw=randread --size=128k --bs=128k --filename=sample.h5 --loops=123 --openfiles=1 --output=/dev/null"

...


@[kworker/u58:2, tracepoint:nfs4:nfs4_close]: 1
@[kworker/u57:12, tracepoint:nfs4:nfs4_pnfs_read]: 1
@[kworker/u57:3, tracepoint:nfs4:nfs4_pnfs_read]: 57
@[kworker/u57:10, tracepoint:nfs4:nfs4_pnfs_read]: 65
@[fio, tracepoint:nfs4:nfs4_open_file]: 123
@[fio, tracepoint:syscalls:sys_enter_pread64]: 125
@[fio, tracepoint:syscalls:sys_enter_openat]: 202

The number os syscall are as expected as well as the number of nfs4_pnfs_read. However, the number of nfs4_open_file and nfs4_close makes no sense to me.
BTW, the network traffic shows the expected behavior: OPEN+LAYOUTGET -> READ -> CLOSE; OPEN+LAYOUTGET (delegation); READ
Thus, to me, it looks like the trace_nfs4_open_file misses the delegation and is fired, even if no OPEN requests are sent over the network. However, if
trace_nfs4_open_file is in sync with the application-level openat syscall, then it should match the trace_nfs4_close.


I hope I am doing something wrong or looking at the wrong events. Any clarification appreciated.


Thanks in advance,
   Tigran.



[-- Attachment #2: S/MIME Cryptographic Signature --]
[-- Type: application/pkcs7-signature, Size: 2309 bytes --]