On Tue, Nov 30, 2021 at 07:50:13PM -0800, dai.ngo@xxxxxxxxxx wrote: > > On 11/30/21 7:32 AM, Bruce Fields wrote: > >On Mon, Nov 29, 2021 at 11:13:34PM -0800, dai.ngo@xxxxxxxxxx wrote: > >>Just to be clear, the problem of pynfs with 4.0 is that the server takes > >>~55 secs to expire 1026 4.0 courteous clients, which comes out to ~50ms > >>per client. This causes the test to time out in waiting for RPC reply of > >>the OPEN that triggers the conflicts. > >> > >>I don't know exactly where the time spent in the process of expiring a > >>client. But as Bruce mentioned, it could be related to the time to access > >>/var/lib/nfs to remove the client's persistent record. > >Could you try something like > > > > strace -r -$(pidof) -oTRACE Oops, I mean $(pidof nfsdcld). But, your system isn't using that: > > Strace does not have any info that shows where the server spent time when > expiring client state. The client record is removed by nfsd4_umh_cltrack_remove > doing upcall to user space helper /sbin/nfsdcltrack to do the job. I used > the low-tech debug tool, printk, to measure the time spent by > nfsd4_client_record_remove. Here is a sample of the output, START and END > are in milliseconds: > > Nov 30 12:31:04 localhost kernel: nfsd4_client_record_remove: START [0x15d418] clp[ffff888119206040] client_tracking_ops[ffffffffa04bc2e0] > Nov 30 12:31:04 localhost kernel: nfsd4_client_record_remove: END [0x15d459] clp[ffff888119206040] client_tracking_ops[ffffffffa04bc2e0] > Nov 30 12:31:04 localhost kernel: nfsd4_client_record_remove: START [0x15d461] clp[ffff888119206740] client_tracking_ops[ffffffffa04bc2e0] > Nov 30 12:31:04 localhost kernel: nfsd4_client_record_remove: END [0x15d48e] clp[ffff888119206740] client_tracking_ops[ffffffffa04bc2e0] > Nov 30 12:31:04 localhost kernel: nfsd4_client_record_remove: START [0x15d49c] clp[ffff88811b54e000] client_tracking_ops[ffffffffa04bc2e0] > Nov 30 12:31:04 localhost kernel: nfsd4_client_record_remove: END [0x15d4c5] clp[ffff88811b54e000] client_tracking_ops[ffffffffa04bc2e0] > > The average time spent to remove the client record is about ~50ms, matches > with the time reported by pynfs test. This confirms what Bruce suspected > earlier. OK, good to know. It'd be interesting to dig into where nfsdcltrack is spending its time, which we could do by replacing it with a wrapper that runs the real nfsdcltrack under strace. Though maybe it'd be better to do this on a system using nfsdcld, since that's what we're transitioning to. --b.
