Re: [PATCH RFC 5/5] NFS: Replace dprintk callsites in nfs_readpage(s)

[David Wysochanski <dwysocha@redhat.com>]

On Thu, Oct 7, 2021 at 11:01 AM Chuck Lever III <chuck.lever@oracle.com> wrote:
>
>
>
> > On Oct 7, 2021, at 9:05 AM, David Wysochanski <dwysocha@redhat.com> wrote:
> >
> > On Tue, Oct 5, 2021 at 1:14 PM Chuck Lever <chuck.lever@oracle.com> 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@oracle.com>
> > > ---
> > >  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.
>

Well, I was trying to understand the various approaches in nfstrace.h.
There are tracepoints that are paired with entry and exit, but I guess
these have multiple pieces of information that may change from
start to finish.  Examples:
nfs_refresh_inode_enter
nfs_refresh_inode_exit
nfs_lookup_revalidate_enter
nfs_lookup_revalidate_exit

> A return point trace event could be generated only when there
> is an unexpected error condition, for example, to reduce trace
> log noise?
>
Ok so you would just add a second tracepoint for non-zero returns?

>
> >          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

Example:
bigfile-6279    [004] ..... 11550.387252: nfs_aops_readpages_error:
fileid=00:2f:26127 fhandle=0xb6d0e8f0 version=1633611037513339503
nr_pages=6 error=-5



>
> --
> Chuck Lever
>
>
>