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 <[email protected]>
---
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..85e67b326bcd 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(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_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(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);
+ __entry->ret = ret;
+ ),
+
+ TP_printk(
+ "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu page_index=%lu ret=%d",
+ MAJOR(__entry->dev), MINOR(__entry->dev),
+ (unsigned long long)__entry->fileid,
+ __entry->fhandle, __entry->version,
+ __entry->index, __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;
}
> On Oct 7, 2021, at 12:17 PM, Chuck Lever <[email protected]> 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 <[email protected]>
Well obviously I forgot to update the patch description.
I can send a v3 later to do that.
> ---
> 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..85e67b326bcd 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(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_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(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);
> + __entry->ret = ret;
> + ),
> +
> + TP_printk(
> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu page_index=%lu ret=%d",
> + MAJOR(__entry->dev), MINOR(__entry->dev),
> + (unsigned long long)__entry->fileid,
> + __entry->fhandle, __entry->version,
> + __entry->index, __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;
> }
>
>
--
Chuck Lever
On Thu, Oct 7, 2021 at 12:22 PM Chuck Lever III <[email protected]> wrote:
>
>
>
> > On Oct 7, 2021, at 12:17 PM, Chuck Lever <[email protected]> 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 <[email protected]>
>
> Well obviously I forgot to update the patch description.
> I can send a v3 later to do that.
>
>
Why not just call the tracepoints nfs_readpage and nfs_readpages?
> > ---
> > 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..85e67b326bcd 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(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_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(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);
> > + __entry->ret = ret;
> > + ),
> > +
> > + TP_printk(
> > + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu page_index=%lu ret=%d",
> > + MAJOR(__entry->dev), MINOR(__entry->dev),
> > + (unsigned long long)__entry->fileid,
> > + __entry->fhandle, __entry->version,
> > + __entry->index, __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;
> > }
> >
> >
>
> --
> Chuck Lever
>
>
>
> On Oct 7, 2021, at 3:16 PM, David Wysochanski <[email protected]> wrote:
>
> On Thu, Oct 7, 2021 at 12:22 PM Chuck Lever III <[email protected]> wrote:
>>
>>
>>
>>> On Oct 7, 2021, at 12:17 PM, Chuck Lever <[email protected]> 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 <[email protected]>
>>
>> Well obviously I forgot to update the patch description.
>> I can send a v3 later to do that.
>>
>>
>
> Why not just call the tracepoints nfs_readpage and nfs_readpages?
Because there is already an nfs_readpage_done() tracepoint.
>>> ---
>>> 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..85e67b326bcd 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(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_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(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);
>>> + __entry->ret = ret;
>>> + ),
>>> +
>>> + TP_printk(
>>> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu page_index=%lu ret=%d",
>>> + MAJOR(__entry->dev), MINOR(__entry->dev),
>>> + (unsigned long long)__entry->fileid,
>>> + __entry->fhandle, __entry->version,
>>> + __entry->index, __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;
>>> }
>>>
>>>
>>
>> --
>> Chuck Lever
--
Chuck Lever
On Thu, Oct 7, 2021 at 3:25 PM Chuck Lever III <[email protected]> wrote:
>
>
>
> > On Oct 7, 2021, at 3:16 PM, David Wysochanski <[email protected]> wrote:
> >
> > On Thu, Oct 7, 2021 at 12:22 PM Chuck Lever III <[email protected]> wrote:
> >>
> >>
> >>
> >>> On Oct 7, 2021, at 12:17 PM, Chuck Lever <[email protected]> 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 <[email protected]>
> >>
> >> Well obviously I forgot to update the patch description.
> >> I can send a v3 later to do that.
> >>
> >>
> >
> > Why not just call the tracepoints nfs_readpage and nfs_readpages?
>
> Because there is already an nfs_readpage_done() tracepoint.
>
Ah ok. FWIW, you could use nfs_readpage_enter() and
nfs_readpage_exit() similar to nfs_rmdir() for example.
>
> >>> ---
> >>> 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..85e67b326bcd 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(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_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(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);
> >>> + __entry->ret = ret;
> >>> + ),
> >>> +
> >>> + TP_printk(
> >>> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu page_index=%lu ret=%d",
> >>> + MAJOR(__entry->dev), MINOR(__entry->dev),
> >>> + (unsigned long long)__entry->fileid,
> >>> + __entry->fhandle, __entry->version,
> >>> + __entry->index, __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;
> >>> }
> >>>
> >>>
> >>
> >> --
> >> Chuck Lever
>
> --
> Chuck Lever
>
>
>
> On Oct 7, 2021, at 3:31 PM, David Wysochanski <[email protected]> wrote:
>
> On Thu, Oct 7, 2021 at 3:25 PM Chuck Lever III <[email protected]> wrote:
>>
>>
>>
>>> On Oct 7, 2021, at 3:16 PM, David Wysochanski <[email protected]> wrote:
>>>
>>> On Thu, Oct 7, 2021 at 12:22 PM Chuck Lever III <[email protected]> wrote:
>>>>
>>>>
>>>>
>>>>> On Oct 7, 2021, at 12:17 PM, Chuck Lever <[email protected]> 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 <[email protected]>
>>>>
>>>> Well obviously I forgot to update the patch description.
>>>> I can send a v3 later to do that.
>>>>
>>>>
>>>
>>> Why not just call the tracepoints nfs_readpage and nfs_readpages?
>>
>> Because there is already an nfs_readpage_done() tracepoint.
>>
> Ah ok. FWIW, you could use nfs_readpage_enter() and
> nfs_readpage_exit() similar to nfs_rmdir() for example.
Sure. I was hoping to tag all NFS address space ops methods so
they could turned on with a single command, like:
# trace-cmd record -e nfs:nfs_aop_\*
But maybe that's not valuable.
--
Chuck Lever