Re: [PATCH 3/3] SUNRPC: Count ops completing with tk_status < 0

[Chuck Lever <chuck.lever@oracle.com>]

> On May 30, 2019, at 6:33 PM, Bruce Fields <bfields@fieldses.org> wrote:
> 
> On Thu, May 30, 2019 at 06:19:54PM -0400, Chuck Lever wrote:
>> 
>> 
>>> On May 30, 2019, at 5:38 PM, bfields@fieldses.org wrote:
>>> 
>>> On Thu, May 23, 2019 at 04:13:50PM -0400, Dave Wysochanski wrote:
>>>> We often see various error conditions with NFS4.x that show up with
>>>> a very high operation count all completing with tk_status < 0 in a
>>>> short period of time.  Add a count to rpc_iostats to record on a
>>>> per-op basis the ops that complete in this manner, which will
>>>> enable lower overhead diagnostics.
>>> 
>>> Looks like a good idea to me.
>>> 
>>> It's too bad we can't distinguish the errors.  (E.g. ESTALE on a lookup
>>> call is a lot more interesting than ENOENT.)  But understood that
>>> maintaining (number of possible errors) * (number of possible ops)
>>> counters is probably overkill, so just counting the number of errors
>>> seems like a good start.
>> 
>> We now have trace points that can do that too.
> 
> You mean, that can report every error (and its value)?

Yes, the nfs_xdr_status trace point reports the error by value and symbolic name.


> I assume having these statistics in mountstats is still useful, though.
> 
> --b.
> 
>> 
>> 
>>> --b.
>>> 
>>>> 
>>>> Signed-off-by: Dave Wysochanski <dwysocha@redhat.com>
>>>> ---
>>>> include/linux/sunrpc/metrics.h | 7 ++++++-
>>>> net/sunrpc/stats.c             | 8 ++++++--
>>>> 2 files changed, 12 insertions(+), 3 deletions(-)
>>>> 
>>>> diff --git a/include/linux/sunrpc/metrics.h b/include/linux/sunrpc/metrics.h
>>>> index 1b3751327575..0ee3f7052846 100644
>>>> --- a/include/linux/sunrpc/metrics.h
>>>> +++ b/include/linux/sunrpc/metrics.h
>>>> @@ -30,7 +30,7 @@
>>>> #include <linux/ktime.h>
>>>> #include <linux/spinlock.h>
>>>> 
>>>> -#define RPC_IOSTATS_VERS	"1.0"
>>>> +#define RPC_IOSTATS_VERS	"1.1"
>>>> 
>>>> struct rpc_iostats {
>>>> 	spinlock_t		om_lock;
>>>> @@ -66,6 +66,11 @@ struct rpc_iostats {
>>>> 	ktime_t			om_queue,	/* queued for xmit */
>>>> 				om_rtt,		/* RPC RTT */
>>>> 				om_execute;	/* RPC execution */
>>>> +	/*
>>>> +	 * The count of operations that complete with tk_status < 0.
>>>> +	 * These statuses usually indicate error conditions.
>>>> +	 */
>>>> +	unsigned long           om_error_status;
>>>> } ____cacheline_aligned;
>>>> 
>>>> struct rpc_task;
>>>> diff --git a/net/sunrpc/stats.c b/net/sunrpc/stats.c
>>>> index 8b2d3c58ffae..737414247ca7 100644
>>>> --- a/net/sunrpc/stats.c
>>>> +++ b/net/sunrpc/stats.c
>>>> @@ -176,6 +176,8 @@ void rpc_count_iostats_metrics(const struct rpc_task *task,
>>>> 
>>>> 	execute = ktime_sub(now, task->tk_start);
>>>> 	op_metrics->om_execute = ktime_add(op_metrics->om_execute, execute);
>>>> +	if (task->tk_status < 0)
>>>> +		op_metrics->om_error_status++;
>>>> 
>>>> 	spin_unlock(&op_metrics->om_lock);
>>>> 
>>>> @@ -218,13 +220,14 @@ static void _add_rpc_iostats(struct rpc_iostats *a, struct rpc_iostats *b)
>>>> 	a->om_queue = ktime_add(a->om_queue, b->om_queue);
>>>> 	a->om_rtt = ktime_add(a->om_rtt, b->om_rtt);
>>>> 	a->om_execute = ktime_add(a->om_execute, b->om_execute);
>>>> +	a->om_error_status += b->om_error_status;
>>>> }
>>>> 
>>>> static void _print_rpc_iostats(struct seq_file *seq, struct rpc_iostats *stats,
>>>> 			       int op, const struct rpc_procinfo *procs)
>>>> {
>>>> 	_print_name(seq, op, procs);
>>>> -	seq_printf(seq, "%lu %lu %lu %llu %llu %llu %llu %llu\n",
>>>> +	seq_printf(seq, "%lu %lu %lu %llu %llu %llu %llu %llu %lu\n",
>>>> 		   stats->om_ops,
>>>> 		   stats->om_ntrans,
>>>> 		   stats->om_timeouts,
>>>> @@ -232,7 +235,8 @@ static void _print_rpc_iostats(struct seq_file *seq, struct rpc_iostats *stats,
>>>> 		   stats->om_bytes_recv,
>>>> 		   ktime_to_ms(stats->om_queue),
>>>> 		   ktime_to_ms(stats->om_rtt),
>>>> -		   ktime_to_ms(stats->om_execute));
>>>> +		   ktime_to_ms(stats->om_execute),
>>>> +		   stats->om_error_status);
>>>> }
>>>> 
>>>> void rpc_clnt_show_stats(struct seq_file *seq, struct rpc_clnt *clnt)
>>>> -- 
>>>> 2.20.1
>> 
>> --
>> Chuck Lever

--
Chuck Lever