Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
From:   "NeilBrown" <neilb@suse.de>
To:     "Lorenzo Bianconi" <lorenzo@kernel.org>
Cc:     linux-nfs@vger.kernel.org, lorenzo.bianconi@redhat.com,
        chuck.lever@oracle.com, jlayton@kernel.org
Subject: Re: [PATCH v3] NFSD: add rpc_status entry in nfsd debug filesystem
In-reply-to: <4aa3c87872031ca42d411ed60169c6daa951620b.1689610081.git.lorenzo@kernel.org>
References: <4aa3c87872031ca42d411ed60169c6daa951620b.1689610081.git.lorenzo@kernel.org>
Date:   Tue, 18 Jul 2023 07:49:24 +1000
Message-id: <168963056470.1518.10737362406173956339@noble.neil.brown.name>
Precedence: bulk

On Tue, 18 Jul 2023, Lorenzo Bianconi wrote:
> Introduce rpc_status entry in nfsd debug filesystem in order to dump
> pending RPC requests debugging information.
>=20
> Link: https://bugzilla.linux-nfs.org/show_bug.cgi?id=3D366
> Signed-off-by: Lorenzo Bianconi <lorenzo@kernel.org>
> ---
> Changes since v2:
> - minor changes in nfsd_rpc_status_show output
>=20
> Changes since v1:
> - rework nfsd_rpc_status_show output
>=20
> Changes since RFCv1:
> - riduce time holding nfsd_mutex bumping svc_serv refcoung in
>   nfsd_rpc_status_open()
> - dump rqstp->rq_stime
> - add missing kdoc for nfsd_rpc_status_open()
> ---
>  fs/nfsd/nfs4proc.c |  4 +--
>  fs/nfsd/nfsctl.c   | 10 ++++++
>  fs/nfsd/nfsd.h     |  2 ++
>  fs/nfsd/nfssvc.c   | 83 ++++++++++++++++++++++++++++++++++++++++++++++
>  net/sunrpc/svc.c   |  2 +-
>  5 files changed, 97 insertions(+), 4 deletions(-)
>=20
> diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
> index d8e7a533f9d2..a7f522390a66 100644
> --- a/fs/nfsd/nfs4proc.c
> +++ b/fs/nfsd/nfs4proc.c
> @@ -2463,8 +2463,6 @@ static inline void nfsd4_increment_op_stats(u32 opnum)
> =20
>  static const struct nfsd4_operation nfsd4_ops[];
> =20
> -static const char *nfsd4_op_name(unsigned opnum);
> -
>  /*
>   * Enforce NFSv4.1 COMPOUND ordering rules:
>   *
> @@ -3594,7 +3592,7 @@ void warn_on_nonidempotent_op(struct nfsd4_op *op)
>  	}
>  }
> =20
> -static const char *nfsd4_op_name(unsigned opnum)
> +const char *nfsd4_op_name(unsigned opnum)
>  {
>  	if (opnum < ARRAY_SIZE(nfsd4_ops))
>  		return nfsd4_ops[opnum].op_name;
> diff --git a/fs/nfsd/nfsctl.c b/fs/nfsd/nfsctl.c
> index 1b8b1aab9a15..629b4296e7c6 100644
> --- a/fs/nfsd/nfsctl.c
> +++ b/fs/nfsd/nfsctl.c
> @@ -57,6 +57,8 @@ enum {
>  	NFSD_RecoveryDir,
>  	NFSD_V4EndGrace,
>  #endif
> +	NFSD_Rpc_Status,
> +
>  	NFSD_MaxReserved
>  };
> =20
> @@ -195,6 +197,13 @@ static inline struct net *netns(struct file *file)
>  	return file_inode(file)->i_sb->s_fs_info;
>  }
> =20
> +static const struct file_operations nfsd_rpc_status_operations =3D {
> +	.open		=3D nfsd_rpc_status_open,
> +	.read		=3D seq_read,
> +	.llseek		=3D seq_lseek,
> +	.release	=3D nfsd_pool_stats_release,
> +};
> +
>  /*
>   * write_unlock_ip - Release all locks used by a client
>   *
> @@ -1400,6 +1409,7 @@ static int nfsd_fill_super(struct super_block *sb, st=
ruct fs_context *fc)
>  		[NFSD_RecoveryDir] =3D {"nfsv4recoverydir", &transaction_ops, S_IWUSR|S_=
IRUSR},
>  		[NFSD_V4EndGrace] =3D {"v4_end_grace", &transaction_ops, S_IWUSR|S_IRUGO=
},
>  #endif
> +		[NFSD_Rpc_Status] =3D {"rpc_status", &nfsd_rpc_status_operations, S_IRUG=
O},
>  		/* last one */ {""}
>  	};
> =20
> diff --git a/fs/nfsd/nfsd.h b/fs/nfsd/nfsd.h
> index d88498f8b275..75a3e1d55bc8 100644
> --- a/fs/nfsd/nfsd.h
> +++ b/fs/nfsd/nfsd.h
> @@ -94,6 +94,7 @@ int		nfsd_get_nrthreads(int n, int *, struct net *);
>  int		nfsd_set_nrthreads(int n, int *, struct net *);
>  int		nfsd_pool_stats_open(struct inode *, struct file *);
>  int		nfsd_pool_stats_release(struct inode *, struct file *);
> +int		nfsd_rpc_status_open(struct inode *inode, struct file *file);
>  void		nfsd_shutdown_threads(struct net *net);
> =20
>  void		nfsd_put(struct net *net);
> @@ -506,6 +507,7 @@ extern void nfsd4_ssc_init_umount_work(struct nfsd_net =
*nn);
> =20
>  extern void nfsd4_init_leases_net(struct nfsd_net *nn);
> =20
> +const char *nfsd4_op_name(unsigned opnum);
>  #else /* CONFIG_NFSD_V4 */
>  static inline int nfsd4_is_junction(struct dentry *dentry)
>  {
> diff --git a/fs/nfsd/nfssvc.c b/fs/nfsd/nfssvc.c
> index 97830e28c140..3f6d53e5f579 100644
> --- a/fs/nfsd/nfssvc.c
> +++ b/fs/nfsd/nfssvc.c
> @@ -1149,3 +1149,86 @@ int nfsd_pool_stats_release(struct inode *inode, str=
uct file *file)
>  	mutex_unlock(&nfsd_mutex);
>  	return ret;
>  }
> +
> +static int nfsd_rpc_status_show(struct seq_file *m, void *v)
> +{
> +	struct inode *inode =3D file_inode(m->file);
> +	struct nfsd_net *nn =3D net_generic(inode->i_sb->s_fs_info, nfsd_net_id);
> +	int i;
> +
> +	rcu_read_lock();
> +
> +	for (i =3D 0; i < nn->nfsd_serv->sv_nrpools; i++) {
> +		struct svc_rqst *rqstp;
> +
> +		list_for_each_entry_rcu(rqstp,
> +				&nn->nfsd_serv->sv_pools[i].sp_all_threads,
> +				rq_all) {
> +			if (!test_bit(RQ_BUSY, &rqstp->rq_flags))
> +				continue;

The fact that RQ_BUSY is set doesn't mean that the various fields you
are sampling are valid or stable.

I suggest you add add a counter to the rqstp which is incremented from
even to odd after parsing a request - including he v4 parsing needed to
have a sable ->opcnt - and then incremented from odd to even when the
request is complete.
Then this code samples the counter, skips the rqst if the counter is
even, and resamples the counter after collecting the data.  If it has
changed, the drop the record.

> +
> +			seq_printf(m,
> +				   "0x%08x 0x%08lx 0x%08x NFSv%d %s %016lld",
> +				   be32_to_cpu(rqstp->rq_xid), rqstp->rq_flags,
> +				   rqstp->rq_prog, rqstp->rq_vers,
> +				   svc_proc_name(rqstp),
> +				   ktime_to_us(rqstp->rq_stime));
> +
> +			if (rqstp->rq_addr.ss_family =3D=3D AF_INET)
> +				seq_printf(m, " %pI4 %pI4",
> +					   &((struct sockaddr_in *)&rqstp->rq_addr)->sin_addr,
> +					   &((struct sockaddr_in *)&rqstp->rq_daddr)->sin_addr);
> +			else if (rqstp->rq_addr.ss_family =3D=3D AF_INET6)
> +				seq_printf(m, " %pI6 %pI6",
> +					   &((struct sockaddr_in6 *)&rqstp->rq_addr)->sin6_addr,
> +					   &((struct sockaddr_in6 *)&rqstp->rq_daddr)->sin6_addr);
> +			else
> +				seq_printf(m, " unknown:%hu unknown:%hu",
> +					   rqstp->rq_addr.ss_family,
> +					   rqstp->rq_daddr.ss_family);

The above code looks a lot like svc_print_addr().  Can we use the same
code?  Do they need to be different.

NeilBrown


> +#ifdef CONFIG_NFSD_V4
> +			if (rqstp->rq_vers =3D=3D NFS4_VERSION &&
> +			    rqstp->rq_proc =3D=3D NFSPROC4_COMPOUND) {
> +				/* NFSv4 compund */
> +				struct nfsd4_compoundargs *args =3D rqstp->rq_argp;
> +				struct nfsd4_compoundres *resp =3D rqstp->rq_resp;
> +
> +				while (resp->opcnt < args->opcnt) {
> +					struct nfsd4_op *op =3D &args->ops[resp->opcnt++];
> +
> +					seq_printf(m, " %s%s", nfsd4_op_name(op->opnum),
> +						   resp->opcnt < args->opcnt ? ":" : "");
> +				}
> +			}
> +#endif /* CONFIG_NFSD_V4 */
> +			seq_puts(m, "\n");
> +		}
> +	}
> +
> +	rcu_read_unlock();
> +
> +	return 0;
> +}
> +
> +/**
> + * nfsd_rpc_status_open - Atomically copy a write verifier
> + * @inode: entry inode pointer.
> + * @file: entry file pointer.
> + *
> + * This routine dumps pending RPC requests info queued into nfs server.
> + */
> +int nfsd_rpc_status_open(struct inode *inode, struct file *file)
> +{
> +	struct nfsd_net *nn =3D net_generic(inode->i_sb->s_fs_info, nfsd_net_id);
> +
> +	mutex_lock(&nfsd_mutex);
> +	if (!nn->nfsd_serv) {
> +		mutex_unlock(&nfsd_mutex);
> +		return -ENODEV;
> +	}
> +
> +	svc_get(nn->nfsd_serv);
> +	mutex_unlock(&nfsd_mutex);
> +
> +	return single_open(file, nfsd_rpc_status_show, inode->i_private);
> +}
> diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
> index 587811a002c9..44eac83b35a1 100644
> --- a/net/sunrpc/svc.c
> +++ b/net/sunrpc/svc.c
> @@ -1629,7 +1629,7 @@ const char *svc_proc_name(const struct svc_rqst *rqst=
p)
>  		return rqstp->rq_procinfo->pc_name;
>  	return "unknown";
>  }
> -
> +EXPORT_SYMBOL_GPL(svc_proc_name);
> =20
>  /**
>   * svc_encode_result_payload - mark a range of bytes as a result payload
> --=20
> 2.41.0
>=20
>=20