On Sat, Oct 16, 2021 at 6:03 PM Chuck Lever <chuck.lever@xxxxxxxxxx> wrote:
>
> These new events report slightly different information for readpage
> and readpages/readahead.
>
> For readpage:
> fsx-1387 [006] 380.761896: nfs_aop_readpage: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355910932437 offset=131072
> fsx-1387 [006] 380.761900: nfs_aop_readpage_done: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355910932437 offset=131072 ret=0
>
> The index of a synchronous single-page read is reported.
>
> For readpages:
>
> fsx-1387 [006] 380.760847: nfs_aop_readahead: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355909932456 nr_pages=3
> fsx-1387 [006] 380.760853: nfs_aop_readahead_done: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355909932456 nr_pages=3 ret=0
>
Chuck,
I was doing more debugging and thought about the readahead trace event.
Are you set on "nr_pages" output here, or was that mainly due to the parameter?
I think maybe it would be better to have byte fields, "offset" and
"count" like the other IO tracepoints (trace_nfs_initiate_read() for
example). Or do you see some advantages to using nr_pages?
We can get the offset with lru_to_page(pages) and of course "count"
with nr_pages*PAGE_SIZE
> The count of pages requested is reported. nfs_readpages does not
> wait for the READ requests to complete.
>
> Signed-off-by: Chuck Lever <chuck.lever@xxxxxxxxxx>
> ---
> fs/nfs/nfstrace.h | 146 +++++++++++++++++++++++++++++++++++++++++++++++++++++
> fs/nfs/read.c | 11 ++--
> 2 files changed, 151 insertions(+), 6 deletions(-)
>
> diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
> index e9be65b52bfe..898308780df8 100644
> --- a/fs/nfs/nfstrace.h
> +++ b/fs/nfs/nfstrace.h
> @@ -862,6 +862,152 @@ TRACE_EVENT(nfs_sillyrename_unlink,
> )
> );
>
> +TRACE_EVENT(nfs_aop_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(loff_t, offset)
> + ),
> +
> + 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->offset = page_index(page) << PAGE_SHIFT;
> + ),
> +
> + TP_printk(
> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu offset=%lld",
> + MAJOR(__entry->dev), MINOR(__entry->dev),
> + (unsigned long long)__entry->fileid,
> + __entry->fhandle, __entry->version,
> + __entry->offset
> + )
> +);
> +
> +TRACE_EVENT(nfs_aop_readpage_done,
> + TP_PROTO(
> + const struct inode *inode,
> + struct page *page,
> + int ret
> + ),
> +
> + TP_ARGS(inode, page, ret),
> +
> + TP_STRUCT__entry(
> + __field(dev_t, dev)
> + __field(u32, fhandle)
> + __field(int, ret)
> + __field(u64, fileid)
> + __field(u64, version)
> + __field(loff_t, offset)
> + ),
> +
> + 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->offset = page_index(page) << PAGE_SHIFT;
> + __entry->ret = ret;
> + ),
> +
> + TP_printk(
> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu offset=%lld ret=%d",
> + MAJOR(__entry->dev), MINOR(__entry->dev),
> + (unsigned long long)__entry->fileid,
> + __entry->fhandle, __entry->version,
> + __entry->offset, __entry->ret
> + )
> +);
> +
> +TRACE_EVENT(nfs_aop_readahead,
> + 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_aop_readahead_done,
> + TP_PROTO(
> + const struct inode *inode,
> + unsigned int nr_pages,
> + int ret
> + ),
> +
> + TP_ARGS(inode, nr_pages, ret),
> +
> + TP_STRUCT__entry(
> + __field(dev_t, dev)
> + __field(u32, fhandle)
> + __field(int, ret)
> + __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;
> + __entry->ret = ret;
> + ),
> +
> + TP_printk(
> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu nr_pages=%u ret=%d",
> + MAJOR(__entry->dev), MINOR(__entry->dev),
> + (unsigned long long)__entry->fileid,
> + __entry->fhandle, __entry->version,
> + __entry->nr_pages, __entry->ret
> + )
> +);
> +
> 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..c8273d4b12ad 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_aop_readpage(inode, page);
> nfs_inc_stats(inode, NFSIOS_VFSREADPAGE);
>
> /*
> @@ -390,9 +389,11 @@ int nfs_readpage(struct file *file, struct page *page)
> }
> out:
> put_nfs_open_context(desc.ctx);
> + trace_nfs_aop_readpage_done(inode, page, ret);
> return ret;
> out_unlock:
> unlock_page(page);
> + trace_nfs_aop_readpage_done(inode, page, ret);
> return ret;
> }
>
> @@ -403,10 +404,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_aop_readahead(inode, nr_pages);
> nfs_inc_stats(inode, NFSIOS_VFSREADPAGES);
>
> ret = -ESTALE;
> @@ -439,6 +437,7 @@ int nfs_readpages(struct file *file, struct address_space *mapping,
> read_complete:
> put_nfs_open_context(desc.ctx);
> out:
> + trace_nfs_aop_readahead_done(inode, nr_pages, ret);
> return ret;
> }
>
>
