[05/22] lnet: o2iblnd: add verbose debug prints for rx/tx events

Message ID	1668953828-10909-6-git-send-email-jsimmons@infradead.org (mailing list archive)
State	New, archived
Headers	show Return-Path: <lustre-devel-bounces@lists.lustre.org> From: James Simmons <jsimmons@infradead.org> To: Andreas Dilger <adilger@whamcloud.com>, Oleg Drokin <green@whamcloud.com>, NeilBrown <neilb@suse.de> Date: Sun, 20 Nov 2022 09:16:51 -0500 Message-Id: <1668953828-10909-6-git-send-email-jsimmons@infradead.org> In-Reply-To: <1668953828-10909-1-git-send-email-jsimmons@infradead.org> References: <1668953828-10909-1-git-send-email-jsimmons@infradead.org> Subject: [lustre-devel] [PATCH 05/22] lnet: o2iblnd: add verbose debug prints for rx/tx events Precedence: list Cc: Serguei Smirnov <ssmirnov@whamcloud.com>, Lustre Development List <lustre-devel@lists.lustre.org> MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Errors-To: lustre-devel-bounces@lists.lustre.org Sender: "lustre-devel" <lustre-devel-bounces@lists.lustre.org>
Series	lustre: backport OpenSFS work as of Nov 20, 2022 \| expand [00/22] lustre: backport OpenSFS work as of Nov 20, 2022 [01/22] lustre: llite: clear stale page's uptodate bit [02/22] lustre: osc: Remove oap lock [03/22] lnet: Don't modify uptodate peer with temp NI [04/22] lustre: llite: Explicitly support .splice_write [05/22] lnet: o2iblnd: add verbose debug prints for rx/tx events [06/22] lnet: use Netlink to support old and new NI APIs. [07/22] lustre: obdclass: improve precision of wakeups for mod_rpcs [08/22] lnet: allow ping packet to contain large nids [09/22] lustre: llog: skip bad records in llog [10/22] lnet: fix build issue when IPv6 is disabled. [11/22] lustre: obdclass: fill jobid in a safe way [12/22] lustre: llite: remove linefeed from LDLM_DEBUG [13/22] lnet: selftest: migrate LNet selftest session handling to Netlink [14/22] lustre: clio: append to non-existent component [15/22] lnet: fix debug message in lnet_discovery_event_reply [16/22] lustre: ldlm: group lock unlock fix [17/22] lnet: Signal completion on ping send failure [18/22] lnet: extend lnet_is_nid_in_ping_info() [19/22] lnet: find correct primary for peer [20/22] lnet: change lnet_notify() to take struct lnet_nid [21/22] lnet: discard lnet_nid2ni_*() [22/22] lnet: change lnet_debug_peer() to struct lnet_nid

