From patchwork Thu May 23 20:13:48 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: David Wysochanski X-Patchwork-Id: 10958739 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 35CEF924 for ; Thu, 23 May 2019 20:14:09 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 257D31FEBA for ; Thu, 23 May 2019 20:14:09 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 19D4A28748; Thu, 23 May 2019 20:14:09 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-7.9 required=2.0 tests=BAYES_00,MAILING_LIST_MULTI, RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id D621828740 for ; Thu, 23 May 2019 20:14:07 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1731551AbfEWUOH (ORCPT ); Thu, 23 May 2019 16:14:07 -0400 Received: from mx1.redhat.com ([209.132.183.28]:42240 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726451AbfEWUOH (ORCPT ); Thu, 23 May 2019 16:14:07 -0400 Received: from smtp.corp.redhat.com (int-mx01.intmail.prod.int.phx2.redhat.com [10.5.11.11]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id E07EADF26 for ; Thu, 23 May 2019 20:14:06 +0000 (UTC) Received: from f29-node1.dwysocha.net (dhcp145-42.rdu.redhat.com [10.13.145.42]) by smtp.corp.redhat.com (Postfix) with ESMTP id B52C26012C for ; Thu, 23 May 2019 20:14:06 +0000 (UTC) From: Dave Wysochanski To: linux-nfs@vger.kernel.org Subject: [PATCH 1/3] SUNRPC: Move call to rpc_count_iostats before rpc_call_done Date: Thu, 23 May 2019 16:13:48 -0400 Message-Id: <20190523201351.12232-1-dwysocha@redhat.com> MIME-Version: 1.0 X-Scanned-By: MIMEDefang 2.79 on 10.5.11.11 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.30]); Thu, 23 May 2019 20:14:06 +0000 (UTC) Sender: linux-nfs-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-nfs@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP For diagnostic purposes, it would be useful to have an rpc_iostats metric of RPCs completing with tk_status < 0. Unfortunately, tk_status is reset inside the rpc_call_done functions for each operation, and the call to tally the per-op metrics comes after rpc_call_done. Refactor the call to rpc_count_iostat earlier in rpc_exit_task so we can count these RPCs completing in error. Signed-off-by: Dave Wysochanski --- net/sunrpc/sched.c | 5 +++++ net/sunrpc/xprt.c | 4 ---- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/net/sunrpc/sched.c b/net/sunrpc/sched.c index 28956c70100a..543caef296e4 100644 --- a/net/sunrpc/sched.c +++ b/net/sunrpc/sched.c @@ -22,6 +22,7 @@ #include #include +#include #include "sunrpc.h" @@ -770,6 +771,10 @@ rpc_reset_task_statistics(struct rpc_task *task) void rpc_exit_task(struct rpc_task *task) { task->tk_action = NULL; + if (task->tk_ops->rpc_count_stats) + task->tk_ops->rpc_count_stats(task, task->tk_calldata); + else if (task->tk_client) + rpc_count_iostats(task, task->tk_client->cl_metrics); if (task->tk_ops->rpc_call_done != NULL) { task->tk_ops->rpc_call_done(task, task->tk_calldata); if (task->tk_action != NULL) { diff --git a/net/sunrpc/xprt.c b/net/sunrpc/xprt.c index d7117d241460..d4477b227a96 100644 --- a/net/sunrpc/xprt.c +++ b/net/sunrpc/xprt.c @@ -1716,10 +1716,6 @@ void xprt_release(struct rpc_task *task) } xprt = req->rq_xprt; - if (task->tk_ops->rpc_count_stats != NULL) - task->tk_ops->rpc_count_stats(task, task->tk_calldata); - else if (task->tk_client) - rpc_count_iostats(task, task->tk_client->cl_metrics); xprt_request_dequeue_all(task, req); spin_lock_bh(&xprt->transport_lock); xprt->ops->release_xprt(xprt, task); From patchwork Thu May 23 20:13:49 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: David Wysochanski X-Patchwork-Id: 10958741 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 0668816C1 for ; Thu, 23 May 2019 20:14:10 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id E9E6A286B9 for ; Thu, 23 May 2019 20:14:09 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id DE2C828740; Thu, 23 May 2019 20:14:09 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-7.9 required=2.0 tests=BAYES_00,MAILING_LIST_MULTI, RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 42FB42874C for ; Thu, 23 May 2019 20:14:08 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S2387412AbfEWUOH (ORCPT ); Thu, 23 May 2019 16:14:07 -0400 Received: from mx1.redhat.com ([209.132.183.28]:42242 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1727001AbfEWUOH (ORCPT ); Thu, 23 May 2019 16:14:07 -0400 Received: from smtp.corp.redhat.com (int-mx01.intmail.prod.int.phx2.redhat.com [10.5.11.11]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 2B05B285B4 for ; Thu, 23 May 2019 20:14:07 +0000 (UTC) Received: from f29-node1.dwysocha.net (dhcp145-42.rdu.redhat.com [10.13.145.42]) by smtp.corp.redhat.com (Postfix) with ESMTP id F370B6012C for ; Thu, 23 May 2019 20:14:06 +0000 (UTC) From: Dave Wysochanski To: linux-nfs@vger.kernel.org Subject: [PATCH 2/3] SUNRPC: Use proper printk specifiers for unsigned long long Date: Thu, 23 May 2019 16:13:49 -0400 Message-Id: <20190523201351.12232-2-dwysocha@redhat.com> In-Reply-To: <20190523201351.12232-1-dwysocha@redhat.com> References: <20190523201351.12232-1-dwysocha@redhat.com> MIME-Version: 1.0 X-Scanned-By: MIMEDefang 2.79 on 10.5.11.11 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.30]); Thu, 23 May 2019 20:14:07 +0000 (UTC) Sender: linux-nfs-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-nfs@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP Update the printk specifiers inside _print_rpc_iostats to avoid a checkpatch warning. Signed-off-by: Dave Wysochanski --- net/sunrpc/stats.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/net/sunrpc/stats.c b/net/sunrpc/stats.c index 71166b393732..8b2d3c58ffae 100644 --- a/net/sunrpc/stats.c +++ b/net/sunrpc/stats.c @@ -224,7 +224,7 @@ 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 %Lu %Lu %Lu %Lu %Lu\n", + seq_printf(seq, "%lu %lu %lu %llu %llu %llu %llu %llu\n", stats->om_ops, stats->om_ntrans, stats->om_timeouts, From patchwork Thu May 23 20:13:50 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: David Wysochanski X-Patchwork-Id: 10958743 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 35011924 for ; Thu, 23 May 2019 20:14:10 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 24EEC26E3A for ; Thu, 23 May 2019 20:14:10 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 19205286B9; Thu, 23 May 2019 20:14:10 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-7.9 required=2.0 tests=BAYES_00,MAILING_LIST_MULTI, RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 9F99F28746 for ; Thu, 23 May 2019 20:14:08 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S2387436AbfEWUOI (ORCPT ); Thu, 23 May 2019 16:14:08 -0400 Received: from mx1.redhat.com ([209.132.183.28]:40042 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S2387408AbfEWUOH (ORCPT ); Thu, 23 May 2019 16:14:07 -0400 Received: from smtp.corp.redhat.com (int-mx01.intmail.prod.int.phx2.redhat.com [10.5.11.11]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 6704E308624A for ; Thu, 23 May 2019 20:14:07 +0000 (UTC) Received: from f29-node1.dwysocha.net (dhcp145-42.rdu.redhat.com [10.13.145.42]) by smtp.corp.redhat.com (Postfix) with ESMTP id 3C9BC6012C for ; Thu, 23 May 2019 20:14:07 +0000 (UTC) From: Dave Wysochanski To: linux-nfs@vger.kernel.org Subject: [PATCH 3/3] SUNRPC: Count ops completing with tk_status < 0 Date: Thu, 23 May 2019 16:13:50 -0400 Message-Id: <20190523201351.12232-3-dwysocha@redhat.com> In-Reply-To: <20190523201351.12232-1-dwysocha@redhat.com> References: <20190523201351.12232-1-dwysocha@redhat.com> MIME-Version: 1.0 X-Scanned-By: MIMEDefang 2.79 on 10.5.11.11 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.49]); Thu, 23 May 2019 20:14:07 +0000 (UTC) Sender: linux-nfs-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-nfs@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP 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. Signed-off-by: Dave Wysochanski --- 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 #include -#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)