UCT/IB: Dump complete packets in trace-data logs

src/uct/base/uct_log.h

@@ -26,7 +26,7 @@
  */
 typedef void (*uct_log_data_dump_func_t)(uct_base_iface_t *iface,
                                          uct_am_trace_type_t type, void *data,
-                                         size_t length, size_t valid_length,
-                                         char *buffer, size_t max);
+                                         size_t length, char *buffer,
+                                         size_t max);
 
 #endif

src/uct/ib/base/ib_log.c

@@ -45,13 +45,13 @@ void uct_ib_log_dump_sg_list(uct_ib_iface_t *iface, uct_am_trace_type_t type,
                              uct_log_data_dump_func_t data_dump,
                              int data_dump_sge, char *buf, size_t max)
 {
-    char data[256];
-    size_t total_len       = 0;
-    size_t total_valid_len = 0;
-    char *s    = buf;
-    char *ends = buf + max;
-    void *md   = data;
-    size_t len;
+    int dump_sge     = ucs_min(num_sge, data_dump_sge);
+    size_t total_len = 0;
+    size_t offset    = 0;
+    char *s          = buf;
+    char *ends       = buf + max;
+    size_t dump_len, len;
+    void *data;
     int i;
 
     for (i = 0; i < num_sge; ++i) {
@@ -63,22 +63,51 @@ void uct_ib_log_dump_sg_list(uct_ib_iface_t *iface, uct_am_trace_type_t type,
                      sg_list[i].addr, sg_list[i].length, sg_list[i].lkey);
         }
 
-        s               += strlen(s);
-
-        if ((i < data_dump_sge) && data_dump) {
-            len = ucs_min(sg_list[i].length,
-                          UCS_PTR_BYTE_DIFF(md, data) + sizeof(data));
-            memcpy(md, (void*)sg_list[i].addr, len);
+        s += strlen(s);
 
-            md               = UCS_PTR_BYTE_OFFSET(md, len);
-            total_len       += len;
-            total_valid_len += sg_list[i].length;
+        if (i < dump_sge) {
+            total_len += sg_list[i].length;
         }
     }
 
-    if (data_dump) {
-        data_dump(&iface->super, type, data, total_len, total_valid_len, s, ends - s);
+    /* Every dump callback starts by reading a header out of the data, so
+     * there is nothing it can print when no data was collected */
+    if ((data_dump == NULL) || (total_len == 0)) {
+        return;
+    }
+
+    if (dump_sge == 1) {
+        /* A single segment is contiguous, pass it as it is */
+        data_dump(&iface->super, type, (void*)sg_list[0].addr, total_len, s,
+                  ends - s);
+        return;
+    }
+
+    /* A dump callback parses the message by its own headers, so gather the
+     * scattered segments for it. A segment holds every header the transport
+     * can send, and the payload past it is not parsed, so stop at that much. */
+    dump_len = ucs_min(total_len, iface->config.seg_size);
+    data     = ucs_alloc_on_stack(dump_len, "ib_log_data");
+    if (data == NULL) {
+        return;
+    }
+
+    for (i = 0; (i < dump_sge) && (offset < dump_len); ++i) {
+        len = ucs_min(sg_list[i].length, dump_len - offset);
+        memcpy(UCS_PTR_BYTE_OFFSET(data, offset), (void*)sg_list[i].addr, len);
+        offset += len;
     }
+
+    data_dump(&iface->super, type, data, dump_len, s, ends - s);
+    ucs_free_on_stack(data, dump_len);
+}
+
+void uct_ib_log_mark_line_cut(char *buf, size_t max)
+{
+    static const char ellipsis[] = "...";
+
+    ucs_assertv(max >= sizeof(ellipsis), "max=%zu", max);
+    strcpy(buf + max - sizeof(ellipsis), ellipsis);
 }
 
 void uct_ib_log_dump_remote_addr(uint64_t remote_addr, uint32_t rkey,
@@ -148,8 +177,8 @@ void uct_ib_log_dump_recv_completion(uct_ib_iface_t *iface, uint32_t local_qp,
     s += strlen(s);
 
     if (data_dump != NULL) {
-        data_dump(&iface->super, UCT_AM_TRACE_TYPE_RECV, data, length, length,
-                  s, ends - s);
+        data_dump(&iface->super, UCT_AM_TRACE_TYPE_RECV, data, length, s,
+                  ends - s);
     }
 }
 
@@ -260,10 +289,11 @@ void __uct_ib_log_post_send_one(const char *file, int line,
                                 int max_sge,
                                 uct_log_data_dump_func_t data_dump_cb)
 {
-    char buf[256] = {0};
+    char buf[UCT_IB_LOG_LINE_LEN] = {0};
 
     uct_ib_dump_send_wr(iface, qp, wr, max_sge, data_dump_cb, ah, remote_qpn,
                         buf, sizeof(buf) - 1);
+    uct_ib_log_mark_line_cut(buf, sizeof(buf));
     uct_log_data(file, line, function, buf);
 }
 
@@ -295,7 +325,7 @@ void __uct_ib_log_recv_completion(const char *file, int line, const char *functi
                                   size_t length,
                                   uct_log_data_dump_func_t packet_dump_cb)
 {
-    char buf[256] = {0};
+    char buf[UCT_IB_LOG_LINE_LEN] = {0};
     size_t len;
 
     len = length;
@@ -305,5 +335,6 @@ void __uct_ib_log_recv_completion(const char *file, int line, const char *functi
     }
     uct_ib_log_dump_recv_completion(iface, l_qp, r_qp, slid, data, len,
                                     packet_dump_cb, buf, sizeof(buf) - 1);
+    uct_ib_log_mark_line_cut(buf, sizeof(buf));
     uct_log_data(file, line, function, buf);
 }

src/uct/ib/base/ib_log.h

@@ -15,6 +15,10 @@
 #include <ucs/sys/math.h>
 
 
+/* Length of a packet description line */
+#define UCT_IB_LOG_LINE_LEN 256
+
+
 enum {
     UCT_IB_OPCODE_FLAG_HAS_RADDR       = UCS_BIT(0),
     UCT_IB_OPCODE_FLAG_HAS_ATOMIC      = UCS_BIT(1),
@@ -40,6 +44,15 @@ void uct_ib_log_dump_sg_list(uct_ib_iface_t *iface, uct_am_trace_type_t type,
                              uct_log_data_dump_func_t data_dump,
                              int data_dump_sge, char *buf, size_t max);
 
+/**
+ * Stamp the end of a packet description line with an ellipsis, so that a
+ * description which was cut is not read as a complete one.
+ *
+ * @param buf Packet description.
+ * @param max Size of the description buffer.
+ */
+void uct_ib_log_mark_line_cut(char *buf, size_t max);
+
 void uct_ib_log_dump_remote_addr(uint64_t remote_addr, uint32_t rkey,
                                  char *buf, size_t max);
 

src/uct/ib/efa/srd/srd_log.c

@@ -37,8 +37,7 @@ static void uct_srd_dump_ctl_hdr(char *p, char *endp, uct_srd_ctl_hdr_t *ctl)
 }
 
 void uct_srd_dump_packet(uct_base_iface_t *iface, uct_am_trace_type_t type,
-                         void *data, size_t length, size_t valid_length,
-                         char *buffer, size_t max)
+                         void *data, size_t length, char *buffer, size_t max)
 {
     uct_srd_hdr_t *hdr = data;
     char *p, *endp;

src/uct/ib/efa/srd/srd_log.h

@@ -17,8 +17,7 @@
 
 
 void uct_srd_dump_packet(uct_base_iface_t *iface, uct_am_trace_type_t type,
-                         void *data, size_t length, size_t valid_length,
-                         char *buffer, size_t max);
+                         void *data, size_t length, char *buffer, size_t max);
 
 
 const char *uct_srd_ctl_id_to_string(uct_srd_ctl_id_t id);

src/uct/ib/mlx5/ib_mlx5_log.c

@@ -492,15 +492,16 @@ void __uct_ib_mlx5_log_tx(const char *file, int line, const char *function,
                           void *qend, int max_sge, uct_ib_log_sge_t *log_sge,
                           uct_log_data_dump_func_t packet_dump_cb)
 {
-    char buf[256] = {0};
+    char buf[UCT_IB_LOG_LINE_LEN] = {0};
     uct_ib_mlx5_wqe_dump(iface, wqe, qstart, qend, max_sge, 1, packet_dump_cb,
                          buf, sizeof(buf) - 1, log_sge);
+    uct_ib_log_mark_line_cut(buf, sizeof(buf));
     uct_log_data(file, line, function, buf);
 }
 
 void uct_ib_mlx5_cqe_dump(const char *file, int line, const char *function, struct mlx5_cqe64 *cqe)
 {
-    char buf[256] = {0};
+    char buf[UCT_IB_LOG_LINE_LEN] = {0};
 
     snprintf(buf, sizeof(buf) - 1,
             "CQE(op_own 0x%x) qp 0x%x sqp 0x%x slid %d bytes %d wqe_idx %d ",
@@ -562,7 +563,7 @@ void __uct_ib_mlx5_log_rx(const char *file, int line, const char *function,
                           uct_ib_iface_t *iface, struct mlx5_cqe64 *cqe,
                           void *data, uct_log_data_dump_func_t packet_dump_cb)
 {
-    char buf[256] = {0};
+    char buf[UCT_IB_LOG_LINE_LEN] = {0};
     size_t length;
 
     length = ntohl(cqe->byte_cnt) & UCT_IB_MLX5_MP_RQ_BYTE_CNT_MASK;
@@ -576,5 +577,6 @@ void __uct_ib_mlx5_log_rx(const char *file, int line, const char *function,
                                     ntohs(cqe->slid),
                                     data, length,
                                     packet_dump_cb, buf, sizeof(buf) - 1);
+    uct_ib_log_mark_line_cut(buf, sizeof(buf));
     uct_log_data(file, line, function, buf);
 }

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

@@ -696,8 +696,8 @@ void uct_rc_mlx5_iface_common_tag_cleanup(uct_rc_mlx5_iface_common_t *iface);
 ucs_status_t uct_rc_mlx5_ep_tag_rndv_cancel(uct_ep_h tl_ep, void *op);
 
 void uct_rc_mlx5_common_packet_dump(uct_base_iface_t *iface, uct_am_trace_type_t type,
-                                    void *data, size_t length, size_t valid_length,
-                                    char *buffer, size_t max);
+                                    void *data, size_t length, char *buffer,
+                                    size_t max);
 
 static UCS_F_ALWAYS_INLINE void
 uct_rc_mlx5_am_hdr_fill(uct_rc_mlx5_hdr_t *rch, uint8_t id)

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

@@ -1420,8 +1420,8 @@ ucs_status_t uct_rc_mlx5_ep_get_address(uct_ep_h tl_ep, uct_ep_addr_t *addr)
 }
 
 void uct_rc_mlx5_common_packet_dump(uct_base_iface_t *iface, uct_am_trace_type_t type,
-                                    void *data, size_t length, size_t valid_length,
-                                    char *buffer, size_t max)
+                                    void *data, size_t length, char *buffer,
+                                    size_t max)
 {
     uct_rc_mlx5_hdr_t *rch = data;
 
@@ -1454,8 +1454,8 @@ void uct_rc_mlx5_common_packet_dump(uct_base_iface_t *iface, uct_am_trace_type_t
 
     data = &rch->rc_hdr;
     /* coverity[overrun-buffer-val] */
-    uct_rc_ep_packet_dump(iface, type, data, length - UCS_PTR_BYTE_DIFF(rch, data),
-                          valid_length, buffer, max);
+    uct_rc_ep_packet_dump(iface, type, data,
+                          length - UCS_PTR_BYTE_DIFF(rch, data), buffer, max);
 }
 
 void uct_rc_mlx5_txwq_set_path_mtu(uct_ib_mlx5_txwq_t *txwq,

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

@@ -195,8 +195,7 @@ static UCS_CLASS_CLEANUP_FUNC(uct_rc_ep_t)
 UCS_CLASS_DEFINE(uct_rc_ep_t, uct_base_ep_t)
 
 void uct_rc_ep_packet_dump(uct_base_iface_t *iface, uct_am_trace_type_t type,
-                           void *data, size_t length, size_t valid_length,
-                           char *buffer, size_t max)
+                           void *data, size_t length, char *buffer, size_t max)
 {
     uct_rc_hdr_t *rch = data;
     uint8_t fc_hdr    = uct_rc_fc_get_fc_hdr(rch->am_id);

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

@@ -240,8 +240,7 @@ UCS_CLASS_DECLARE(uct_rc_ep_t, uct_rc_iface_t*, uint32_t, const uct_ep_params_t*
 
 
 void uct_rc_ep_packet_dump(uct_base_iface_t *iface, uct_am_trace_type_t type,
-                           void *data, size_t length, size_t valid_length,
-                           char *buffer, size_t max);
+                           void *data, size_t length, char *buffer, size_t max);
 
 void uct_rc_ep_send_op_set_iov(uct_rc_iface_send_op_t *op, const uct_iov_t *iov,
                                size_t iovcnt);

src/uct/ib/ud/base/ud_iface.h

@@ -287,8 +287,7 @@ uct_ud_iface_set_event_cb(uct_ud_iface_t *iface, ucs_async_event_cb_t event_cb);
 void uct_ud_iface_remove_async_handlers(uct_ud_iface_t *iface);
 
 void uct_ud_dump_packet(uct_base_iface_t *iface, uct_am_trace_type_t type,
-                        void *data, size_t length, size_t valid_length,
-                        char *buffer, size_t max);
+                        void *data, size_t length, char *buffer, size_t max);
 
 union ibv_gid* uct_ud_grh_get_dgid(struct ibv_grh *grh, size_t dgid_len);
 

src/uct/ib/ud/base/ud_log.c

@@ -13,8 +13,7 @@
 
 
 void uct_ud_dump_packet(uct_base_iface_t *iface, uct_am_trace_type_t type,
-                        void *data, size_t length, size_t valid_length,
-                        char *buffer, size_t max)
+                        void *data, size_t length, char *buffer, size_t max)
 {
     uct_ud_neth_t *neth = data;
     uct_ud_put_hdr_t *puth;