diff mbox series

[2/2] NFSD: add trace points to track server copy progress

Message ID 1693439219-19467-2-git-send-email-dai.ngo@oracle.com (mailing list archive)
State New, archived
Headers show
Series [1/2] NFSD: initialize copy->cp_clp early in nfsd4_copy for use by trace point | expand

Commit Message

Dai Ngo Aug. 30, 2023, 11:46 p.m. UTC 
Add trace points on destination server to track inter and intra
server copy operations.

Signed-off-by: Dai Ngo <dai.ngo@oracle.com>
---
 fs/nfsd/nfs4proc.c | 12 +++++--
 fs/nfsd/trace.h    | 89 ++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 99 insertions(+), 2 deletions(-)

Comments

kernel test robot Aug. 31, 2023, 5:18 a.m. UTC | #1 
Hi Dai,

kernel test robot noticed the following build errors:

[auto build test ERROR on linus/master]
[also build test ERROR on v6.5 next-20230830]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Dai-Ngo/NFSD-add-trace-points-to-track-server-copy-progress/20230831-074806
base:   linus/master
patch link:    https://lore.kernel.org/r/1693439219-19467-2-git-send-email-dai.ngo%40oracle.com
patch subject: [PATCH 2/2] NFSD: add trace points to track server copy progress
config: s390-defconfig (https://download.01.org/0day-ci/archive/20230831/202308311350.wOmbsChS-lkp@intel.com/config)
compiler: s390-linux-gcc (GCC) 13.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20230831/202308311350.wOmbsChS-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202308311350.wOmbsChS-lkp@intel.com/

All errors (new ones prefixed by >>):

   fs/nfsd/nfs4proc.c: In function 'nfsd4_do_async_copy':
>> fs/nfsd/nfs4proc.c:1730:9: error: implicit declaration of function 'trace_nfsd4_copy_do_async'; did you mean 'nfsd4_copy_is_async'? [-Werror=implicit-function-declaration]
    1730 |         trace_nfsd4_copy_do_async(copy);
         |         ^~~~~~~~~~~~~~~~~~~~~~~~~
         |         nfsd4_copy_is_async
   fs/nfsd/nfs4proc.c: In function 'nfsd4_copy':
>> fs/nfsd/nfs4proc.c:1771:17: error: implicit declaration of function 'trace_nfsd4_copy_inter'; did you mean 'trace_nfsd_ctl_time'? [-Werror=implicit-function-declaration]
    1771 |                 trace_nfsd4_copy_inter(copy);
         |                 ^~~~~~~~~~~~~~~~~~~~~~
         |                 trace_nfsd_ctl_time
>> fs/nfsd/nfs4proc.c:1778:25: error: implicit declaration of function 'trace_nfsd4_copy_done'; did you mean 'trace_nfsd_read_done'? [-Werror=implicit-function-declaration]
    1778 |                         trace_nfsd4_copy_done(copy, status);
         |                         ^~~~~~~~~~~~~~~~~~~~~
         |                         trace_nfsd_read_done
>> fs/nfsd/nfs4proc.c:1782:17: error: implicit declaration of function 'trace_nfsd4_copy_intra'; did you mean 'trace_nfsd_cb_setup'? [-Werror=implicit-function-declaration]
    1782 |                 trace_nfsd4_copy_intra(copy);
         |                 ^~~~~~~~~~~~~~~~~~~~~~
         |                 trace_nfsd_cb_setup
   cc1: some warnings being treated as errors


vim +1730 fs/nfsd/nfs4proc.c

  1717	
  1718	/**
  1719	 * nfsd4_do_async_copy - kthread function for background server-side COPY
  1720	 * @data: arguments for COPY operation
  1721	 *
  1722	 * Return values:
  1723	 *   %0: Copy operation is done.
  1724	 */
  1725	static int nfsd4_do_async_copy(void *data)
  1726	{
  1727		struct nfsd4_copy *copy = (struct nfsd4_copy *)data;
  1728		__be32 nfserr;
  1729	
> 1730		trace_nfsd4_copy_do_async(copy);
  1731		if (nfsd4_ssc_is_inter(copy)) {
  1732			struct file *filp;
  1733	
  1734			filp = nfs42_ssc_open(copy->ss_nsui->nsui_vfsmount,
  1735					      &copy->c_fh, &copy->stateid);
  1736			if (IS_ERR(filp)) {
  1737				switch (PTR_ERR(filp)) {
  1738				case -EBADF:
  1739					nfserr = nfserr_wrong_type;
  1740					break;
  1741				default:
  1742					nfserr = nfserr_offload_denied;
  1743				}
  1744				/* ss_mnt will be unmounted by the laundromat */
  1745				goto do_callback;
  1746			}
  1747			nfserr = nfsd4_do_copy(copy, filp, copy->nf_dst->nf_file,
  1748					       false);
  1749			nfsd4_cleanup_inter_ssc(copy->ss_nsui, filp, copy->nf_dst);
  1750		} else {
  1751			nfserr = nfsd4_do_copy(copy, copy->nf_src->nf_file,
  1752					       copy->nf_dst->nf_file, false);
  1753		}
  1754	
  1755	do_callback:
  1756		nfsd4_send_cb_offload(copy, nfserr);
  1757		cleanup_async_copy(copy);
  1758		return 0;
  1759	}
  1760	
  1761	static __be32
  1762	nfsd4_copy(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
  1763			union nfsd4_op_u *u)
  1764	{
  1765		struct nfsd4_copy *copy = &u->copy;
  1766		__be32 status;
  1767		struct nfsd4_copy *async_copy = NULL;
  1768	
  1769		copy->cp_clp = cstate->clp;
  1770		if (nfsd4_ssc_is_inter(copy)) {
> 1771			trace_nfsd4_copy_inter(copy);
  1772			if (!inter_copy_offload_enable || nfsd4_copy_is_sync(copy)) {
  1773				status = nfserr_notsupp;
  1774				goto out;
  1775			}
  1776			status = nfsd4_setup_inter_ssc(rqstp, cstate, copy);
  1777			if (status) {
> 1778				trace_nfsd4_copy_done(copy, status);
  1779				return nfserr_offload_denied;
  1780			}
  1781		} else {
> 1782			trace_nfsd4_copy_intra(copy);
  1783			status = nfsd4_setup_intra_ssc(rqstp, cstate, copy);
  1784			if (status) {
  1785				trace_nfsd4_copy_done(copy, status);
  1786				return status;
  1787			}
  1788		}
  1789	
  1790		memcpy(&copy->fh, &cstate->current_fh.fh_handle,
  1791			sizeof(struct knfsd_fh));
  1792		if (nfsd4_copy_is_async(copy)) {
  1793			struct nfsd_net *nn = net_generic(SVC_NET(rqstp), nfsd_net_id);
  1794	
  1795			status = nfserrno(-ENOMEM);
  1796			async_copy = kzalloc(sizeof(struct nfsd4_copy), GFP_KERNEL);
  1797			if (!async_copy)
  1798				goto out_err;
  1799			INIT_LIST_HEAD(&async_copy->copies);
  1800			refcount_set(&async_copy->refcount, 1);
  1801			async_copy->cp_src = kmalloc(sizeof(*async_copy->cp_src), GFP_KERNEL);
  1802			if (!async_copy->cp_src)
  1803				goto out_err;
  1804			if (!nfs4_init_copy_state(nn, copy))
  1805				goto out_err;
  1806			memcpy(&copy->cp_res.cb_stateid, &copy->cp_stateid.cs_stid,
  1807				sizeof(copy->cp_res.cb_stateid));
  1808			dup_copy_fields(copy, async_copy);
  1809			async_copy->copy_task = kthread_create(nfsd4_do_async_copy,
  1810					async_copy, "%s", "copy thread");
  1811			if (IS_ERR(async_copy->copy_task))
  1812				goto out_err;
  1813			spin_lock(&async_copy->cp_clp->async_lock);
  1814			list_add(&async_copy->copies,
  1815					&async_copy->cp_clp->async_copies);
  1816			spin_unlock(&async_copy->cp_clp->async_lock);
  1817			wake_up_process(async_copy->copy_task);
  1818			status = nfs_ok;
  1819		} else {
  1820			status = nfsd4_do_copy(copy, copy->nf_src->nf_file,
  1821					       copy->nf_dst->nf_file, true);
  1822		}
  1823	out:
  1824		trace_nfsd4_copy_done(copy, status);
  1825		release_copy_files(copy);
  1826		return status;
  1827	out_err:
  1828		if (nfsd4_ssc_is_inter(copy)) {
  1829			/*
  1830			 * Source's vfsmount of inter-copy will be unmounted
  1831			 * by the laundromat. Use copy instead of async_copy
  1832			 * since async_copy->ss_nsui might not be set yet.
  1833			 */
  1834			refcount_dec(&copy->ss_nsui->nsui_refcnt);
  1835		}
  1836		if (async_copy)
  1837			cleanup_async_copy(async_copy);
  1838		status = nfserrno(-ENOMEM);
  1839		goto out;
  1840	}
  1841
Chuck Lever III Aug. 31, 2023, 2:13 p.m. UTC | #2 
On Wed, Aug 30, 2023 at 04:46:59PM -0700, Dai Ngo wrote:
> Add trace points on destination server to track inter and intra
> server copy operations.
> 
> Signed-off-by: Dai Ngo <dai.ngo@oracle.com>
> ---
>  fs/nfsd/nfs4proc.c | 12 +++++--
>  fs/nfsd/trace.h    | 89 ++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 99 insertions(+), 2 deletions(-)
> 
> diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
> index 62f6aba6140b..9a780559073f 100644
> --- a/fs/nfsd/nfs4proc.c
> +++ b/fs/nfsd/nfs4proc.c
> @@ -1760,6 +1760,7 @@ static int nfsd4_do_async_copy(void *data)
>  	struct nfsd4_copy *copy = (struct nfsd4_copy *)data;
>  	__be32 nfserr;
>  
> +	trace_nfsd4_copy_do_async(copy);

Nice addition to our observability of COPY operations!

Only comment is we have no other tracepoints named "nfsd4_yada" so
I feel it would be better if these were all renamed "nfsd_yada".


>  	if (nfsd4_ssc_is_inter(copy)) {
>  		struct file *filp;
>  
> @@ -1800,17 +1801,23 @@ nfsd4_copy(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>  
>  	copy->cp_clp = cstate->clp;
>  	if (nfsd4_ssc_is_inter(copy)) {
> +		trace_nfsd4_copy_inter(copy);
>  		if (!inter_copy_offload_enable || nfsd4_copy_is_sync(copy)) {
>  			status = nfserr_notsupp;
>  			goto out;
>  		}
>  		status = nfsd4_setup_inter_ssc(rqstp, cstate, copy);
> -		if (status)
> +		if (status) {
> +			trace_nfsd4_copy_done(copy, status);
>  			return nfserr_offload_denied;
> +		}
>  	} else {
> +		trace_nfsd4_copy_intra(copy);
>  		status = nfsd4_setup_intra_ssc(rqstp, cstate, copy);
> -		if (status)
> +		if (status) {
> +			trace_nfsd4_copy_done(copy, status);
>  			return status;
> +		}
>  	}
>  
>  	memcpy(&copy->fh, &cstate->current_fh.fh_handle,
> @@ -1847,6 +1854,7 @@ nfsd4_copy(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>  				       copy->nf_dst->nf_file, true);
>  	}
>  out:
> +	trace_nfsd4_copy_done(copy, status);
>  	release_copy_files(copy);
>  	return status;
>  out_err:
> diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
> index 803904348871..6256a77c95c9 100644
> --- a/fs/nfsd/trace.h
> +++ b/fs/nfsd/trace.h
> @@ -1863,6 +1863,95 @@ TRACE_EVENT(nfsd_end_grace,
>  	)
>  );
>  
> +#ifdef CONFIG_NFS_V4_2
> +DECLARE_EVENT_CLASS(nfsd4_copy_class,
> +	TP_PROTO(
> +		const struct nfsd4_copy *copy
> +	),
> +	TP_ARGS(copy),
> +	TP_STRUCT__entry(
> +		__field(bool, intra)
> +		__field(bool, async)
> +		__field(u32, src_cl_boot)
> +		__field(u32, src_cl_id)
> +		__field(u32, src_so_id)
> +		__field(u32, src_si_generation)
> +		__field(u32, dst_cl_boot)
> +		__field(u32, dst_cl_id)
> +		__field(u32, dst_so_id)
> +		__field(u32, dst_si_generation)
> +		__field(u64, src_cp_pos)
> +		__field(u64, dst_cp_pos)
> +		__field(u64, cp_count)
> +		__sockaddr(addr, sizeof(struct sockaddr_in6))
> +	),
> +	TP_fast_assign(
> +		const stateid_t *src_stp = &copy->cp_src_stateid;
> +		const stateid_t *dst_stp = &copy->cp_dst_stateid;
> +
> +		__entry->intra = test_bit(NFSD4_COPY_F_INTRA, &copy->cp_flags);
> +		__entry->async = !test_bit(NFSD4_COPY_F_SYNCHRONOUS, &copy->cp_flags);
> +		__entry->src_cl_boot = src_stp->si_opaque.so_clid.cl_boot;
> +		__entry->src_cl_id = src_stp->si_opaque.so_clid.cl_id;
> +		__entry->src_so_id = src_stp->si_opaque.so_id;
> +		__entry->src_si_generation = src_stp->si_generation;
> +		__entry->dst_cl_boot = dst_stp->si_opaque.so_clid.cl_boot;
> +		__entry->dst_cl_id = dst_stp->si_opaque.so_clid.cl_id;
> +		__entry->dst_so_id = dst_stp->si_opaque.so_id;
> +		__entry->dst_si_generation = dst_stp->si_generation;
> +		__entry->src_cp_pos = copy->cp_src_pos;
> +		__entry->dst_cp_pos = copy->cp_dst_pos;
> +		__entry->cp_count = copy->cp_count;
> +		__assign_sockaddr(addr, &copy->cp_clp->cl_addr,
> +				sizeof(struct sockaddr_in6));
> +	),
> +	TP_printk("client=%pISpc intra=%d async=%d "
> +		"src_stateid[si_generation:0x%x cl_boot:0x%x cl_id:0x%x so_id:0x%x] "
> +		"dst_stateid[si_generation:0x%x cl_boot:0x%x cl_id:0x%x so_id:0x%x] "
> +		"cp_src_pos=%llu cp_dst_pos=%llu cp_count=%llu",
> +		__get_sockaddr(addr), __entry->intra, __entry->async,
> +		__entry->src_si_generation, __entry->src_cl_boot,
> +		__entry->src_cl_id, __entry->src_so_id,
> +		__entry->dst_si_generation, __entry->dst_cl_boot,
> +		__entry->dst_cl_id, __entry->dst_so_id,
> +		__entry->src_cp_pos, __entry->dst_cp_pos, __entry->cp_count
> +	)
> +);
> +
> +#define DEFINE_COPY_EVENT(name)				\
> +DEFINE_EVENT(nfsd4_copy_class, nfsd4_copy_##name,	\
> +	TP_PROTO(const struct nfsd4_copy *copy),	\
> +	TP_ARGS(copy))
> +
> +DEFINE_COPY_EVENT(inter);
> +DEFINE_COPY_EVENT(intra);
> +DEFINE_COPY_EVENT(do_async);
> +
> +TRACE_EVENT(nfsd4_copy_done,
> +	TP_PROTO(
> +		const struct nfsd4_copy *copy,
> +		__be32 status
> +	),
> +	TP_ARGS(copy, status),
> +	TP_STRUCT__entry(
> +		__field(int, status)
> +		__field(bool, intra)
> +		__field(bool, async)
> +		__sockaddr(addr, sizeof(struct sockaddr_in6))
> +	),
> +	TP_fast_assign(
> +		__entry->status = be32_to_cpu(status);
> +		__entry->intra = test_bit(NFSD4_COPY_F_INTRA, &copy->cp_flags);
> +		__entry->async = !test_bit(NFSD4_COPY_F_SYNCHRONOUS, &copy->cp_flags);
> +		__assign_sockaddr(addr, &copy->cp_clp->cl_addr,
> +				sizeof(struct sockaddr_in6));
> +	),
> +	TP_printk("addr=%pISpc status=%d intra=%d async=%d ",
> +		__get_sockaddr(addr), __entry->status, __entry->intra, __entry->async
> +	)
> +);
> +#endif	/* CONFIG_NFS_V4_2 */
> +
>  #endif /* _NFSD_TRACE_H */
>  
>  #undef TRACE_INCLUDE_PATH
> -- 
> 2.39.3
>
diff mbox series

Patch

diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index 62f6aba6140b..9a780559073f 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -1760,6 +1760,7 @@  static int nfsd4_do_async_copy(void *data)
 	struct nfsd4_copy *copy = (struct nfsd4_copy *)data;
 	__be32 nfserr;
 
+	trace_nfsd4_copy_do_async(copy);
 	if (nfsd4_ssc_is_inter(copy)) {
 		struct file *filp;
 
@@ -1800,17 +1801,23 @@  nfsd4_copy(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 
 	copy->cp_clp = cstate->clp;
 	if (nfsd4_ssc_is_inter(copy)) {
+		trace_nfsd4_copy_inter(copy);
 		if (!inter_copy_offload_enable || nfsd4_copy_is_sync(copy)) {
 			status = nfserr_notsupp;
 			goto out;
 		}
 		status = nfsd4_setup_inter_ssc(rqstp, cstate, copy);
-		if (status)
+		if (status) {
+			trace_nfsd4_copy_done(copy, status);
 			return nfserr_offload_denied;
+		}
 	} else {
+		trace_nfsd4_copy_intra(copy);
 		status = nfsd4_setup_intra_ssc(rqstp, cstate, copy);
-		if (status)
+		if (status) {
+			trace_nfsd4_copy_done(copy, status);
 			return status;
+		}
 	}
 
 	memcpy(&copy->fh, &cstate->current_fh.fh_handle,
@@ -1847,6 +1854,7 @@  nfsd4_copy(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 				       copy->nf_dst->nf_file, true);
 	}
 out:
+	trace_nfsd4_copy_done(copy, status);
 	release_copy_files(copy);
 	return status;
 out_err:
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 803904348871..6256a77c95c9 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -1863,6 +1863,95 @@  TRACE_EVENT(nfsd_end_grace,
 	)
 );
 
+#ifdef CONFIG_NFS_V4_2
+DECLARE_EVENT_CLASS(nfsd4_copy_class,
+	TP_PROTO(
+		const struct nfsd4_copy *copy
+	),
+	TP_ARGS(copy),
+	TP_STRUCT__entry(
+		__field(bool, intra)
+		__field(bool, async)
+		__field(u32, src_cl_boot)
+		__field(u32, src_cl_id)
+		__field(u32, src_so_id)
+		__field(u32, src_si_generation)
+		__field(u32, dst_cl_boot)
+		__field(u32, dst_cl_id)
+		__field(u32, dst_so_id)
+		__field(u32, dst_si_generation)
+		__field(u64, src_cp_pos)
+		__field(u64, dst_cp_pos)
+		__field(u64, cp_count)
+		__sockaddr(addr, sizeof(struct sockaddr_in6))
+	),
+	TP_fast_assign(
+		const stateid_t *src_stp = &copy->cp_src_stateid;
+		const stateid_t *dst_stp = &copy->cp_dst_stateid;
+
+		__entry->intra = test_bit(NFSD4_COPY_F_INTRA, &copy->cp_flags);
+		__entry->async = !test_bit(NFSD4_COPY_F_SYNCHRONOUS, &copy->cp_flags);
+		__entry->src_cl_boot = src_stp->si_opaque.so_clid.cl_boot;
+		__entry->src_cl_id = src_stp->si_opaque.so_clid.cl_id;
+		__entry->src_so_id = src_stp->si_opaque.so_id;
+		__entry->src_si_generation = src_stp->si_generation;
+		__entry->dst_cl_boot = dst_stp->si_opaque.so_clid.cl_boot;
+		__entry->dst_cl_id = dst_stp->si_opaque.so_clid.cl_id;
+		__entry->dst_so_id = dst_stp->si_opaque.so_id;
+		__entry->dst_si_generation = dst_stp->si_generation;
+		__entry->src_cp_pos = copy->cp_src_pos;
+		__entry->dst_cp_pos = copy->cp_dst_pos;
+		__entry->cp_count = copy->cp_count;
+		__assign_sockaddr(addr, &copy->cp_clp->cl_addr,
+				sizeof(struct sockaddr_in6));
+	),
+	TP_printk("client=%pISpc intra=%d async=%d "
+		"src_stateid[si_generation:0x%x cl_boot:0x%x cl_id:0x%x so_id:0x%x] "
+		"dst_stateid[si_generation:0x%x cl_boot:0x%x cl_id:0x%x so_id:0x%x] "
+		"cp_src_pos=%llu cp_dst_pos=%llu cp_count=%llu",
+		__get_sockaddr(addr), __entry->intra, __entry->async,
+		__entry->src_si_generation, __entry->src_cl_boot,
+		__entry->src_cl_id, __entry->src_so_id,
+		__entry->dst_si_generation, __entry->dst_cl_boot,
+		__entry->dst_cl_id, __entry->dst_so_id,
+		__entry->src_cp_pos, __entry->dst_cp_pos, __entry->cp_count
+	)
+);
+
+#define DEFINE_COPY_EVENT(name)				\
+DEFINE_EVENT(nfsd4_copy_class, nfsd4_copy_##name,	\
+	TP_PROTO(const struct nfsd4_copy *copy),	\
+	TP_ARGS(copy))
+
+DEFINE_COPY_EVENT(inter);
+DEFINE_COPY_EVENT(intra);
+DEFINE_COPY_EVENT(do_async);
+
+TRACE_EVENT(nfsd4_copy_done,
+	TP_PROTO(
+		const struct nfsd4_copy *copy,
+		__be32 status
+	),
+	TP_ARGS(copy, status),
+	TP_STRUCT__entry(
+		__field(int, status)
+		__field(bool, intra)
+		__field(bool, async)
+		__sockaddr(addr, sizeof(struct sockaddr_in6))
+	),
+	TP_fast_assign(
+		__entry->status = be32_to_cpu(status);
+		__entry->intra = test_bit(NFSD4_COPY_F_INTRA, &copy->cp_flags);
+		__entry->async = !test_bit(NFSD4_COPY_F_SYNCHRONOUS, &copy->cp_flags);
+		__assign_sockaddr(addr, &copy->cp_clp->cl_addr,
+				sizeof(struct sockaddr_in6));
+	),
+	TP_printk("addr=%pISpc status=%d intra=%d async=%d ",
+		__get_sockaddr(addr), __entry->status, __entry->intra, __entry->async
+	)
+);
+#endif	/* CONFIG_NFS_V4_2 */
+
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH