prov/efa: Add passive debug instrumentation for duplicate completion diagnosis

Add circular buffer to track packet lifecycle events for diagnosing
'Packet already processed' errors.

Key features:
- 9 event types: SEND/RECV/READ/WRITE × POST/COMPLETION + RECV_RDMA_WITH_IMM
- 48 entries per packet (8 bytes each)
- Debug info allocated separately from buffer pool
- Packet struct remains 128 bytes (no size increase)
- Zero overhead in production builds

Implementation:
- New struct efa_rdm_pke_debug_info_buffer (392 bytes)
  - 1 byte counter + 7 bytes padding + 384 bytes entries
- Packet entry has 8-byte pointer to debug buffer
- Buffer allocated on first use, reused across packet lifetime
- History preserved across packet reuse (when poisoning enabled)
- ASAN builds: always allocate fresh (no history preservation)
- NULL checks prevent crashes if allocation fails

Memory layout:
- Debug buffer: counter (1) + padding (7) + entries (48 × 8)
- Bit packing: qpn (10 bits) + gen (6 bits) in 16-bit field
- Event type in separate byte (9 types: 0-8)

Signed-off-by: Yin Li <yinliq@amazon.com>

Author: yinliaws

prov/efa/src/rdm/efa_rdm_cq.c

@@ -230,6 +230,14 @@ static void efa_rdm_cq_proc_ibv_recv_rdma_with_imm_completion(
 		 */
 		assert(pkt_entry);
 		ep->efa_rx_pkts_posted--;
+#if ENABLE_DEBUG
+		/* Record RECV_RDMA_WITH_IMM event */
+		efa_rdm_pke_record_debug_info(pkt_entry,
+		                               ep->base_ep.qp->qp_num,
+		                               ep->base_ep.qp->qkey,
+		                               pkt_entry->gen,
+		                               EFA_RDM_PKE_DEBUG_EVENT_RECV_RDMA_WITH_IMM);
+#endif
 		efa_rdm_cq_increment_pkt_entry_gen(pkt_entry);
 		efa_rdm_pke_release_rx(pkt_entry);
 	}
