UCT/IB: Add option to print periodic ep/iface status information

src/ucs/sys/sock.c

@@ -97,8 +97,8 @@ unsigned ucs_netif_bond_ad_num_ports(const char *bond_name)
                                   UCS_NETIF_BOND_AD_NUM_PORTS_FMT, bond_name);
     if ((status != UCS_OK) || (ad_num_ports <= 0) ||
         (ad_num_ports > UINT_MAX)) {
-        ucs_diag("failed to read from " UCS_NETIF_BOND_AD_NUM_PORTS_FMT ": %m, "
-                 "assuming 802.3ad bonding is disabled", bond_name);
+        ucs_debug("failed to read from " UCS_NETIF_BOND_AD_NUM_PORTS_FMT ": %m, "
+                  "assuming 802.3ad bonding is disabled", bond_name);
         return 1;
     }
 
@@ -761,7 +761,7 @@ ucs_status_t ucs_sockaddr_get_ifname(int fd, char *ifname_str, size_t max_strlen
         return UCS_ERR_INVALID_PARAM;
     }
 
-    ucs_debug("check ifname for socket on %s", 
+    ucs_debug("check ifname for socket on %s",
               ucs_sockaddr_str(my_addr, str_local_addr, UCS_SOCKADDR_STRING_LEN));
 
     if (getifaddrs(&ifaddrs)) {
@@ -777,7 +777,7 @@ ucs_status_t ucs_sockaddr_get_ifname(int fd, char *ifname_str, size_t max_strlen
             continue;
         }
 
-        if (((sa->sa_family == AF_INET) ||(sa->sa_family == AF_INET6)) && 
+        if (((sa->sa_family == AF_INET) ||(sa->sa_family == AF_INET6)) &&
             (!ucs_sockaddr_cmp(sa, my_addr, NULL))) {
             ucs_debug("matching ip found iface on %s", ifa->ifa_name);
             ucs_strncpy_safe(ifname_str, ifa->ifa_name, max_strlen);

src/uct/base/uct_iface.c

@@ -498,7 +498,8 @@ UCS_CLASS_INIT_FUNC(uct_base_iface_t, uct_iface_ops_t *ops, uct_md_h md,
         alloc_methods_bitmap |= UCS_BIT(method);
     }
 
-    self->config.failure_level = (ucs_log_level_t)config->failure;
+    self->config.failure_level = (ucs_log_level_t)config->failure_log_level;
+    self->config.trace_level   = (ucs_log_level_t)config->trace_log_level;
     self->config.max_num_eps   = config->max_num_eps;
 
     return UCS_STATS_NODE_ALLOC(&self->stats, &uct_iface_stats_class,
@@ -623,7 +624,13 @@ ucs_config_field_t uct_iface_config_table[] = {
 
   {"FAILURE", "error",
    "Level of network failure reporting",
-   ucs_offsetof(uct_iface_config_t, failure), UCS_CONFIG_TYPE_ENUM(ucs_log_level_names)},
+   ucs_offsetof(uct_iface_config_t, failure_log_level),
+   UCS_CONFIG_TYPE_ENUM(ucs_log_level_names)},
+
+  {"TRACE", "trace",
+   "Level of periodic traces",
+   ucs_offsetof(uct_iface_config_t, trace_log_level),
+   UCS_CONFIG_TYPE_ENUM(ucs_log_level_names)},
 
   {"MAX_NUM_EPS", "inf",
    "Maximum number of endpoints that the transport interface is able to create",

src/uct/base/uct_iface.h

@@ -221,6 +221,7 @@ typedef struct uct_base_iface {
         unsigned            num_alloc_methods;
         uct_alloc_method_t  alloc_methods[UCT_ALLOC_METHOD_LAST];
         ucs_log_level_t     failure_level;
+        ucs_log_level_t     trace_level;
         size_t              max_num_eps;
     } config;
 
@@ -319,7 +320,8 @@ struct uct_iface_config {
         unsigned            count;
     } alloc_methods;
 
-    int               failure;   /* Level of failure reports */
+    int               failure_log_level; /* Level of failure reports */
+    int               trace_log_level;   /* Level of periodic trace */
     size_t            max_num_eps;
 };
 

src/uct/ib/rc/accel/rc_mlx5_common.c

@@ -149,7 +149,7 @@ unsigned uct_rc_mlx5_iface_srq_post_recv(uct_rc_mlx5_iface_common_t *iface)
 void uct_rc_mlx5_iface_common_prepost_recvs(uct_rc_mlx5_iface_common_t *iface)
 {
     /* prepost recvs only if quota available (recvs were not preposted
-     * before) */ 
+     * before) */
     if (iface->super.rx.srq.quota == 0) {
         return;
     }
@@ -1189,16 +1189,57 @@ void uct_rc_mlx5_iface_commom_cq_clean_tx(uct_rc_mlx5_iface_common_t *iface,
     uct_rc_mlx5_common_iface_cq_available_check(iface);
 }
 
+void UCS_F_NOINLINE
+uct_rc_mlx5_iface_print_eps(uct_rc_mlx5_iface_common_t *mlx5_iface,
+                            ucs_log_level_t log_level)
+{
+    uct_rc_mlx5_ep_t *ep;
+
+    ucs_list_for_each(ep, &mlx5_iface->super.ep_list, super.list) {
+        ucs_log(log_level, "ep %p: txq [qpn 0x%x rqpn 0x%x n 0x%x avail %d unsig %u]",
+                ep, ep->tx.wq.super.qp_num, ep->super.remove_qpn, ep->tx.wq.bb_max,
+                ep->super.txqp.available, ep->super.txqp.unsignaled);
+    }
+}
+
 void uct_rc_mlx5_iface_print(uct_rc_mlx5_iface_common_t *mlx5_iface,
-                             const char *title)
+                             int print_all_eps, const char *title)
 {
-    ucs_trace("%s: txcq [n 0x%x avail %d ci 0x%x] rcxq [n 0x%x ci 0x%x] "
-            "srq [n 0x%x avail %d]", title,
-            mlx5_iface->cq[UCT_IB_DIR_TX].cq_num,
-            mlx5_iface->super.tx.cq_available,
+    ucs_log_level_t log_level = mlx5_iface->super.super.super.config.trace_level;
+    unsigned total_outstanding, cq_credits_used;
+    uct_rc_mlx5_ep_t *ep;
+    unsigned cq_max;
+
+    if (!ucs_log_is_enabled(log_level)) {
+        return;
+    }
+
+    cq_max = mlx5_iface->super.config.tx_cq_len - 2;
+    ucs_log(log_level, "%s: iface %p txcq [n 0x%x avail %d(+%d)/%d ci 0x%x] rcxq [n 0x%x ci 0x%x] "
+            "srq [n 0x%x avail %d fidx %u ridx %u swpi %u]",
+            title, mlx5_iface, mlx5_iface->cq[UCT_IB_DIR_TX].cq_num,
+            mlx5_iface->super.tx.cq_available, mlx5_iface->super.tx.cq_free,
+            cq_max,
             mlx5_iface->cq[UCT_IB_DIR_TX].cq_ci,
             mlx5_iface->cq[UCT_IB_DIR_RX].cq_num,
-            mlx5_iface->cq[UCT_IB_DIR_RX].cq_ci,
-            mlx5_iface->rx.srq.srq_num,
-            mlx5_iface->super.rx.srq.available);
+            mlx5_iface->cq[UCT_IB_DIR_RX].cq_ci, mlx5_iface->rx.srq.srq_num,
+            mlx5_iface->super.rx.srq.available, mlx5_iface->rx.srq.free_idx,
+            mlx5_iface->rx.srq.ready_idx, mlx5_iface->rx.srq.sw_pi);
+
+    total_outstanding = 0;
+    cq_credits_used = cq_max - mlx5_iface->super.tx.cq_available -
+                      mlx5_iface->super.tx.cq_free;
+    ucs_list_for_each(ep, &mlx5_iface->super.ep_list, super.list) {
+        total_outstanding += ep->tx.wq.bb_max - ep->super.txqp.available;
+    }
+
+    if (cq_credits_used > total_outstanding) {
+        uct_rc_mlx5_iface_print_eps(mlx5_iface, UCS_LOG_LEVEL_DIAG);
+        ucs_warn("iface %p: detected CQ resource leak: cq_credits_used %d total_outstanding %d",
+                    mlx5_iface, cq_credits_used, total_outstanding);
+    }
+
+    if ((mlx5_iface->super.tx.cq_available == 0) || print_all_eps) {
+        uct_rc_mlx5_iface_print_eps(mlx5_iface, log_level);
+    }
 }

src/uct/ib/rc/accel/rc_mlx5_common.h

@@ -765,6 +765,6 @@ uct_rc_mlx5_common_iface_init_rx(uct_rc_mlx5_iface_common_t *iface,
 void uct_rc_mlx5_destroy_srq(uct_ib_mlx5_srq_t *srq);
 
 void uct_rc_mlx5_iface_print(uct_rc_mlx5_iface_common_t *mlx5_iface,
-                             const char *title);
+                             int print_all_eps, const char *title);
 
 #endif

src/uct/ib/rc/accel/rc_mlx5_ep.c

@@ -701,6 +701,7 @@ ucs_status_t uct_rc_mlx5_ep_connect_to_ep(uct_ep_h tl_ep,
     }
 
     ep->atomic_mr_offset = uct_ib_md_atomic_offset(rc_addr->atomic_mr_id);
+    ep->super.remove_qpn = qp_num;
 
     return UCS_OK;
 }
@@ -891,7 +892,7 @@ UCS_CLASS_INIT_FUNC(uct_rc_mlx5_ep_t, const uct_ep_params_t *params)
     uct_ib_qp_attr_t attr = {};
     ucs_status_t status;
 
-    uct_rc_mlx5_iface_print(iface, "ep_create");
+    uct_rc_mlx5_iface_print(iface, 0, "ep_create");
 
     self->connected = 0;
 

src/uct/ib/rc/accel/rc_mlx5_iface.c

@@ -120,7 +120,7 @@ uct_rc_mlx5_iface_poll_tx(uct_rc_mlx5_iface_common_t *iface)
                             uct_rc_mlx5_ep_t);
     if (ucs_unlikely(ep == NULL)) {
         /* TODO replace the warning with assertion for optimization */
-        ucs_warn("completion ignored on QP 0x%x index %d",
+        ucs_warn("tx completion ignored on QP 0x%x index %d",
                  qp_num, htons(cqe->wqe_counter));
         return 1;
     }
@@ -185,7 +185,7 @@ uct_rc_mlx5_common_ka_progress(uct_rc_mlx5_iface_common_t *iface)
     }
     ucs_spin_unlock(&iface->super.ep_list_lock);
 
-    uct_rc_mlx5_iface_print(iface, "keepalive");
+    uct_rc_mlx5_iface_print(iface, 1, "keepalive");
 
     iface->keepalive.time = ucs_get_time() + iface->config.ka_interval;
 

src/uct/ib/rc/base/rc_ep.h

@@ -201,6 +201,7 @@ struct uct_rc_ep {
     uct_rc_txqp_t       txqp;
     ucs_list_link_t     list;
     ucs_arbiter_group_t arb_group;
+    uint32_t            remove_qpn;
     uct_rc_fc_t         fc;
     uint8_t             path_index;
 };