> On Oct 7, 2021, at 9:05 AM, David Wysochanski <dwysocha@xxxxxxxxxx> wrote: > > On Tue, Oct 5, 2021 at 1:14 PM Chuck Lever <chuck.lever@xxxxxxxxxx> wrote: > > > > There are two new events that report slightly different information > > for readpage and readpages. > > > > For readpage: > > fsx-1387 [006] 380.761896: nfs_aops_readpage: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355910932437 page_index=32 > > > > The index of a synchronous single-page read is reported. > > > > For readpages: > > > > fsx-1387 [006] 380.760847: nfs_aops_readpages: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355909932456 nr_pages=3 > > > > The count of pages requested is reported. readpages does not wait > > for the READ requests to complete. > > > > Signed-off-by: Chuck Lever <chuck.lever@xxxxxxxxxx> > > --- > > fs/nfs/nfstrace.h | 70 +++++++++++++++++++++++++++++++++++++++++++++++++++++ > > fs/nfs/read.c | 8 ++---- > > 2 files changed, 72 insertions(+), 6 deletions(-) > > > > diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h > > index e9be65b52bfe..0534d090ee55 100644 > > --- a/fs/nfs/nfstrace.h > > +++ b/fs/nfs/nfstrace.h > > @@ -862,6 +862,76 @@ TRACE_EVENT(nfs_sillyrename_unlink, > > ) > > ); > > > > +TRACE_EVENT(nfs_aops_readpage, > > + TP_PROTO( > > + const struct inode *inode, > > + struct page *page > > + ), > > + > > + TP_ARGS(inode, page), > > + > > + TP_STRUCT__entry( > > + __field(dev_t, dev) > > + __field(u32, fhandle) > > + __field(u64, fileid) > > + __field(u64, version) > > + __field(pgoff_t, index) > > + ), > > + > > + TP_fast_assign( > > + const struct nfs_inode *nfsi = NFS_I(inode); > > + > > + __entry->dev = inode->i_sb->s_dev; > > + __entry->fileid = nfsi->fileid; > > + __entry->fhandle = nfs_fhandle_hash(&nfsi->fh); > > + __entry->version = inode_peek_iversion_raw(inode); > > + __entry->index = page_index(page); > > + ), > > + > > + TP_printk( > > + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu page_index=%lu", > > + MAJOR(__entry->dev), MINOR(__entry->dev), > > + (unsigned long long)__entry->fileid, > > + __entry->fhandle, __entry->version, > > + __entry->index > > + ) > > +); > > + > > +TRACE_EVENT(nfs_aops_readpages, > > + TP_PROTO( > > + const struct inode *inode, > > + unsigned int nr_pages > > + ), > > + > > + TP_ARGS(inode, nr_pages), > > + > > + TP_STRUCT__entry( > > + __field(dev_t, dev) > > + __field(u32, fhandle) > > + __field(u64, fileid) > > + __field(u64, version) > > + __field(unsigned int, nr_pages) > > + ), > > + > > + TP_fast_assign( > > + const struct nfs_inode *nfsi = NFS_I(inode); > > + > > + __entry->dev = inode->i_sb->s_dev; > > + __entry->fileid = nfsi->fileid; > > + __entry->fhandle = nfs_fhandle_hash(&nfsi->fh); > > + __entry->version = inode_peek_iversion_raw(inode); > > + __entry->nr_pages = nr_pages; > > + ), > > + > > + TP_printk( > > + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu nr_pages=%u", > > + MAJOR(__entry->dev), MINOR(__entry->dev), > > + (unsigned long long)__entry->fileid, > > + __entry->fhandle, __entry->version, > > + __entry->nr_pages > > + ) > > +); > > + > > TRACE_EVENT(nfs_initiate_read, > > TP_PROTO( > > const struct nfs_pgio_header *hdr > > diff --git a/fs/nfs/read.c b/fs/nfs/read.c > > index 08d6cc57cbc3..94690eda2a88 100644 > > --- a/fs/nfs/read.c > > +++ b/fs/nfs/read.c > > @@ -337,8 +337,7 @@ int nfs_readpage(struct file *file, struct page *page) > > struct inode *inode = page_file_mapping(page)->host; > > int ret; > > > > - dprintk("NFS: nfs_readpage (%p %ld@%lu)\n", > > - page, PAGE_SIZE, page_index(page)); > > + trace_nfs_aops_readpage(inode, page); > > nfs_inc_stats(inode, NFSIOS_VFSREADPAGE); > > > > /* > > @@ -403,10 +402,7 @@ int nfs_readpages(struct file *file, struct address_space *mapping, > > struct inode *inode = mapping->host; > > int ret; > > > > - dprintk("NFS: nfs_readpages (%s/%Lu %d)\n", > > - inode->i_sb->s_id, > > - (unsigned long long)NFS_FILEID(inode), > > - nr_pages); > > + trace_nfs_aops_readpages(inode, nr_pages); > > nfs_inc_stats(inode, NFSIOS_VFSREADPAGES); > > > > ret = -ESTALE; > > > > > > I added this on top of my fscache patches and have been testing. > Should we be tracing (only?) the return point with the return > value? The purpose of the entry point is: you get a timestamp, filehandle information, and you know what is driving the READ request (sync read or async readahead). There is a dprintk() at the top of the function as well as a performance metric counter, but there currently isn't a dprintk() at the bottom of the function. So I assumed the return code is not a critical piece of information. I'm willing to be educated, though. A return point trace event could be generated only when there is an unexpected error condition, for example, to reduce trace log noise? > bigfile-6279 [004] ..... 11550.387232: nfs_aops_readpages: fileid=00:2f:26127 fhandle=0xb6d0e8f0 version=1633611037513339503 nr_pages=32 > bigfile-6279 [004] ..... 11550.387236: nfs_fscache_page_event_read: fileid=00:2f:26127 fhandle=0xb6d0e8f0 offset=0 count=4096 > bigfile-6279 [004] ..... 11550.387237: nfs_fscache_page_event_read_done: fileid=00:2f:26127 fhandle=0xb6d0e8f0 offset=0 count=4096 error=-105 > bigfile-6279 [004] ..... 11550.387248: nfs_fscache_page_event_read: fileid=00:2f:26127 fhandle=0xb6d0e8f0 offset=4096 count=4096 > bigfile-6279 [004] ..... 11550.387248: nfs_fscache_page_event_read_done: fileid=00:2f:26127 fhandle=0xb6d0e8f0 offset=4096 count=4096 error=-105 > bigfile-6279 [004] ..... 11550.387250: nfs_fscache_page_event_read: fileid=00:2f:26127 fhandle=0xb6d0e8f0 offset=8192 count=4096 > bigfile-6279 [004] ..... 11550.387250: nfs_fscache_page_event_read_done: fileid=00:2f:26127 fhandle=0xb6d0e8f0 offset=8192 count=4096 error=-105 -- Chuck Lever