> On Oct 7, 2021, at 11:25 AM, David Wysochanski <dwysocha@xxxxxxxxxx> wrote:
>
> On Thu, Oct 7, 2021 at 11:01 AM Chuck Lever III <chuck.lever@xxxxxxxxxx> wrote:
>>
>>
>>
>>> 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.
>>
>
> 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
These were added over many years by several different people.
Unfortunately there isn't much strategy here at this point.
But yes, especially for nfs_readpages, the *pages argument
is a list that is drained by read_cache_pages() so it wouldn't
have the same value at the end of the function (not that the
trace point is recording it, but you get the idea).
>> 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?
So for I/O operations, there is precedent for recording the
completion with a _done trace event. I'm redriving this patch
to include an unconditional return point trace event. Stand by...
>>> 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
--
Chuck Lever
