Add trace points on destination server to track inter and intra
server copy operations.
Signed-off-by: Dai Ngo <[email protected]>
---
v2: rename trace points from nfsd4_trace_... to nfsd_trace_...
fix kernel test robot by removing ifdef CONFIG_NFS_V4_2 in trace.h
fs/nfsd/nfs4proc.c | 12 +++++--
fs/nfsd/trace.h | 87 ++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 97 insertions(+), 2 deletions(-)
diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index 62f6aba6140b..cac4528faa73 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_nfsd_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_nfsd_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_nfsd_copy_done(copy, status);
return nfserr_offload_denied;
+ }
} else {
+ trace_nfsd_copy_intra(copy);
status = nfsd4_setup_intra_ssc(rqstp, cstate, copy);
- if (status)
+ if (status) {
+ trace_nfsd_copy_done(copy, status);
return status;
+ }
}
memcpy(©->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_nfsd_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..fbc0ccb40424 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -1863,6 +1863,93 @@ TRACE_EVENT(nfsd_end_grace,
)
);
+DECLARE_EVENT_CLASS(nfsd_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 = ©->cp_src_stateid;
+ const stateid_t *dst_stp = ©->cp_dst_stateid;
+
+ __entry->intra = test_bit(NFSD4_COPY_F_INTRA, ©->cp_flags);
+ __entry->async = !test_bit(NFSD4_COPY_F_SYNCHRONOUS, ©->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, ©->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(nfsd_copy_class, nfsd_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(nfsd_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, ©->cp_flags);
+ __entry->async = !test_bit(NFSD4_COPY_F_SYNCHRONOUS, ©->cp_flags);
+ __assign_sockaddr(addr, ©->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 /* _NFSD_TRACE_H */
#undef TRACE_INCLUDE_PATH
--
2.39.3
> -----?ʼ?ԭ??-----
> ??????: Dai Ngo <[email protected]>
> ????ʱ??: 2023??9??1?? 3:36
> ?ռ???: [email protected]; [email protected]
> ????: [email protected]
> ????: [PATCH v2 1/1] NFSD: add trace points to track server copy progress
>
> Add trace points on destination server to track inter and intra server copy
> operations.
>
> Signed-off-by: Dai Ngo <[email protected]>
> ---
> v2: rename trace points from nfsd4_trace_... to nfsd_trace_...
> fix kernel test robot by removing ifdef CONFIG_NFS_V4_2 in trace.h
>
Hi, Dai
I'm testing this patch base on 7ba2090ca64ea1aa435744884124387db1fac70f via Fedora 38.
but got some oops message.
Pls have a look.
Regards,
- Chen
How to reproduce:
server:
trace-cmd record -e nfsd:nfsd_copy*
client
mount -o vers=4.2 192.168.122.212:/nfstest /mnt/test
mount -o vers=4.2 192.168.122.212:/nfsscratch /mnt/scratch
cp /mnt/test/some-file.tgz /mnt/scratch
[ 713.008623] CPU: 0 PID: 1562 Comm: nfsd Kdump: loaded Not tainted 6.5.0+ #14
[ 713.008660] Hardware name: Red Hat KVM/RHEL-AV, BIOS 1.13.0-2.module+el8.3.0+7353+9de0a3cc 04/01/2014
[ 713.008699] RIP: 0010:trace_event_raw_event_nfsd_copy_class+0xd6/0x140 [nfsd]
[ 713.008868] Code: 48 8b 53 20 48 89 50 30 48 8b 53 28 48 89 50 38 48 8b 53 30 48 89 50 40 48 8b b3 f8 00 00 00 48 8d 50 4c 48 8d 8e b8 00 00 00 <48> 8b b6 b8 00 00 00 48 89 70 4c 48 8b 41 08 48 89 42 08 48 8b 41
[ 713.008944] RSP: 0018:ff22381280edfd78 EFLAGS: 00010202
[ 713.008972] RAX: ff12ee8a8007701c RBX: ff12ee8a820988e0 RCX: 00000000000000b8
[ 713.009004] RDX: ff12ee8a80077068 RSI: 0000000000000000 RDI: ff22381280edfd78
[ 713.009036] RBP: ff12ee8a90afdf00 R08: 0000000000000001 R09: 0000000000000000
[ 713.009055] R10: 0000000000000000 R11: 0000000000038560 R12: ff22381280edfd78
[ 713.009064] R13: ff12ee8a959b4000 R14: 0000000000000000 R15: ff12ee8a820988c0
[ 713.009074] FS: 0000000000000000(0000) GS:ff12ee8afba00000(0000) knlGS:0000000000000000
[ 713.009084] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 713.009091] CR2: 00000000000000b8 CR3: 0000000110970004 CR4: 0000000000771ef0
[ 713.009104] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 713.009113] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 713.009123] PKRU: 55555554
[ 713.009127] Call Trace:
[ 713.009134] <TASK>
[ 713.009139] ? __die+0x1f/0x70
[ 713.009148] ? page_fault_oops+0x171/0x4f0
[ 713.009157] ? __kmem_cache_alloc_node+0x175/0x310
[ 713.009167] ? security_prepare_creds+0xc5/0xe0
[ 713.009177] ? exc_page_fault+0x7b/0x180
[ 713.009186] ? asm_exc_page_fault+0x22/0x30
[ 713.009195] ? trace_event_raw_event_nfsd_copy_class+0xd6/0x140 [nfsd]
[ 713.009237] ? trace_event_raw_event_nfsd_copy_class+0x4b/0x140 [nfsd]
[ 713.009274] nfsd4_copy+0x47d/0x6e0 [nfsd]
[ 713.009319] nfsd4_proc_compound+0x399/0x6f0 [nfsd]
[ 713.009360] ? __pfx_nfsd+0x10/0x10 [nfsd]
[ 713.009401] nfsd_dispatch+0x80/0x1b0 [nfsd]
[ 713.009442] svc_process_common+0x439/0x6e0 [sunrpc]
[ 713.009510] ? __pfx_nfsd_dispatch+0x10/0x10 [nfsd]
[ 713.009551] ? __pfx_nfsd+0x10/0x10 [nfsd]
[ 713.009599] svc_process+0x12d/0x170 [sunrpc]
[ 713.009890] nfsd+0x80/0xd0 [nfsd]
[ 713.010142] kthread+0xf0/0x120
[ 713.010352] ? __pfx_kthread+0x10/0x10
[ 713.010569] ret_from_fork+0x2d/0x50
[ 713.010771] ? __pfx_kthread+0x10/0x10
[ 713.010972] ret_from_fork_asm+0x1b/0x30
[ 713.011176] </TASK>
[ 713.011374] Modules linked in: rpcsec_gss_krb5 rpcrdma rdma_cm iw_cm ib_cm ib_core nfsd auth_rpcgss nfs_acl lockd grace nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 rfkill sunrpc ip_set nf_tables nfnetlink qrtr intel_rapl_msr intel_rapl_common nfit libnvdimm kvm_intel kvm snd_hda_codec_generic ledtrig_audio snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi snd_hda_codec iTCO_wdt irqbypass intel_pmc_bxt snd_hda_core iTCO_vendor_support snd_hwdep snd_pcm snd_timer snd i2c_i801 i2c_smbus pcspkr lpc_ich soundcore virtio_balloon joydev fuse loop zram xfs crct10dif_pclmul crc32_pclmul crc32c_intel polyval_clmulni polyval_generic ghash_clmulni_intel qxl sha512_ssse3 drm_ttm_helper virtio_net ttm virtio_blk net_failover virtio_console failover serio_raw scsi_dh_rdac scsi_dh_emc scsi_dh_alua dm_multipath qemu_fw_cfg
[ 713.013232] CR2: 00000000000000b8
[ 713.013460] ---[ end trace 0000000000000000 ]---
[ 713.013688] RIP: 0010:trace_event_raw_event_nfsd_copy_class+0xd6/0x140 [nfsd]
[ 713.013944] Code: 48 8b 53 20 48 89 50 30 48 8b 53 28 48 89 50 38 48 8b 53 30 48 89 50 40 48 8b b3 f8 00 00 00 48 8d 50 4c 48 8d 8e b8 00 00 00 <48> 8b b6 b8 00 00 00 48 89 70 4c 48 8b 41 08 48 89 42 08 48 8b 41
[ 713.014406] RSP: 0018:ff22381280edfd78 EFLAGS: 00010202
[ 713.014644] RAX: ff12ee8a8007701c RBX: ff12ee8a820988e0 RCX: 00000000000000b8
[ 713.014880] RDX: ff12ee8a80077068 RSI: 0000000000000000 RDI: ff22381280edfd78
[ 713.015117] RBP: ff12ee8a90afdf00 R08: 0000000000000001 R09: 0000000000000000
[ 713.015351] R10: 0000000000000000 R11: 0000000000038560 R12: ff22381280edfd78
[ 713.015590] R13: ff12ee8a959b4000 R14: 0000000000000000 R15: ff12ee8a820988c0
[ 713.015821] FS: 0000000000000000(0000) GS:ff12ee8afba00000(0000) knlGS:0000000000000000
[ 713.016057] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 713.016296] CR2: 00000000000000b8 CR3: 0000000110970004 CR4: 0000000000771ef0
[ 713.016536] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 713.016778] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 713.017019] PKRU: 55555554
[ 713.017263] note: nfsd[1562] exited with irqs disabled
[ 713.017532] note: nfsd[1562] exited with preempt_count 2
[ 835.057703] ------------[ cut here ]------------
[ 835.058376] WARNING: CPU: 2 PID: 1712 at kernel/trace/ring_buffer.c:5304 reset_disabled_cpu_buffer+0x254/0x270
[ 835.058643] Modules linked in: rpcsec_gss_krb5 rpcrdma rdma_cm iw_cm ib_cm ib_core nfsd auth_rpcgss nfs_acl lockd grace nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 rfkill sunrpc ip_set nf_tables nfnetlink qrtr intel_rapl_msr intel_rapl_common nfit libnvdimm kvm_intel kvm snd_hda_codec_generic ledtrig_audio snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi snd_hda_codec iTCO_wdt irqbypass intel_pmc_bxt snd_hda_core iTCO_vendor_support snd_hwdep snd_pcm snd_timer snd i2c_i801 i2c_smbus pcspkr lpc_ich soundcore virtio_balloon joydev fuse loop zram xfs crct10dif_pclmul crc32_pclmul crc32c_intel polyval_clmulni polyval_generic ghash_clmulni_intel qxl sha512_ssse3 drm_ttm_helper virtio_net ttm virtio_blk net_failover virtio_console failover serio_raw scsi_dh_rdac scsi_dh_emc scsi_dh_alua dm_multipath qemu_fw_cfg
[ 835.060996] CPU: 2 PID: 1712 Comm: trace-cmd Kdump: loaded Tainted: G D 6.5.0+ #14
[ 835.061311] Hardware name: Red Hat KVM/RHEL-AV, BIOS 1.13.0-2.module+el8.3.0+7353+9de0a3cc 04/01/2014
[ 835.061633] RIP: 0010:reset_disabled_cpu_buffer+0x254/0x270
[ 835.061952] Code: 28 01 00 00 00 00 00 00 4c 89 e7 e8 56 13 d7 00 90 5b 48 89 ee 4c 89 ef 5d 41 5c 41 5d e9 c4 0a d7 00 48 8b 43 10 f0 ff 40 08 <0f> 0b eb e3 89 c6 4c 89 e7 e8 2e 16 d7 00 90 e9 d4 fd ff ff 0f 1f
[ 835.062611] RSP: 0018:ff2238128073bbd0 EFLAGS: 00010002
[ 835.062945] RAX: ff12ee8a8003e700 RBX: ff12ee8a80040c00 RCX: 0000000000000000
[ 835.063282] RDX: 0000000000000001 RSI: 0000000000000000 RDI: 0000000000000000
[ 835.063619] RBP: 0000000000000206 R08: 0000000000000000 R09: 0000000000000000
[ 835.063941] R10: 0000000000000001 R11: 0000000000000100 R12: ff12ee8a8003e700
[ 835.064260] R13: ff12ee8a80040c18 R14: ff12ee8a82d4ac98 R15: ff12ee8a82d4ac00
[ 835.064576] FS: 00007f433e809780(0000) GS:ff12ee8afbb00000(0000) knlGS:0000000000000000
[ 835.064884] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 835.065190] CR2: 00005635914ef0f8 CR3: 0000000110970006 CR4: 0000000000771ee0
[ 835.065495] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 835.065788] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 835.066082] PKRU: 55555554
[ 835.066374] Call Trace:
[ 835.066666] <TASK>
[ 835.066943] ? reset_disabled_cpu_buffer+0x254/0x270
[ 835.067216] ? __warn+0x7d/0x130
[ 835.067488] ? reset_disabled_cpu_buffer+0x254/0x270
[ 835.067761] ? report_bug+0x18d/0x1c0
[ 835.068029] ? handle_bug+0x3c/0x80
[ 835.068294] ? exc_invalid_op+0x13/0x60
[ 835.068558] ? asm_exc_invalid_op+0x16/0x20
[ 835.068827] ? reset_disabled_cpu_buffer+0x254/0x270
[ 835.069087] ring_buffer_reset_online_cpus+0x7e/0xc0
[ 835.069346] tracing_reset_online_cpus+0x6e/0xc0
[ 835.069610] tracing_open+0x143/0x160
[ 835.069864] ? __pfx_tracing_open+0x10/0x10
[ 835.070120] do_dentry_open+0x200/0x4f0
[ 835.070371] path_openat+0xafe/0x1160
[ 835.070627] do_filp_open+0xaf/0x160
[ 835.070880] do_sys_openat2+0xab/0xe0
[ 835.071129] ? kmem_cache_free+0x1e/0x3e0
[ 835.071380] __x64_sys_openat+0x53/0xa0
[ 835.071636] do_syscall_64+0x59/0x90
[ 835.071883] ? syscall_exit_to_user_mode+0x27/0x40
[ 835.072128] ? do_syscall_64+0x68/0x90
[ 835.072367] ? syscall_exit_to_user_mode+0x27/0x40
[ 835.072604] ? do_syscall_64+0x68/0x90
[ 835.072825] entry_SYSCALL_64_after_hwframe+0x6e/0xd8
[ 835.073044] RIP: 0033:0x7f433e918015
[ 835.073254] Code: 83 e2 40 75 50 89 f0 f7 d0 a9 00 00 41 00 74 45 80 3d d6 c5 0d 00 00 74 60 89 da 4c 89 e6 bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 7f 00 00 00 48 8b 55 b8 64 48 2b 14 25 28
[ 835.073690] RSP: 002b:00007ffd20591490 EFLAGS: 00000202 ORIG_RAX: 0000000000000101
[ 835.073904] RAX: ffffffffffffffda RBX: 0000000000000241 RCX: 00007f433e918015
[ 835.074116] RDX: 0000000000000241 RSI: 00005635914db9c0 RDI: 00000000ffffff9c
[ 835.074325] RBP: 00007ffd20591500 R08: 0000000000000004 R09: 0000000000000001
[ 835.074532] R10: 00000000000001b6 R11: 0000000000000202 R12: 00005635914db9c0
[ 835.074736] R13: 000056359037a976 R14: 000056359037a976 R15: 0000000000000001
[ 835.074933] </TASK>
[ 835.075121] ---[ end trace 0000000000000000 ]---