by Chuck Lever III

[permalink] [raw]

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

> On Nov 2, 2021, at 3:36 PM, David Wysochanski <[email protected]> wrote:
>
> On Sat, Oct 16, 2021 at 6:03 PM Chuck Lever <[email protected]> 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

IMO offset is interesting to include, but I don't think multiplying
by PAGE_SIZE adds much value. If you disagree, you can always tuck
that into the tracepoint's TP_fast_assign section.

>> The count of pages requested is reported. nfs_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..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;
>> }

--
Chuck Lever