@@ -524,6 +532,15 @@ static void efa_rdm_cq_handle_recv_completion(struct efa_ibv_cq *ibv_cq, struct
 	uint32_t imm_data = 0;
 	bool has_imm_data = false;
 
+#if ENABLE_DEBUG
+	/* Record RECV_COMPLETION event */
+	efa_rdm_pke_record_debug_info(pkt_entry,
+	                               ep->base_ep.qp->qp_num,
+	                               ep->base_ep.qp->qkey,
+	                               pkt_entry->gen,
+	                               EFA_RDM_PKE_DEBUG_EVENT_RECV_COMPLETION);
+#endif
+
 	EFA_DBG(FI_LOG_CQ, "Processing receive completion for packet %p\n", pkt_entry);
 
 	if (pkt_entry->alloc_type == EFA_RDM_PKE_FROM_USER_RX_POOL) {

prov/efa/src/rdm/efa_rdm_ep.h

@@ -131,6 +131,8 @@ struct efa_rdm_ep {
 	struct ofi_bufpool *peer_robuf_pool;
 
 #if ENABLE_DEBUG
+	/* buffer pool for packet debug info */
+	struct ofi_bufpool *pke_debug_info_pool;
 	/* tx/rx_entries waiting to receive data in
          * long CTS msg/read/write protocols */
 	struct dlist_entry ope_recv_list;

prov/efa/src/rdm/efa_rdm_ep_fiops.c

@@ -292,6 +292,18 @@ int efa_rdm_ep_create_buffer_pools(struct efa_rdm_ep *ep)
 	if (ret)
 		goto err_free;
 
+#if ENABLE_DEBUG
+	/* Create debug info pool - one buffer per packet entry */
+	ret = ofi_bufpool_create(&ep->pke_debug_info_pool,
+				 sizeof(struct efa_rdm_pke_debug_info_buffer),
+				 EFA_RDM_BUFPOOL_ALIGNMENT,
+				 0, /* no limit to max_cnt */
+				 efa_rdm_ep_get_tx_pool_size(ep) + efa_rdm_ep_get_rx_pool_size(ep),
+				 OFI_BUFPOOL_NO_TRACK);
+	if (ret)
+		goto err_free;
+#endif
+
 	return 0;
 
 err_free:
@@ -331,6 +343,11 @@ int efa_rdm_ep_create_buffer_pools(struct efa_rdm_ep *ep)
 	if (ep->peer_robuf_pool)
 		ofi_bufpool_destroy(ep->peer_robuf_pool);
 
+#if ENABLE_DEBUG
+	if (ep->pke_debug_info_pool)
+		ofi_bufpool_destroy(ep->pke_debug_info_pool);
+#endif
+
 	return ret;
 }
 
@@ -889,6 +906,11 @@ static void efa_rdm_ep_destroy_buffer_pools(struct efa_rdm_ep *efa_rdm_ep)
 
 	if (efa_rdm_ep->peer_robuf_pool)
 		ofi_bufpool_destroy(efa_rdm_ep->peer_robuf_pool);
+
+#if ENABLE_DEBUG
+	if (efa_rdm_ep->pke_debug_info_pool)
+		ofi_bufpool_destroy(efa_rdm_ep->pke_debug_info_pool);
+#endif
 }
 
 /**

prov/efa/src/rdm/efa_rdm_ep_utils.c

@@ -381,6 +381,24 @@ void efa_rdm_ep_record_tx_op_submitted(struct efa_rdm_ep *ep, struct efa_rdm_pke
 	}
 #if ENABLE_DEBUG
 	ep->efa_total_posted_tx_ops++;
+	/* Record post event based on operation type */
+	int event_type;
+	switch (ope->op) {
+	case ofi_op_read_req:
+		event_type = EFA_RDM_PKE_DEBUG_EVENT_READ_POST;
+		break;
+	case ofi_op_write:
+		event_type = EFA_RDM_PKE_DEBUG_EVENT_WRITE_POST;
+		break;
+	default:
+		event_type = EFA_RDM_PKE_DEBUG_EVENT_SEND_POST;
+		break;
+	}
+	efa_rdm_pke_record_debug_info(pkt_entry,
+	                               ep->base_ep.qp->qp_num,
+	                               ep->base_ep.qp->qkey,
+	                               pkt_entry->gen,
+	                               event_type);
 #endif
 }
 
