From patchwork Sat Jun 13 16:27:16 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: James Simmons X-Patchwork-Id: 11602913 Return-Path: Received: from mail.kernel.org (pdx-korg-mail-1.web.codeaurora.org [172.30.200.123]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 486731392 for ; Sat, 13 Jun 2020 16:28:30 +0000 (UTC) Received: from pdx1-mailman02.dreamhost.com (pdx1-mailman02.dreamhost.com [64.90.62.194]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPS id 30AE12078A for ; Sat, 13 Jun 2020 16:28:30 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 30AE12078A Authentication-Results: mail.kernel.org; dmarc=none (p=none dis=none) header.from=infradead.org Authentication-Results: mail.kernel.org; spf=none smtp.mailfrom=lustre-devel-bounces@lists.lustre.org Received: from pdx1-mailman02.dreamhost.com (localhost [IPv6:::1]) by pdx1-mailman02.dreamhost.com (Postfix) with ESMTP id 0497821F4B2; Sat, 13 Jun 2020 09:27:58 -0700 (PDT) X-Original-To: lustre-devel@lists.lustre.org Delivered-To: lustre-devel-lustre.org@pdx1-mailman02.dreamhost.com Received: from smtp3.ccs.ornl.gov (smtp3.ccs.ornl.gov [160.91.203.39]) by pdx1-mailman02.dreamhost.com (Postfix) with ESMTP id CF99621EBAC for ; Sat, 13 Jun 2020 09:27:28 -0700 (PDT) Received: from star.ccs.ornl.gov (star.ccs.ornl.gov [160.91.202.134]) by smtp3.ccs.ornl.gov (Postfix) with ESMTP id B3F678E9; Sat, 13 Jun 2020 12:27:19 -0400 (EDT) Received: by star.ccs.ornl.gov (Postfix, from userid 2004) id B2DEF47A; Sat, 13 Jun 2020 12:27:19 -0400 (EDT) From: James Simmons To: Andreas Dilger , Oleg Drokin , NeilBrown Date: Sat, 13 Jun 2020 12:27:16 -0400 Message-Id: <1592065636-28333-21-git-send-email-jsimmons@infradead.org> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1592065636-28333-1-git-send-email-jsimmons@infradead.org> References: <1592065636-28333-1-git-send-email-jsimmons@infradead.org> Subject: [lustre-devel] [PATCH 20/20] lnet: o2iblnd: 'Timed out tx' error message X-BeenThere: lustre-devel@lists.lustre.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: "For discussing Lustre software development." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Lustre Development List MIME-Version: 1.0 Errors-To: lustre-devel-bounces@lists.lustre.org Sender: "lustre-devel" From: Sonia Sharma Fix the error message in kiblnd_check_txs_locked() to report the total RDMA time outstanding rather than the number of seconds past the deadline. This patch also adds time_on_activeq to struct kib_tx so the time spent by tx in internal queue and active queue can be tracked and reported. This would help in diagnosing the issue. WC-bug-id: https://jira.whamcloud.com/browse/LU-1742 Lustre-commit: 7308662efc02f ("LU-1742 o2iblnd: 'Timed out tx' error message") Signed-off-by: Sonia Sharma Reviewed-on: https://review.whamcloud.com/33235 Reviewed-by: Andreas Dilger Reviewed-by: Stephen Champion Reviewed-by: Oleg Drokin Signed-off-by: James Simmons --- net/lnet/klnds/o2iblnd/o2iblnd.h | 2 ++ net/lnet/klnds/o2iblnd/o2iblnd_cb.c | 26 ++++++++++++++++++++++---- 2 files changed, 24 insertions(+), 4 deletions(-) diff --git a/net/lnet/klnds/o2iblnd/o2iblnd.h b/net/lnet/klnds/o2iblnd/o2iblnd.h index f60a69d..dc09e5e 100644 --- a/net/lnet/klnds/o2iblnd/o2iblnd.h +++ b/net/lnet/klnds/o2iblnd/o2iblnd.h @@ -541,6 +541,8 @@ struct kib_tx { /* transmit message */ bool tx_gaps; struct kib_fmr tx_fmr; /* FMR */ int tx_dmadir; /* dma direction */ + /* time when tx added on ibc_active_txs */ + ktime_t tx_on_activeq; }; struct kib_connvars { diff --git a/net/lnet/klnds/o2iblnd/o2iblnd_cb.c b/net/lnet/klnds/o2iblnd/o2iblnd_cb.c index 40e196d..f421cdf 100644 --- a/net/lnet/klnds/o2iblnd/o2iblnd_cb.c +++ b/net/lnet/klnds/o2iblnd/o2iblnd_cb.c @@ -821,6 +821,7 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, */ tx->tx_sending++; list_add(&tx->tx_list, &conn->ibc_active_txs); + tx->tx_on_activeq = ktime_get(); /* I'm still holding ibc_lock! */ if (conn->ibc_state != IBLND_CONN_ESTABLISHED) { @@ -3169,6 +3170,8 @@ static int kiblnd_resolve_addr(struct rdma_cm_id *cmid, static int kiblnd_check_txs_locked(struct kib_conn *conn, struct list_head *txs) { + bool active_txs = strcmp(kiblnd_queue2str(conn, txs), + "active_txs") == 0; struct kib_tx *tx; list_for_each_entry(tx, txs, tx_list) { @@ -3179,13 +3182,28 @@ static int kiblnd_resolve_addr(struct rdma_cm_id *cmid, LASSERT(tx->tx_waiting || tx->tx_sending); } - if (ktime_compare(ktime_get(), tx->tx_deadline) >= 0) { - CERROR("Timed out tx: %s, %lld seconds\n", + if (ktime_compare(ktime_get(), tx->tx_deadline) < 0) + continue; + + if (!active_txs) { + CERROR("Timed out tx: %s, outstanding RDMA time: %lld sec\n", kiblnd_queue2str(conn, txs), + *kiblnd_tunables.kib_timeout + + (ktime_ms_delta(ktime_get(), + tx->tx_deadline) / MSEC_PER_SEC)); + } else { + CERROR("Timed out tx: %s, time in internal queue: %lld sec, time in active queue: %lld sec, outstanding RDMA time: %lld sec\n", + kiblnd_queue2str(conn, txs), + ktime_ms_delta(tx->tx_deadline, + tx->tx_on_activeq) / MSEC_PER_SEC, ktime_ms_delta(ktime_get(), - tx->tx_deadline) / MSEC_PER_SEC); - return 1; + tx->tx_on_activeq) / MSEC_PER_SEC, + *kiblnd_tunables.kib_timeout + + (ktime_ms_delta(ktime_get(), + tx->tx_deadline) / MSEC_PER_SEC)); } + + return 1; } return 0;