From 861e1671bc2eed063aa624cdb2be8cfff16331c9 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Mon, 23 Dec 2019 10:28:33 -0500 Subject: NFS: Introduce trace events triggered by page writeback errors Try to capture the reason for the writeback path tagging an error on a page. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- fs/nfs/nfstrace.h | 45 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 45 insertions(+) (limited to 'fs/nfs/nfstrace.h') diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h index f64a33d2a1d1..4d6eb1703943 100644 --- a/fs/nfs/nfstrace.h +++ b/fs/nfs/nfstrace.h @@ -989,6 +989,51 @@ TRACE_EVENT(nfs_writeback_done, ) ); +DECLARE_EVENT_CLASS(nfs_page_error_class, + TP_PROTO( + const struct nfs_page *req, + int error + ), + + TP_ARGS(req, error), + + TP_STRUCT__entry( + __field(const void *, req) + __field(pgoff_t, index) + __field(unsigned int, offset) + __field(unsigned int, pgbase) + __field(unsigned int, bytes) + __field(int, error) + ), + + TP_fast_assign( + __entry->req = req; + __entry->index = req->wb_index; + __entry->offset = req->wb_offset; + __entry->pgbase = req->wb_pgbase; + __entry->bytes = req->wb_bytes; + __entry->error = error; + ), + + TP_printk( + "req=%p index=%lu offset=%u pgbase=%u bytes=%u error=%d", + __entry->req, __entry->index, __entry->offset, + __entry->pgbase, __entry->bytes, __entry->error + ) +); + +#define DEFINE_NFS_PAGEERR_EVENT(name) \ + DEFINE_EVENT(nfs_page_error_class, name, \ + TP_PROTO( \ + const struct nfs_page *req, \ + int error \ + ), \ + TP_ARGS(req, error)) + +DEFINE_NFS_PAGEERR_EVENT(nfs_write_error); +DEFINE_NFS_PAGEERR_EVENT(nfs_comp_error); +DEFINE_NFS_PAGEERR_EVENT(nfs_commit_error); + TRACE_EVENT(nfs_initiate_commit, TP_PROTO( const struct nfs_commit_data *data -- cgit v1.2.3 From 2343172d34c6296f79b404a0eb291e15ab19e5ca Mon Sep 17 00:00:00 2001 From: Trond Myklebust Date: Mon, 6 Jan 2020 15:25:08 -0500 Subject: NFS: Clean up generic file read tracepoints Clean up the generic file read tracepoints so they do pass the full structures as arguments. Also ensure we report the number of bytes actually read. Signed-off-by: Trond Myklebust Signed-off-by: Anna Schumaker --- fs/nfs/nfstrace.h | 56 ++++++++++++++++++++++++++++++++----------------------- fs/nfs/read.c | 5 ++--- 2 files changed, 35 insertions(+), 26 deletions(-) (limited to 'fs/nfs/nfstrace.h') diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h index 4d6eb1703943..0710b91f82d3 100644 --- a/fs/nfs/nfstrace.h +++ b/fs/nfs/nfstrace.h @@ -820,75 +820,85 @@ TRACE_EVENT(nfs_sillyrename_unlink, TRACE_EVENT(nfs_initiate_read, TP_PROTO( - const struct inode *inode, - loff_t offset, unsigned long count + const struct nfs_pgio_header *hdr ), - TP_ARGS(inode, offset, count), + TP_ARGS(hdr), TP_STRUCT__entry( - __field(loff_t, offset) - __field(unsigned long, count) __field(dev_t, dev) __field(u32, fhandle) __field(u64, fileid) + __field(loff_t, offset) + __field(u32, count) ), TP_fast_assign( + const struct inode *inode = hdr->inode; const struct nfs_inode *nfsi = NFS_I(inode); + const struct nfs_fh *fh = hdr->args.fh ? + hdr->args.fh : &nfsi->fh; - __entry->offset = offset; - __entry->count = count; + __entry->offset = hdr->args.offset; + __entry->count = hdr->args.count; __entry->dev = inode->i_sb->s_dev; __entry->fileid = nfsi->fileid; - __entry->fhandle = nfs_fhandle_hash(&nfsi->fh); + __entry->fhandle = nfs_fhandle_hash(fh); ), TP_printk( "fileid=%02x:%02x:%llu fhandle=0x%08x " - "offset=%lld count=%lu", + "offset=%lld count=%u", MAJOR(__entry->dev), MINOR(__entry->dev), (unsigned long long)__entry->fileid, __entry->fhandle, - __entry->offset, __entry->count + (long long)__entry->offset, __entry->count ) ); TRACE_EVENT(nfs_readpage_done, TP_PROTO( - const struct inode *inode, - int status, loff_t offset, bool eof + const struct rpc_task *task, + const struct nfs_pgio_header *hdr ), - TP_ARGS(inode, status, offset, eof), + TP_ARGS(task, hdr), TP_STRUCT__entry( - __field(int, status) - __field(loff_t, offset) - __field(bool, eof) __field(dev_t, dev) __field(u32, fhandle) __field(u64, fileid) + __field(loff_t, offset) + __field(u32, arg_count) + __field(u32, res_count) + __field(bool, eof) + __field(int, status) ), TP_fast_assign( + const struct inode *inode = hdr->inode; const struct nfs_inode *nfsi = NFS_I(inode); - - __entry->status = status; - __entry->offset = offset; - __entry->eof = eof; + const struct nfs_fh *fh = hdr->args.fh ? + hdr->args.fh : &nfsi->fh; + + __entry->status = task->tk_status; + __entry->offset = hdr->args.offset; + __entry->arg_count = hdr->args.count; + __entry->res_count = hdr->res.count; + __entry->eof = hdr->res.eof; __entry->dev = inode->i_sb->s_dev; __entry->fileid = nfsi->fileid; - __entry->fhandle = nfs_fhandle_hash(&nfsi->fh); + __entry->fhandle = nfs_fhandle_hash(fh); ), TP_printk( "fileid=%02x:%02x:%llu fhandle=0x%08x " - "offset=%lld status=%d%s", + "offset=%lld count=%u res=%u status=%d%s", MAJOR(__entry->dev), MINOR(__entry->dev), (unsigned long long)__entry->fileid, __entry->fhandle, - __entry->offset, __entry->status, + (long long)__entry->offset, __entry->arg_count, + __entry->res_count, __entry->status, __entry->eof ? " eof" : "" ) ); diff --git a/fs/nfs/read.c b/fs/nfs/read.c index cfe0b586eadd..12deb3bdb2a0 100644 --- a/fs/nfs/read.c +++ b/fs/nfs/read.c @@ -214,7 +214,7 @@ static void nfs_initiate_read(struct nfs_pgio_header *hdr, task_setup_data->flags |= swap_flags; rpc_ops->read_setup(hdr, msg); - trace_nfs_initiate_read(inode, hdr->io_start, hdr->good_bytes); + trace_nfs_initiate_read(hdr); } static void @@ -247,8 +247,7 @@ static int nfs_readpage_done(struct rpc_task *task, return status; nfs_add_stats(inode, NFSIOS_SERVERREADBYTES, hdr->res.count); - trace_nfs_readpage_done(inode, task->tk_status, - hdr->args.offset, hdr->res.eof); + trace_nfs_readpage_done(task, hdr); if (task->tk_status == -ESTALE) { set_bit(NFS_INO_STALE, &NFS_I(inode)->flags); -- cgit v1.2.3 From 5bb2a7cb9fe58d2b1efedd6058d442c7871c45ec Mon Sep 17 00:00:00 2001 From: Trond Myklebust Date: Mon, 6 Jan 2020 15:25:09 -0500 Subject: NFS: Clean up generic writeback tracepoints Clean up the generic writeback tracepoints so they do pass the full structures as arguments. Also ensure we report the number of bytes actually written. Signed-off-by: Trond Myklebust Signed-off-by: Anna Schumaker --- fs/nfs/nfstrace.h | 73 +++++++++++++++++++++++++++++++------------------------ fs/nfs/write.c | 6 ++--- 2 files changed, 43 insertions(+), 36 deletions(-) (limited to 'fs/nfs/nfstrace.h') diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h index 0710b91f82d3..7ed75b3b7aac 100644 --- a/fs/nfs/nfstrace.h +++ b/fs/nfs/nfstrace.h @@ -915,87 +915,96 @@ TRACE_DEFINE_ENUM(NFS_FILE_SYNC); TRACE_EVENT(nfs_initiate_write, TP_PROTO( - const struct inode *inode, - loff_t offset, unsigned long count, - enum nfs3_stable_how stable + const struct nfs_pgio_header *hdr ), - TP_ARGS(inode, offset, count, stable), + TP_ARGS(hdr), TP_STRUCT__entry( - __field(loff_t, offset) - __field(unsigned long, count) - __field(enum nfs3_stable_how, stable) __field(dev_t, dev) __field(u32, fhandle) __field(u64, fileid) + __field(loff_t, offset) + __field(u32, count) + __field(enum nfs3_stable_how, stable) ), TP_fast_assign( + const struct inode *inode = hdr->inode; const struct nfs_inode *nfsi = NFS_I(inode); + const struct nfs_fh *fh = hdr->args.fh ? + hdr->args.fh : &nfsi->fh; - __entry->offset = offset; - __entry->count = count; - __entry->stable = stable; + __entry->offset = hdr->args.offset; + __entry->count = hdr->args.count; + __entry->stable = hdr->args.stable; __entry->dev = inode->i_sb->s_dev; __entry->fileid = nfsi->fileid; - __entry->fhandle = nfs_fhandle_hash(&nfsi->fh); + __entry->fhandle = nfs_fhandle_hash(fh); ), TP_printk( "fileid=%02x:%02x:%llu fhandle=0x%08x " - "offset=%lld count=%lu stable=%s", + "offset=%lld count=%u stable=%s", MAJOR(__entry->dev), MINOR(__entry->dev), (unsigned long long)__entry->fileid, __entry->fhandle, - __entry->offset, __entry->count, + (long long)__entry->offset, __entry->count, nfs_show_stable(__entry->stable) ) ); TRACE_EVENT(nfs_writeback_done, TP_PROTO( - const struct inode *inode, - int status, - loff_t offset, - struct nfs_writeverf *writeverf + const struct rpc_task *task, + const struct nfs_pgio_header *hdr ), - TP_ARGS(inode, status, offset, writeverf), + TP_ARGS(task, hdr), TP_STRUCT__entry( - __field(int, status) - __field(loff_t, offset) - __field(enum nfs3_stable_how, stable) - __field(unsigned long long, verifier) __field(dev_t, dev) __field(u32, fhandle) __field(u64, fileid) + __field(loff_t, offset) + __field(u32, arg_count) + __field(u32, res_count) + __field(int, status) + __field(enum nfs3_stable_how, stable) + __array(char, verifier, NFS4_VERIFIER_SIZE) ), TP_fast_assign( + const struct inode *inode = hdr->inode; const struct nfs_inode *nfsi = NFS_I(inode); + const struct nfs_fh *fh = hdr->args.fh ? + hdr->args.fh : &nfsi->fh; + const struct nfs_writeverf *verf = hdr->res.verf; - __entry->status = status; - __entry->offset = offset; - __entry->stable = writeverf->committed; - memcpy(&__entry->verifier, &writeverf->verifier, - sizeof(__entry->verifier)); + __entry->status = task->tk_status; + __entry->offset = hdr->args.offset; + __entry->arg_count = hdr->args.count; + __entry->res_count = hdr->res.count; + __entry->stable = verf->committed; + memcpy(__entry->verifier, + &verf->verifier, + NFS4_VERIFIER_SIZE); __entry->dev = inode->i_sb->s_dev; __entry->fileid = nfsi->fileid; - __entry->fhandle = nfs_fhandle_hash(&nfsi->fh); + __entry->fhandle = nfs_fhandle_hash(fh); ), TP_printk( "fileid=%02x:%02x:%llu fhandle=0x%08x " - "offset=%lld status=%d stable=%s " - "verifier 0x%016llx", + "offset=%lld count=%u res=%u status=%d stable=%s " + "verifier=%s", MAJOR(__entry->dev), MINOR(__entry->dev), (unsigned long long)__entry->fileid, __entry->fhandle, - __entry->offset, __entry->status, + (long long)__entry->offset, __entry->arg_count, + __entry->res_count, __entry->status, nfs_show_stable(__entry->stable), - __entry->verifier + __print_hex_str(__entry->verifier, NFS4_VERIFIER_SIZE) ) ); diff --git a/fs/nfs/write.c b/fs/nfs/write.c index c86fc9efd99b..cd837744a732 100644 --- a/fs/nfs/write.c +++ b/fs/nfs/write.c @@ -1414,8 +1414,7 @@ static void nfs_initiate_write(struct nfs_pgio_header *hdr, task_setup_data->priority = priority; rpc_ops->write_setup(hdr, msg, &task_setup_data->rpc_client); - trace_nfs_initiate_write(hdr->inode, hdr->io_start, hdr->good_bytes, - hdr->args.stable); + trace_nfs_initiate_write(hdr); } /* If a nfs_flush_* function fails, it should remove reqs from @head and @@ -1579,8 +1578,7 @@ static int nfs_writeback_done(struct rpc_task *task, return status; nfs_add_stats(inode, NFSIOS_SERVERWRITTENBYTES, hdr->res.count); - trace_nfs_writeback_done(inode, task->tk_status, - hdr->args.offset, hdr->res.verf); + trace_nfs_writeback_done(task, hdr); if (hdr->res.verf->committed < hdr->args.stable && task->tk_status >= 0) { -- cgit v1.2.3 From 7bdd297ea6e695f27be67cb99b1fea1ff83e38e4 Mon Sep 17 00:00:00 2001 From: Trond Myklebust Date: Mon, 6 Jan 2020 15:25:10 -0500 Subject: NFS: Clean up generic file commit tracepoint Clean up the generic file commit tracepoints to use a 64-bit value for the verifier, and to display the pNFS filehandle, if it exists. Signed-off-by: Trond Myklebust Signed-off-by: Anna Schumaker --- fs/nfs/nfstrace.h | 42 ++++++++++++++++++++++++++---------------- fs/nfs/write.c | 2 +- 2 files changed, 27 insertions(+), 17 deletions(-) (limited to 'fs/nfs/nfstrace.h') diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h index 7ed75b3b7aac..a543573e038f 100644 --- a/fs/nfs/nfstrace.h +++ b/fs/nfs/nfstrace.h @@ -1061,71 +1061,81 @@ TRACE_EVENT(nfs_initiate_commit, TP_ARGS(data), TP_STRUCT__entry( - __field(loff_t, offset) - __field(unsigned long, count) __field(dev_t, dev) __field(u32, fhandle) __field(u64, fileid) + __field(loff_t, offset) + __field(u32, count) ), TP_fast_assign( const struct inode *inode = data->inode; const struct nfs_inode *nfsi = NFS_I(inode); + const struct nfs_fh *fh = data->args.fh ? + data->args.fh : &nfsi->fh; __entry->offset = data->args.offset; __entry->count = data->args.count; __entry->dev = inode->i_sb->s_dev; __entry->fileid = nfsi->fileid; - __entry->fhandle = nfs_fhandle_hash(&nfsi->fh); + __entry->fhandle = nfs_fhandle_hash(fh); ), TP_printk( "fileid=%02x:%02x:%llu fhandle=0x%08x " - "offset=%lld count=%lu", + "offset=%lld count=%u", MAJOR(__entry->dev), MINOR(__entry->dev), (unsigned long long)__entry->fileid, __entry->fhandle, - __entry->offset, __entry->count + (long long)__entry->offset, __entry->count ) ); TRACE_EVENT(nfs_commit_done, TP_PROTO( + const struct rpc_task *task, const struct nfs_commit_data *data ), - TP_ARGS(data), + TP_ARGS(task, data), TP_STRUCT__entry( - __field(int, status) - __field(loff_t, offset) - __field(unsigned long long, verifier) __field(dev_t, dev) __field(u32, fhandle) __field(u64, fileid) + __field(loff_t, offset) + __field(int, status) + __field(enum nfs3_stable_how, stable) + __array(char, verifier, NFS4_VERIFIER_SIZE) ), TP_fast_assign( const struct inode *inode = data->inode; const struct nfs_inode *nfsi = NFS_I(inode); + const struct nfs_fh *fh = data->args.fh ? + data->args.fh : &nfsi->fh; + const struct nfs_writeverf *verf = data->res.verf; - __entry->status = data->res.op_status; + __entry->status = task->tk_status; __entry->offset = data->args.offset; - memcpy(&__entry->verifier, &data->verf.verifier, - sizeof(__entry->verifier)); + __entry->stable = verf->committed; + memcpy(__entry->verifier, + &verf->verifier, + NFS4_VERIFIER_SIZE); __entry->dev = inode->i_sb->s_dev; __entry->fileid = nfsi->fileid; - __entry->fhandle = nfs_fhandle_hash(&nfsi->fh); + __entry->fhandle = nfs_fhandle_hash(fh); ), TP_printk( "fileid=%02x:%02x:%llu fhandle=0x%08x " - "offset=%lld status=%d verifier 0x%016llx", + "offset=%lld status=%d stable=%s verifier=%s", MAJOR(__entry->dev), MINOR(__entry->dev), (unsigned long long)__entry->fileid, __entry->fhandle, - __entry->offset, __entry->status, - __entry->verifier + (long long)__entry->offset, __entry->status, + nfs_show_stable(__entry->stable), + __print_hex_str(__entry->verifier, NFS4_VERIFIER_SIZE) ) ); diff --git a/fs/nfs/write.c b/fs/nfs/write.c index cd837744a732..83f92a4d65dc 100644 --- a/fs/nfs/write.c +++ b/fs/nfs/write.c @@ -1833,7 +1833,7 @@ static void nfs_commit_done(struct rpc_task *task, void *calldata) /* Call the NFS version-specific code */ NFS_PROTO(data->inode)->commit_done(task, data); - trace_nfs_commit_done(data); + trace_nfs_commit_done(task, data); } static void nfs_commit_release_pages(struct nfs_commit_data *data) -- cgit v1.2.3 From e8194b7dd39ec5423c32a43542f8348a9bd6956f Mon Sep 17 00:00:00 2001 From: Trond Myklebust Date: Mon, 6 Jan 2020 15:25:12 -0500 Subject: NFS: Improve tracing of permission calls On exit from nfs_do_access(), record the mask representing the requested permissions, as well as the server-supplied set of access rights for this user. Signed-off-by: Trond Myklebust Signed-off-by: Anna Schumaker --- fs/nfs/dir.c | 4 ++-- fs/nfs/nfstrace.h | 61 ++++++++++++++++++++++++++++++++++++++++++++++++++++++- 2 files changed, 62 insertions(+), 3 deletions(-) (limited to 'fs/nfs/nfstrace.h') diff --git a/fs/nfs/dir.c b/fs/nfs/dir.c index e180033e35cf..372c16b3042c 100644 --- a/fs/nfs/dir.c +++ b/fs/nfs/dir.c @@ -2476,7 +2476,7 @@ static int nfs_do_access(struct inode *inode, const struct cred *cred, int mask) { struct nfs_access_entry cache; bool may_block = (mask & MAY_NOT_BLOCK) == 0; - int cache_mask; + int cache_mask = -1; int status; trace_nfs_access_enter(inode); @@ -2515,7 +2515,7 @@ out_cached: if ((mask & ~cache_mask & (MAY_READ | MAY_WRITE | MAY_EXEC)) != 0) status = -EACCES; out: - trace_nfs_access_exit(inode, status); + trace_nfs_access_exit(inode, mask, cache_mask, status); return status; } diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h index a543573e038f..f8d677dd6705 100644 --- a/fs/nfs/nfstrace.h +++ b/fs/nfs/nfstrace.h @@ -198,7 +198,66 @@ DEFINE_NFS_INODE_EVENT_DONE(nfs_writeback_inode_exit); DEFINE_NFS_INODE_EVENT(nfs_fsync_enter); DEFINE_NFS_INODE_EVENT_DONE(nfs_fsync_exit); DEFINE_NFS_INODE_EVENT(nfs_access_enter); -DEFINE_NFS_INODE_EVENT_DONE(nfs_access_exit); + +TRACE_EVENT(nfs_access_exit, + TP_PROTO( + const struct inode *inode, + unsigned int mask, + unsigned int permitted, + int error + ), + + TP_ARGS(inode, mask, permitted, error), + + TP_STRUCT__entry( + __field(unsigned long, error) + __field(dev_t, dev) + __field(u32, fhandle) + __field(unsigned char, type) + __field(u64, fileid) + __field(u64, version) + __field(loff_t, size) + __field(unsigned long, nfsi_flags) + __field(unsigned long, cache_validity) + __field(unsigned int, mask) + __field(unsigned int, permitted) + ), + + TP_fast_assign( + const struct nfs_inode *nfsi = NFS_I(inode); + __entry->error = error < 0 ? -error : 0; + __entry->dev = inode->i_sb->s_dev; + __entry->fileid = nfsi->fileid; + __entry->fhandle = nfs_fhandle_hash(&nfsi->fh); + __entry->type = nfs_umode_to_dtype(inode->i_mode); + __entry->version = inode_peek_iversion_raw(inode); + __entry->size = i_size_read(inode); + __entry->nfsi_flags = nfsi->flags; + __entry->cache_validity = nfsi->cache_validity; + __entry->mask = mask; + __entry->permitted = permitted; + ), + + TP_printk( + "error=%ld (%s) fileid=%02x:%02x:%llu fhandle=0x%08x " + "type=%u (%s) version=%llu size=%lld " + "cache_validity=0x%lx (%s) nfs_flags=0x%lx (%s) " + "mask=0x%x permitted=0x%x", + -__entry->error, nfs_show_status(__entry->error), + MAJOR(__entry->dev), MINOR(__entry->dev), + (unsigned long long)__entry->fileid, + __entry->fhandle, + __entry->type, + nfs_show_file_type(__entry->type), + (unsigned long long)__entry->version, + (long long)__entry->size, + __entry->cache_validity, + nfs_show_cache_validity(__entry->cache_validity), + __entry->nfsi_flags, + nfs_show_nfsi_flags(__entry->nfsi_flags), + __entry->mask, __entry->permitted + ) +); TRACE_DEFINE_ENUM(LOOKUP_FOLLOW); TRACE_DEFINE_ENUM(LOOKUP_DIRECTORY); -- cgit v1.2.3