diff --git a/net/lnet/klnds/o2iblnd/o2iblnd.h b/net/lnet/klnds/o2iblnd/o2iblnd.h index 56d486f..bef7a55 100644 --- a/net/lnet/klnds/o2iblnd/o2iblnd.h +++ b/net/lnet/klnds/o2iblnd/o2iblnd.h @@ -588,28 +588,32 @@ static inline int kiblnd_timeout(void) return dev->ibd_can_failover; } -#define kiblnd_conn_addref(conn) \ -do { \ - CDEBUG(D_NET, "conn[%p] (%d)++\n", \ - (conn), atomic_read(&(conn)->ibc_refcount)); \ - atomic_inc(&(conn)->ibc_refcount); \ -} while (0) - -#define kiblnd_conn_decref(conn) \ -do { \ - unsigned long flags; \ - \ - CDEBUG(D_NET, "conn[%p] (%d)--\n", \ - (conn), atomic_read(&(conn)->ibc_refcount)); \ - LASSERT_ATOMIC_POS(&(conn)->ibc_refcount); \ - if (atomic_dec_and_test(&(conn)->ibc_refcount)) { \ - spin_lock_irqsave(&kiblnd_data.kib_connd_lock, flags); \ - list_add_tail(&(conn)->ibc_list, \ - &kiblnd_data.kib_connd_zombies); \ - wake_up(&kiblnd_data.kib_connd_waitq); \ - spin_unlock_irqrestore(&kiblnd_data.kib_connd_lock, flags);\ - } \ -} while (0) +static inline void kiblnd_conn_addref(struct kib_conn *conn) +{ +#ifdef CONFIG_LUSTRE_DEBUG_EXPENSIVE_CHECK + CDEBUG(D_NET, "conn[%p] (%d)++\n", + conn, atomic_read(&conn->ibc_refcount)); +#endif + atomic_inc(&(conn)->ibc_refcount); +} + +static inline void kiblnd_conn_decref(struct kib_conn *conn) +{ + unsigned long flags; + +#ifdef CONFIG_LUSTRE_DEBUG_EXPENSIVE_CHECK + CDEBUG(D_NET, "conn[%p] (%d)--\n", + conn, atomic_read(&conn->ibc_refcount)); +#endif + LASSERT_ATOMIC_POS(&conn->ibc_refcount); + if (atomic_dec_and_test(&conn->ibc_refcount)) { + spin_lock_irqsave(&kiblnd_data.kib_connd_lock, flags); + list_add_tail(&conn->ibc_list, + &kiblnd_data.kib_connd_zombies); + wake_up(&kiblnd_data.kib_connd_waitq); + spin_unlock_irqrestore(&kiblnd_data.kib_connd_lock, flags); + } +} void kiblnd_destroy_peer(struct kref *kref); @@ -971,3 +975,33 @@ void kiblnd_pack_msg(struct lnet_ni *ni, struct kib_msg *msg, int version, int kiblnd_recv(struct lnet_ni *ni, void *private, struct lnet_msg *lntmsg, int delayed, struct iov_iter *to, unsigned int rlen); unsigned int kiblnd_get_dev_prio(struct lnet_ni *ni, unsigned int dev_idx); + +#define kiblnd_dump_conn_dbg(conn) \ +({ \ + if (conn && conn->ibc_cmid) \ + CDEBUG(D_NET, \ + "conn %p state %d nposted %d/%d c/o/r %d/%d/%d ce %d : cm_id %p qp_num 0x%x device_name %s\n", \ + conn, \ + conn->ibc_state, \ + conn->ibc_noops_posted, \ + conn->ibc_nsends_posted, \ + conn->ibc_credits, \ + conn->ibc_outstanding_credits, \ + conn->ibc_reserved_credits, \ + conn->ibc_comms_error, \ + conn->ibc_cmid, \ + conn->ibc_cmid->qp ? conn->ibc_cmid->qp->qp_num : 0, \ + conn->ibc_cmid->qp ? (conn->ibc_cmid->qp->device ? dev_name(&conn->ibc_cmid->qp->device->dev) : "NULL") : "NULL"); \ + else if (conn) \ + CDEBUG(D_NET, \ + "conn %p state %d nposted %d/%d c/o/r %d/%d/%d ce %d : cm_id NULL\n", \ + conn, \ + conn->ibc_state, \ + conn->ibc_noops_posted, \ + conn->ibc_nsends_posted, \ + conn->ibc_credits, \ + conn->ibc_outstanding_credits, \ + conn->ibc_reserved_credits, \ + conn->ibc_comms_error \ + ); \ +}) diff --git a/net/lnet/klnds/o2iblnd/o2iblnd_cb.c b/net/lnet/klnds/o2iblnd/o2iblnd_cb.c index b16841e..d4de326 100644 --- a/net/lnet/klnds/o2iblnd/o2iblnd_cb.c +++ b/net/lnet/klnds/o2iblnd/o2iblnd_cb.c @@ -337,9 +337,12 @@ static int kiblnd_init_rdma(struct kib_conn *conn, struct kib_tx *tx, int type, LASSERT(conn->ibc_state >= IBLND_CONN_ESTABLISHED); - CDEBUG(D_NET, "Received %x[%d] from %s\n", + CDEBUG(D_NET, "Received %x[%d] nob %u cm_id %p qp_num 0x%x\n", msg->ibm_type, credits, - libcfs_nid2str(conn->ibc_peer->ibp_nid)); + msg->ibm_nob, + conn->ibc_cmid, + conn->ibc_cmid->qp ? conn->ibc_cmid->qp->qp_num : 0); + kiblnd_dump_conn_dbg(conn); if (credits) { /* Have I received credits that will let me send? */ @@ -760,8 +763,11 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, } if (credit && !conn->ibc_credits) { /* no credits */ - CDEBUG(D_NET, "%s: no credits\n", - libcfs_nid2str(peer_ni->ibp_nid)); + CDEBUG(D_NET, "%s: no credits cm_id %p qp_num 0x%x\n", + libcfs_nid2str(peer_ni->ibp_nid), + conn->ibc_cmid, + conn->ibc_cmid->qp ? conn->ibc_cmid->qp->qp_num : 0); + kiblnd_dump_conn_dbg(conn); return -EAGAIN; } @@ -790,12 +796,22 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, tx->tx_hstatus = LNET_MSG_STATUS_LOCAL_ERROR; kiblnd_tx_done(tx); spin_lock(&conn->ibc_lock); - CDEBUG(D_NET, "%s(%d): redundant or enough NOOP\n", + CDEBUG(D_NET, "%s(%d): redundant or enough NOOP cm_id %p qp_num 0x%x\n", libcfs_nid2str(peer_ni->ibp_nid), - conn->ibc_noops_posted); + conn->ibc_noops_posted, + conn->ibc_cmid, + conn->ibc_cmid->qp ? conn->ibc_cmid->qp->qp_num : 0); + kiblnd_dump_conn_dbg(conn); return 0; } + CDEBUG(D_NET, "Transmit %x[%d] nob %u cm_id %p qp_num 0x%x\n", + msg->ibm_type, credit, + msg->ibm_nob, + conn->ibc_cmid, + conn->ibc_cmid->qp ? conn->ibc_cmid->qp->qp_num : 0); + kiblnd_dump_conn_dbg(conn); + kiblnd_pack_msg(peer_ni->ibp_ni, msg, ver, conn->ibc_outstanding_credits, peer_ni->ibp_nid, conn->ibc_incarnation); @@ -1000,6 +1016,9 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, tx->tx_hstatus = LNET_MSG_STATUS_REMOTE_DROPPED; tx->tx_waiting = 0; /* don't wait for peer_ni */ tx->tx_status = -EIO; +#ifdef CONFIG_LUSTRE_DEBUG_EXPENSIVE_CHECK + kiblnd_dump_conn_dbg(conn); +#endif } idle = !tx->tx_sending && /* This is the final callback */ @@ -1982,10 +2001,12 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, list_empty(&conn->ibc_tx_queue_rsrvd) && list_empty(&conn->ibc_tx_queue_nocred) && list_empty(&conn->ibc_active_txs)) { - CDEBUG(D_NET, "closing conn to %s\n", + CDEBUG(D_NET, "closing conn %p to %s\n", + conn, libcfs_nid2str(peer_ni->ibp_nid)); } else { - CNETERR("Closing conn to %s: error %d%s%s%s%s%s\n", + CNETERR("Closing conn %p to %s: error %d%s%s%s%s%s\n", + conn, libcfs_nid2str(peer_ni->ibp_nid), error, list_empty(&conn->ibc_tx_queue) ? "" : "(sending)", list_empty(&conn->ibc_tx_noops) ? "" : "(sending_noops)", @@ -2660,11 +2681,11 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, cp.retry_count = *kiblnd_tunables.kib_retry_count; cp.rnr_retry_count = *kiblnd_tunables.kib_rnr_retry_count; - CDEBUG(D_NET, "Accept %s\n", libcfs_nid2str(nid)); + CDEBUG(D_NET, "Accept %s conn %p\n", libcfs_nid2str(nid), conn); rc = rdma_accept(cmid, &cp); if (rc) { - CERROR("Can't accept %s: %d\n", libcfs_nid2str(nid), rc); + CNETERR("Can't accept %s: %d cm_id %p\n", libcfs_nid2str(nid), rc, cmid); rej.ibr_version = version; rej.ibr_why = IBLND_REJECT_FATAL; @@ -3085,10 +3106,13 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, rc = rdma_connect(cmid, &cp); if (rc) { - CERROR("Can't connect to %s: %d\n", - libcfs_nid2str(peer_ni->ibp_nid), rc); + CNETERR("Can't connect to %s: %d cm_id %p\n", + libcfs_nid2str(peer_ni->ibp_nid), rc, cmid); kiblnd_connreq_done(conn, rc); kiblnd_conn_decref(conn); + } else { + CDEBUG(D_NET, "Connected to %s: cm_id %p\n", + libcfs_nid2str(peer_ni->ibp_nid), cmid); } return 0; @@ -3112,13 +3136,13 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, rc = kiblnd_passive_connect(cmid, (void *)KIBLND_CONN_PARAM(event), KIBLND_CONN_PARAM_LEN(event)); - CDEBUG(D_NET, "connreq: %d\n", rc); + CDEBUG(D_NET, "connreq: %d cm_id %p\n", rc, cmid); return rc; case RDMA_CM_EVENT_ADDR_ERROR: peer_ni = (struct kib_peer_ni *)cmid->context; - CNETERR("%s: ADDR ERROR %d\n", - libcfs_nid2str(peer_ni->ibp_nid), event->status); + CNETERR("%s: ADDR ERROR %d cm_id %p\n", + libcfs_nid2str(peer_ni->ibp_nid), event->status, cmid); kiblnd_peer_connect_failed(peer_ni, 1, -EHOSTUNREACH); kiblnd_peer_decref(peer_ni); return -EHOSTUNREACH; /* rc destroys cmid */ @@ -3126,13 +3150,13 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, case RDMA_CM_EVENT_ADDR_RESOLVED: peer_ni = (struct kib_peer_ni *)cmid->context; - CDEBUG(D_NET, "%s Addr resolved: %d\n", - libcfs_nid2str(peer_ni->ibp_nid), event->status); + CDEBUG(D_NET, "%s Addr resolved: %d cm_id %p\n", + libcfs_nid2str(peer_ni->ibp_nid), event->status, cmid); if (event->status) { - CNETERR("Can't resolve address for %s: %d\n", + CNETERR("Can't resolve address for %s: %d cm_id %p\n", libcfs_nid2str(peer_ni->ibp_nid), - event->status); + event->status, cmid); rc = event->status; } else { rc = rdma_resolve_route(cmid, @@ -3151,8 +3175,8 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, } /* Can't initiate route resolution */ - CERROR("Can't resolve route for %s: %d\n", - libcfs_nid2str(peer_ni->ibp_nid), rc); + CNETERR("Can't resolve route for %s: %d cm_id %p\n", + libcfs_nid2str(peer_ni->ibp_nid), rc, cmid); } kiblnd_peer_connect_failed(peer_ni, 1, rc); kiblnd_peer_decref(peer_ni); @@ -3160,8 +3184,8 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, case RDMA_CM_EVENT_ROUTE_ERROR: peer_ni = (struct kib_peer_ni *)cmid->context; - CNETERR("%s: ROUTE ERROR %d\n", - libcfs_nid2str(peer_ni->ibp_nid), event->status); + CNETERR("%s: ROUTE ERROR %d cm_id %p\n", + libcfs_nid2str(peer_ni->ibp_nid), event->status, cmid); kiblnd_peer_connect_failed(peer_ni, 1, -EHOSTUNREACH); kiblnd_peer_decref(peer_ni); return -EHOSTUNREACH; /* rc destroys cmid */ @@ -3174,17 +3198,15 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, if (!event->status) return kiblnd_active_connect(cmid); - CNETERR("Can't resolve route for %s: %d\n", - libcfs_nid2str(peer_ni->ibp_nid), event->status); + CNETERR("Can't resolve route for %s: %d cm_id %p\n", + libcfs_nid2str(peer_ni->ibp_nid), event->status, cmid); kiblnd_peer_connect_failed(peer_ni, 1, event->status); kiblnd_peer_decref(peer_ni); return event->status; /* rc destroys cmid */ case RDMA_CM_EVENT_UNREACHABLE: - CNETERR("%s: UNREACHABLE %d, ibc_state: %d\n", - libcfs_nid2str(conn->ibc_peer->ibp_nid), - event->status, - conn->ibc_state); + CNETERR("%s: UNREACHABLE %d cm_id %p conn %p\n", + libcfs_nid2str(conn->ibc_peer->ibp_nid), event->status, cmid, conn); LASSERT(conn->ibc_state != IBLND_CONN_ESTABLISHED && conn->ibc_state != IBLND_CONN_INIT); if (conn->ibc_state == IBLND_CONN_ACTIVE_CONNECT || @@ -3198,8 +3220,8 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, conn = (struct kib_conn *)cmid->context; LASSERT(conn->ibc_state == IBLND_CONN_ACTIVE_CONNECT || conn->ibc_state == IBLND_CONN_PASSIVE_WAIT); - CNETERR("%s: CONNECT ERROR %d\n", - libcfs_nid2str(conn->ibc_peer->ibp_nid), event->status); + CNETERR("%s: CONNECT ERROR %d cm_id %p conn %p\n", + libcfs_nid2str(conn->ibc_peer->ibp_nid), event->status, cmid, conn); kiblnd_connreq_done(conn, -ENOTCONN); kiblnd_conn_decref(conn); return 0; @@ -3211,9 +3233,9 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, LBUG(); case IBLND_CONN_PASSIVE_WAIT: - CERROR("%s: REJECTED %d\n", + CERROR("%s: REJECTED %d cm_id %p\n", libcfs_nid2str(conn->ibc_peer->ibp_nid), - event->status); + event->status, cmid); kiblnd_connreq_done(conn, -ECONNRESET); break; @@ -3233,14 +3255,14 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, LBUG(); case IBLND_CONN_PASSIVE_WAIT: - CDEBUG(D_NET, "ESTABLISHED (passive): %s\n", - libcfs_nid2str(conn->ibc_peer->ibp_nid)); + CDEBUG(D_NET, "ESTABLISHED (passive): %s cm_id %p conn %p\n", + libcfs_nid2str(conn->ibc_peer->ibp_nid), cmid, conn); kiblnd_connreq_done(conn, 0); break; case IBLND_CONN_ACTIVE_CONNECT: - CDEBUG(D_NET, "ESTABLISHED(active): %s\n", - libcfs_nid2str(conn->ibc_peer->ibp_nid)); + CDEBUG(D_NET, "ESTABLISHED(active): %s cm_id %p conn %p\n", + libcfs_nid2str(conn->ibc_peer->ibp_nid), cmid, conn); kiblnd_check_connreply(conn, (void *)KIBLND_CONN_PARAM(event), KIBLND_CONN_PARAM_LEN(event)); @@ -3255,8 +3277,8 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, case RDMA_CM_EVENT_DISCONNECTED: conn = (struct kib_conn *)cmid->context; if (conn->ibc_state < IBLND_CONN_ESTABLISHED) { - CERROR("%s DISCONNECTED\n", - libcfs_nid2str(conn->ibc_peer->ibp_nid)); + CERROR("%s DISCONNECTED cm_id %p conn %p\n", + libcfs_nid2str(conn->ibc_peer->ibp_nid), cmid, conn); kiblnd_connreq_done(conn, -ECONNRESET); } else { kiblnd_close_conn(conn, 0); @@ -3372,6 +3394,9 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, conn->ibc_credits, conn->ibc_outstanding_credits, conn->ibc_reserved_credits); +#ifdef CONFIG_LUSTRE_DEBUG_EXPENSIVE_CHECK + kiblnd_dump_conn_dbg(conn); +#endif list_add(&conn->ibc_connd_list, &closes); } else { list_add(&conn->ibc_connd_list, &checksends); @@ -3425,7 +3450,9 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, LASSERT(!in_interrupt()); LASSERT(current == kiblnd_data.kib_connd); LASSERT(conn->ibc_state == IBLND_CONN_CLOSING); - +#ifdef CONFIG_LUSTRE_DEBUG_EXPENSIVE_CHECK + kiblnd_dump_conn_dbg(conn); +#endif rdma_disconnect(conn->ibc_cmid); kiblnd_finalise_conn(conn); @@ -3716,6 +3743,7 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, (conn->ibc_nrx > 0 || conn->ibc_nsends_posted > 0)) { kiblnd_conn_addref(conn); /* +1 ref for sched_conns */ + kiblnd_dump_conn_dbg(conn); conn->ibc_scheduled = 1; list_add_tail(&conn->ibc_sched_list, &sched->ibs_conns); @@ -3788,8 +3816,9 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, rc = ib_req_notify_cq(conn->ibc_cq, IB_CQ_NEXT_COMP); if (rc < 0) { - CWARN("%s: ib_req_notify_cq failed: %d, closing connection\n", - libcfs_nid2str(conn->ibc_peer->ibp_nid), rc); + CWARN("%s: ib_req_notify_cq failed: %d, closing connection %p\n", + libcfs_nid2str(conn->ibc_peer->ibp_nid), + rc, conn); kiblnd_close_conn(conn, -EIO); kiblnd_conn_decref(conn); spin_lock_irqsave(&sched->ibs_lock, @@ -3810,9 +3839,9 @@ static int kiblnd_map_tx(struct lnet_ni *ni, struct kib_tx *tx, } if (rc < 0) { - CWARN("%s: ib_poll_cq failed: %d, closing connection\n", + CWARN("%s: ib_poll_cq failed: %d, closing connection %p\n", libcfs_nid2str(conn->ibc_peer->ibp_nid), - rc); + rc, conn); kiblnd_close_conn(conn, -EIO); kiblnd_conn_decref(conn); spin_lock_irqsave(&sched->ibs_lock, flags);

[05/22] lnet: o2iblnd: add verbose debug prints for rx/tx events

Commit Message

Patch