@@ -421,6 +439,31 @@ void efa_rdm_ep_record_tx_op_completed(struct efa_rdm_ep *ep, struct efa_rdm_pke
 {
 	struct efa_rdm_ope *ope = NULL;
 
+#if ENABLE_DEBUG
+	/*
+	 * Record completion event based on operation type.
+	 * Note: qp_num is truncated to 10 bits, gen to 6 bits.
+	 */
+	int event_type = EFA_RDM_PKE_DEBUG_EVENT_SEND_COMPLETION;
+	if (pkt_entry->ope) {
+		switch (pkt_entry->ope->op) {
+		case ofi_op_read_req:
+			event_type = EFA_RDM_PKE_DEBUG_EVENT_READ_COMPLETION;
+			break;
+		case ofi_op_write:
+			event_type = EFA_RDM_PKE_DEBUG_EVENT_WRITE_COMPLETION;
+			break;
+		default:
+			break;
+		}
+	}
+	efa_rdm_pke_record_debug_info(pkt_entry,
+	                               ep->base_ep.qp->qp_num,
+	                               ep->base_ep.qp->qkey,
+	                               pkt_entry->gen,
+	                               event_type);
+#endif
+
 	ope = pkt_entry->ope;
 	/*
 	 * peer can be NULL when:

prov/efa/src/rdm/efa_rdm_peer.c

@@ -163,6 +163,15 @@ int efa_rdm_peer_reorder_msg(struct efa_rdm_peer *peer, struct efa_rdm_ep *ep,
 			EFA_WARN(FI_LOG_EP_CTRL,
 			       "Error: message id has already been processed. received: %" PRIu32 " expected: %"
 			       PRIu32 "\n", msg_id, ofi_recvwin_next_exp_id(robuf));
+
+#if ENABLE_DEBUG
+			/* Print debug info on duplicate message */
+			EFA_WARN(FI_LOG_EP_CTRL,
+			         "  pkt_entry=%p gen=%u\n"
+			         "  Debug info history:\n",
+			         pkt_entry, pkt_entry->gen);
+			efa_rdm_pke_print_debug_info(pkt_entry);
+#endif
 			return -FI_EALREADY;
 		} else {
 			/* Current receive window size is too small to hold incoming messages.

prov/efa/src/rdm/efa_rdm_pke.c

@@ -45,11 +45,49 @@ struct efa_rdm_pke *efa_rdm_pke_alloc(struct efa_rdm_ep *ep,
 	if (!pkt_entry)
 		return NULL;
 
+#ifdef ENABLE_EFA_POISONING
+	/* Preserve gen across poisoning */
+	uint8_t gen = pkt_entry->gen;
+#if ENABLE_DEBUG
+	/* Preserve debug_info pointer across poisoning to maintain packet history.
+	 * On first allocation from a freshly poisoned region, this will be 0xdeadbeef.
+	 * On reuse, this preserves the existing buffer. */
+	struct efa_rdm_pke_debug_info_buffer *debug_info = pkt_entry->debug_info;
+	/* If debug_info contains poison pattern, treat as NULL (uninitialized).
+	 * This happens when packets are allocated from freshly poisoned bufpool regions. */
+	if (((uintptr_t)debug_info & 0xffffffffUL) == 0xdeadbeefUL) {
+		debug_info = NULL;
+	}
+#endif
+	efa_rdm_poison_mem_region(pkt_entry, pkt_pool->attr.size);
+	pkt_entry->gen = gen;
+#if ENABLE_DEBUG
+	pkt_entry->debug_info = debug_info;
+#endif
+#endif
+	/* Without poisoning, debug_info pointer is naturally preserved in memory. */
+
 	pkt_entry->gen &= EFA_RDM_PACKET_GEN_MASK;
 	dlist_init(&pkt_entry->entry);
 
 #if ENABLE_DEBUG
 	dlist_init(&pkt_entry->dbg_entry);
+	/* Allocate debug info if not already allocated */
+	if (!pkt_entry->debug_info) {
+		pkt_entry->debug_info = ofi_buf_alloc(ep->pke_debug_info_pool);
+		if (!pkt_entry->debug_info) {
+			/* Debug info allocation failed from unlimited pool - indicates heap exhaustion.
+			 * Write EQ error since retrying won't help (debug_info is never released). */
+			EFA_WARN(FI_LOG_EP_CTRL,
+				"Failed to allocate debug_info buffer from unlimited pool - heap exhaustion likely\n");
+			efa_base_ep_write_eq_error(&ep->base_ep, FI_ENOMEM, FI_EFA_ERR_OOM);
+			efa_rdm_pke_release(pkt_entry);
+			return NULL;
+		}
+		pkt_entry->debug_info->counter = 0;
+		memset(pkt_entry->debug_info->entries, 0, 
+		       sizeof(pkt_entry->debug_info->entries));
+	}
 #endif
 	/* Initialize necessary fields in pkt_entry.
 	 * The memory region allocated by ofi_buf_alloc_ex is not initalized.
@@ -93,12 +131,18 @@ struct efa_rdm_pke *efa_rdm_pke_alloc(struct efa_rdm_ep *ep,
 void efa_rdm_pke_release(struct efa_rdm_pke *pkt_entry)
 {
 #ifdef ENABLE_EFA_POISONING
-	/* Restore pkt_entry->gen after poisoning. Otherwise, all pkts will have
-	 * the same gen when poisoning is enabled. */
+	/* Preserve gen and debug_info pointer across poisoning to maintain packet history */
 	uint8_t gen = pkt_entry->gen;
+#if ENABLE_DEBUG
+	struct efa_rdm_pke_debug_info_buffer *debug_info = pkt_entry->debug_info;
+#endif
 	efa_rdm_poison_mem_region(pkt_entry, ofi_buf_pool(pkt_entry)->attr.size);
 	pkt_entry->gen = gen;
+#if ENABLE_DEBUG
+	pkt_entry->debug_info = debug_info;
+#endif
 #endif
+	/* Without poisoning, debug_info pointer is naturally preserved in memory. */
 	pkt_entry->flags = 0;
 	ofi_buf_free(pkt_entry);
 }
@@ -708,6 +752,15 @@ ssize_t efa_rdm_pke_recvv(struct efa_rdm_pke **pke_vec,
 		recv_wr = &ep->base_ep.efa_recv_wr_vec[i];
 		recv_wr->wr.wr_id = efa_rdm_pke_get_wr_id(pke_vec[i]);
 
+#if ENABLE_DEBUG
+		/* Record RECV_POST event */
+		efa_rdm_pke_record_debug_info(pke_vec[i],
+		                               ep->base_ep.qp->qp_num,
+		                               ep->base_ep.qp->qkey,
+		                               pke_vec[i]->gen,
+		                               EFA_RDM_PKE_DEBUG_EVENT_RECV_POST);
+#endif
+
 		recv_wr->wr.num_sge = 1;
 		recv_wr->wr.sg_list = recv_wr->sge;
 		recv_wr->wr.sg_list[0].length = pke_vec[i]->pkt_size;
@@ -787,3 +840,50 @@ ssize_t efa_rdm_pke_user_recvv(struct efa_rdm_pke **pke_vec,
 
 	return err;
 }
+
+
+#if ENABLE_DEBUG
+/* Compile-time assertion that debug_info gen field can hold all possible gen values */
+_Static_assert(EFA_RDM_PKE_DEBUG_GEN_MASK >= EFA_RDM_PACKET_GEN_MASK, 
+               "DEBUG_GEN_BITS insufficient to hold EFA_RDM_PACKET_GEN_MASK");
+
+/**
+ * @brief Print debug info history for packet entry
+ *
+ * @param pkt_entry Packet entry
+ */
+void efa_rdm_pke_print_debug_info(struct efa_rdm_pke *pkt_entry)
+{
+	static const char *event_str[] = {
+		"SEND_POST",
+		"SEND_COMPLETION",
+		"RECV_POST",
+		"RECV_COMPLETION",
+		"READ_POST",
+		"READ_COMPLETION",
+		"WRITE_POST",
+		"WRITE_COMPLETION",
+		"RECV_RDMA_WITH_IMM"
+	};
+	int i, count;
+	int start_idx;
+
+	if (!pkt_entry->debug_info)
+		return;
+
+	count = MIN(EFA_RDM_PKE_DEBUG_INFO_SIZE, pkt_entry->debug_info->counter);
+	start_idx = (pkt_entry->debug_info->counter >= EFA_RDM_PKE_DEBUG_INFO_SIZE) ?
+	                (pkt_entry->debug_info->counter % EFA_RDM_PKE_DEBUG_INFO_SIZE) : 0;
+
+	for (i = 0; i < count; i++) {
+		int idx = (start_idx + i) % EFA_RDM_PKE_DEBUG_INFO_SIZE;
+		struct efa_rdm_pke_debug_info *info = &pkt_entry->debug_info->entries[idx];
+		uint8_t event = EFA_RDM_PKE_DEBUG_INFO_GET_EVENT(info);
+		EFA_WARN(FI_LOG_EP_DATA,
+		         "    [%d] counter=%u gen=%u qpn=%u qkey=%u (%s)\n",
+		         i, info->counter, EFA_RDM_PKE_DEBUG_INFO_GET_GEN(info),
+		         EFA_RDM_PKE_DEBUG_INFO_GET_QPN(info), info->qkey,
+		         event < EFA_RDM_PKE_DEBUG_EVENT_TYPE_COUNT ? event_str[event] : "UNKNOWN");
+	}
+}
+#endif