[PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[longli]

From: Long Li <longli@microsoft.com>

Change all the logging statements on the datapath to use RTE_LOG_DP() to
reduce CPU overhead when logging is not enabled for datapath.

Fixes: 517ed6e2d5 ("net/mana: add basic driver with build environment")
Cc: stable@dpdk.org
Signed-off-by: Long Li <longli@microsoft.com>
---
 drivers/net/mana/gdma.c | 56 +++++++++++++++---------------
 drivers/net/mana/mana.h |  3 ++
 drivers/net/mana/mp.c   |  4 +--
 drivers/net/mana/mr.c   | 77 ++++++++++++++++++++---------------------
 drivers/net/mana/rx.c   | 32 ++++++++---------
 drivers/net/mana/tx.c   | 66 +++++++++++++++++------------------
 6 files changed, 120 insertions(+), 118 deletions(-)

diff --git a/drivers/net/mana/gdma.c b/drivers/net/mana/gdma.c
index 3d4039014f..f637084137 100644
--- a/drivers/net/mana/gdma.c
+++ b/drivers/net/mana/gdma.c
@@ -14,12 +14,12 @@ gdma_get_wqe_pointer(struct mana_gdma_queue *queue)
 		(queue->head * GDMA_WQE_ALIGNMENT_UNIT_SIZE) &
 		(queue->size - 1);
 
-	DRV_LOG(DEBUG, "txq sq_head %u sq_size %u offset_in_bytes %u",
-		queue->head, queue->size, offset_in_bytes);
+	DP_LOG(DEBUG, "txq sq_head %u sq_size %u offset_in_bytes %u",
+	       queue->head, queue->size, offset_in_bytes);
 
 	if (offset_in_bytes + GDMA_WQE_ALIGNMENT_UNIT_SIZE > queue->size)
-		DRV_LOG(ERR, "fatal error: offset_in_bytes %u too big",
-			offset_in_bytes);
+		DP_LOG(ERR, "fatal error: offset_in_bytes %u too big",
+		       offset_in_bytes);
 
 	return ((uint8_t *)queue->buffer) + offset_in_bytes;
 }
@@ -39,11 +39,11 @@ write_dma_client_oob(uint8_t *work_queue_buffer_pointer,
 		client_oob_size / sizeof(uint32_t);
 	header->client_data_unit = work_request->client_data_unit;
 
-	DRV_LOG(DEBUG, "queue buf %p sgl %u oob_h %u du %u oob_buf %p oob_b %u",
-		work_queue_buffer_pointer, header->num_sgl_entries,
-		header->inline_client_oob_size_in_dwords,
-		header->client_data_unit, work_request->inline_oob_data,
-		work_request->inline_oob_size_in_bytes);
+	DP_LOG(DEBUG, "queue buf %p sgl %u oob_h %u du %u oob_buf %p oob_b %u",
+	       work_queue_buffer_pointer, header->num_sgl_entries,
+	       header->inline_client_oob_size_in_dwords,
+	       header->client_data_unit, work_request->inline_oob_data,
+	       work_request->inline_oob_size_in_bytes);
 
 	p += sizeof(struct gdma_wqe_dma_oob);
 	if (work_request->inline_oob_data &&
@@ -73,8 +73,8 @@ write_scatter_gather_list(uint8_t *work_queue_head_pointer,
 	uint32_t size_to_queue_end;
 	uint32_t sge_list_size;
 
-	DRV_LOG(DEBUG, "work_queue_cur_pointer %p work_request->flags %x",
-		work_queue_cur_pointer, work_request->flags);
+	DP_LOG(DEBUG, "work_queue_cur_pointer %p work_request->flags %x",
+	       work_queue_cur_pointer, work_request->flags);
 
 	num_sge = work_request->num_sgl_elements;
 	sge_list = work_request->sgl;
@@ -110,9 +110,9 @@ write_scatter_gather_list(uint8_t *work_queue_head_pointer,
 		sge_list_size = size;
 	}
 
-	DRV_LOG(DEBUG, "sge %u address 0x%" PRIx64 " size %u key %u list_s %u",
-		num_sge, sge_list->address, sge_list->size,
-		sge_list->memory_key, sge_list_size);
+	DP_LOG(DEBUG, "sge %u address 0x%" PRIx64 " size %u key %u list_s %u",
+	       num_sge, sge_list->address, sge_list->size,
+	       sge_list->memory_key, sge_list_size);
 
 	return sge_list_size;
 }
@@ -141,13 +141,13 @@ gdma_post_work_request(struct mana_gdma_queue *queue,
 	uint32_t queue_free_units = queue->count - (queue->head - queue->tail);
 
 	if (wqe_size / GDMA_WQE_ALIGNMENT_UNIT_SIZE > queue_free_units) {
-		DRV_LOG(DEBUG, "WQE size %u queue count %u head %u tail %u",
-			wqe_size, queue->count, queue->head, queue->tail);
+		DP_LOG(DEBUG, "WQE size %u queue count %u head %u tail %u",
+		       wqe_size, queue->count, queue->head, queue->tail);
 		return -EBUSY;
 	}
 
-	DRV_LOG(DEBUG, "client_oob_size %u sgl_data_size %u wqe_size %u",
-		client_oob_size, sgl_data_size, wqe_size);
+	DP_LOG(DEBUG, "client_oob_size %u sgl_data_size %u wqe_size %u",
+	       client_oob_size, sgl_data_size, wqe_size);
 
 	if (wqe_info) {
 		wqe_info->wqe_index =
@@ -242,15 +242,15 @@ mana_ring_doorbell(void *db_page, enum gdma_queue_types queue_type,
 		break;
 
 	default:
-		DRV_LOG(ERR, "Unsupported queue type %d", queue_type);
+		DP_LOG(ERR, "Unsupported queue type %d", queue_type);
 		return -1;
 	}
 
 	/* Ensure all writes are done before ringing doorbell */
 	rte_wmb();
 
-	DRV_LOG(DEBUG, "db_page %p addr %p queue_id %u type %u tail %u arm %u",
-		db_page, addr, queue_id, queue_type, tail, arm);
+	DP_LOG(DEBUG, "db_page %p addr %p queue_id %u type %u tail %u arm %u",
+	       db_page, addr, queue_id, queue_type, tail, arm);
 
 	rte_write64(e.as_uint64, addr);
 	return 0;
@@ -274,15 +274,15 @@ gdma_poll_completion_queue(struct mana_gdma_queue *cq, struct gdma_comp *comp)
 				COMPLETION_QUEUE_OWNER_MASK;
 	cqe_owner_bits = cqe->owner_bits;
 
-	DRV_LOG(DEBUG, "comp cqe bits 0x%x owner bits 0x%x",
-		cqe_owner_bits, old_owner_bits);
+	DP_LOG(DEBUG, "comp cqe bits 0x%x owner bits 0x%x",
+	       cqe_owner_bits, old_owner_bits);
 
 	if (cqe_owner_bits == old_owner_bits)
 		return 0; /* No new entry */
 
 	if (cqe_owner_bits != new_owner_bits) {
-		DRV_LOG(ERR, "CQ overflowed, ID %u cqe 0x%x new 0x%x",
-			cq->id, cqe_owner_bits, new_owner_bits);
+		DP_LOG(ERR, "CQ overflowed, ID %u cqe 0x%x new 0x%x",
+		       cq->id, cqe_owner_bits, new_owner_bits);
 		return -1;
 	}
 
@@ -296,8 +296,8 @@ gdma_poll_completion_queue(struct mana_gdma_queue *cq, struct gdma_comp *comp)
 
 	cq->head++;
 
-	DRV_LOG(DEBUG, "comp new 0x%x old 0x%x cqe 0x%x wq %u sq %u head %u",
-		new_owner_bits, old_owner_bits, cqe_owner_bits,
-		comp->work_queue_number, comp->send_work_queue, cq->head);
+	DP_LOG(DEBUG, "comp new 0x%x old 0x%x cqe 0x%x wq %u sq %u head %u",
+	       new_owner_bits, old_owner_bits, cqe_owner_bits,
+	       comp->work_queue_number, comp->send_work_queue, cq->head);
 	return 1;
 }
diff --git a/drivers/net/mana/mana.h b/drivers/net/mana/mana.h
index 4a05238a96..7b8c27df2a 100644
--- a/drivers/net/mana/mana.h
+++ b/drivers/net/mana/mana.h
@@ -447,6 +447,9 @@ extern int mana_logtype_init;
 	rte_log(RTE_LOG_ ## level, mana_logtype_driver, "%s(): " fmt "\n", \
 		__func__, ## args)
 
+#define DP_LOG(level, fmt, args...) \
+	RTE_LOG_DP(level, PMD, fmt, ## args)
+
 #define PMD_INIT_LOG(level, fmt, args...) \
 	rte_log(RTE_LOG_ ## level, mana_logtype_init, "%s(): " fmt "\n",\
 		__func__, ## args)
diff --git a/drivers/net/mana/mp.c b/drivers/net/mana/mp.c
index 92432c431d..738487f65a 100644
--- a/drivers/net/mana/mp.c
+++ b/drivers/net/mana/mp.c
@@ -28,8 +28,8 @@ mana_mp_mr_create(struct mana_priv *priv, uintptr_t addr, uint32_t len)
 	if (!ibv_mr)
 		return -errno;
 
-	DRV_LOG(DEBUG, "MR (2nd) lkey %u addr %p len %zu",
-		ibv_mr->lkey, ibv_mr->addr, ibv_mr->length);
+	DP_LOG(DEBUG, "MR (2nd) lkey %u addr %p len %zu",
+	       ibv_mr->lkey, ibv_mr->addr, ibv_mr->length);
 
 	mr = rte_calloc("MANA MR", 1, sizeof(*mr), 0);
 	if (!mr) {
diff --git a/drivers/net/mana/mr.c b/drivers/net/mana/mr.c
index 22df0917bb..fec0dc961c 100644
--- a/drivers/net/mana/mr.c
+++ b/drivers/net/mana/mr.c
@@ -47,23 +47,23 @@ mana_new_pmd_mr(struct mana_mr_btree *local_tree, struct mana_priv *priv,
 
 	for (i = 0; i < pool->nb_mem_chunks; i++) {
 		if (ranges[i].len > priv->max_mr_size) {
-			DRV_LOG(ERR, "memory chunk size %u exceeding max MR",
-				ranges[i].len);
+			DP_LOG(ERR, "memory chunk size %u exceeding max MR",
+			       ranges[i].len);
 			return -ENOMEM;
 		}
 
-		DRV_LOG(DEBUG,
-			"registering memory chunk start 0x%" PRIx64 " len %u",
-			ranges[i].start, ranges[i].len);
+		DP_LOG(DEBUG,
+		       "registering memory chunk start 0x%" PRIx64 " len %u",
+		       ranges[i].start, ranges[i].len);
 
 		if (rte_eal_process_type() == RTE_PROC_SECONDARY) {
 			/* Send a message to the primary to do MR */
 			ret = mana_mp_req_mr_create(priv, ranges[i].start,
 						    ranges[i].len);
 			if (ret) {
-				DRV_LOG(ERR,
-					"MR failed start 0x%" PRIx64 " len %u",
-					ranges[i].start, ranges[i].len);
+				DP_LOG(ERR,
+				       "MR failed start 0x%" PRIx64 " len %u",
+				       ranges[i].start, ranges[i].len);
 				return ret;
 			}
 			continue;
@@ -72,8 +72,8 @@ mana_new_pmd_mr(struct mana_mr_btree *local_tree, struct mana_priv *priv,
 		ibv_mr = ibv_reg_mr(priv->ib_pd, (void *)ranges[i].start,
 				    ranges[i].len, IBV_ACCESS_LOCAL_WRITE);
 		if (ibv_mr) {
-			DRV_LOG(DEBUG, "MR lkey %u addr %p len %" PRIu64,
-				ibv_mr->lkey, ibv_mr->addr, ibv_mr->length);
+			DP_LOG(DEBUG, "MR lkey %u addr %p len %" PRIu64,
+			       ibv_mr->lkey, ibv_mr->addr, ibv_mr->length);
 
 			mr = rte_calloc("MANA MR", 1, sizeof(*mr), 0);
 			mr->lkey = ibv_mr->lkey;
@@ -86,7 +86,7 @@ mana_new_pmd_mr(struct mana_mr_btree *local_tree, struct mana_priv *priv,
 			rte_spinlock_unlock(&priv->mr_btree_lock);
 			if (ret) {
 				ibv_dereg_mr(ibv_mr);
-				DRV_LOG(ERR, "Failed to add to global MR btree");
+				DP_LOG(ERR, "Failed to add to global MR btree");
 				return ret;
 			}
 
@@ -95,12 +95,12 @@ mana_new_pmd_mr(struct mana_mr_btree *local_tree, struct mana_priv *priv,
 				/* Don't need to clean up MR as it's already
 				 * in the global tree
 				 */
-				DRV_LOG(ERR, "Failed to add to local MR btree");
+				DP_LOG(ERR, "Failed to add to local MR btree");
 				return ret;
 			}
 		} else {
-			DRV_LOG(ERR, "MR failed at 0x%" PRIx64 " len %u",
-				ranges[i].start, ranges[i].len);
+			DP_LOG(ERR, "MR failed at 0x%" PRIx64 " len %u",
+			       ranges[i].start, ranges[i].len);
 			return -errno;
 		}
 	}
@@ -118,7 +118,7 @@ mana_del_pmd_mr(struct mana_mr_cache *mr)
 
 	ret = ibv_dereg_mr(ibv_mr);
 	if (ret)
-		DRV_LOG(ERR, "dereg MR failed ret %d", ret);
+		DP_LOG(ERR, "dereg MR failed ret %d", ret);
 }
 
 /*
@@ -133,17 +133,16 @@ mana_find_pmd_mr(struct mana_mr_btree *local_mr_btree, struct mana_priv *priv,
 	struct mana_mr_cache *mr;
 	uint16_t idx;
 
-	DRV_LOG(DEBUG, "finding mr for mbuf addr %p len %d",
-		mbuf->buf_addr, mbuf->buf_len);
+	DP_LOG(DEBUG, "finding mr for mbuf addr %p len %d",
+	       mbuf->buf_addr, mbuf->buf_len);
 
 try_again:
 	/* First try to find the MR in local queue tree */
 	mr = mana_mr_btree_lookup(local_mr_btree, &idx,
 				  (uintptr_t)mbuf->buf_addr, mbuf->buf_len);
 	if (mr) {
-		DRV_LOG(DEBUG,
-			"Local mr lkey %u addr 0x%" PRIx64 " len %" PRIu64,
-			mr->lkey, mr->addr, mr->len);
+		DP_LOG(DEBUG, "Local mr lkey %u addr 0x%" PRIx64 " len %" PRIu64,
+		       mr->lkey, mr->addr, mr->len);
 		return mr;
 	}
 
@@ -158,25 +157,25 @@ mana_find_pmd_mr(struct mana_mr_btree *local_mr_btree, struct mana_priv *priv,
 	if (mr) {
 		ret = mana_mr_btree_insert(local_mr_btree, mr);
 		if (ret) {
-			DRV_LOG(DEBUG, "Failed to add MR to local tree.");
+			DP_LOG(ERR, "Failed to add MR to local tree.");
 			return NULL;
 		}
 
-		DRV_LOG(DEBUG,
-			"Added local MR key %u addr 0x%" PRIx64 " len %" PRIu64,
-			mr->lkey, mr->addr, mr->len);
+		DP_LOG(DEBUG,
+		       "Added local MR key %u addr 0x%" PRIx64 " len %" PRIu64,
+		       mr->lkey, mr->addr, mr->len);
 		return mr;
 	}
 
 	if (second_try) {
-		DRV_LOG(ERR, "Internal error second try failed");
+		DP_LOG(ERR, "Internal error second try failed");
 		return NULL;
 	}
 
 	ret = mana_new_pmd_mr(local_mr_btree, priv, pool);
 	if (ret) {
-		DRV_LOG(ERR, "Failed to allocate MR ret %d addr %p len %d",
-			ret, mbuf->buf_addr, mbuf->buf_len);
+		DP_LOG(ERR, "Failed to allocate MR ret %d addr %p len %d",
+		       ret, mbuf->buf_addr, mbuf->buf_len);
 		return NULL;
 	}
 
@@ -215,11 +214,11 @@ mana_mr_btree_expand(struct mana_mr_btree *bt, int n)
 	mem = rte_realloc_socket(bt->table, n * sizeof(struct mana_mr_cache),
 				 0, bt->socket);
 	if (!mem) {
-		DRV_LOG(ERR, "Failed to expand btree size %d", n);
+		DP_LOG(ERR, "Failed to expand btree size %d", n);
 		return -1;
 	}
 
-	DRV_LOG(ERR, "Expanded btree to size %d", n);
+	DP_LOG(ERR, "Expanded btree to size %d", n);
 	bt->table = mem;
 	bt->size = n;
 
@@ -266,9 +265,9 @@ mana_mr_btree_lookup(struct mana_mr_btree *bt, uint16_t *idx,
 	if (addr + len <= table[base].addr + table[base].len)
 		return &table[base];
 
-	DRV_LOG(DEBUG,
-		"addr 0x%" PRIx64 " len %zu idx %u sum 0x%" PRIx64 " not found",
-		addr, len, *idx, addr + len);
+	DP_LOG(DEBUG,
+	       "addr 0x%" PRIx64 " len %zu idx %u sum 0x%" PRIx64 " not found",
+	       addr, len, *idx, addr + len);
 
 	return NULL;
 }
@@ -317,8 +316,8 @@ mana_mr_btree_insert(struct mana_mr_btree *bt, struct mana_mr_cache *entry)
 	uint16_t shift;
 
 	if (mana_mr_btree_lookup(bt, &idx, entry->addr, entry->len)) {
-		DRV_LOG(DEBUG, "Addr 0x%" PRIx64 " len %zu exists in btree",
-			entry->addr, entry->len);
+		DP_LOG(DEBUG, "Addr 0x%" PRIx64 " len %zu exists in btree",
+		       entry->addr, entry->len);
 		return 0;
 	}
 
@@ -332,17 +331,17 @@ mana_mr_btree_insert(struct mana_mr_btree *bt, struct mana_mr_cache *entry)
 	idx++;
 	shift = (bt->len - idx) * sizeof(struct mana_mr_cache);
 	if (shift) {
-		DRV_LOG(DEBUG, "Moving %u bytes from idx %u to %u",
-			shift, idx, idx + 1);
+		DP_LOG(DEBUG, "Moving %u bytes from idx %u to %u",
+		       shift, idx, idx + 1);
 		memmove(&table[idx + 1], &table[idx], shift);
 	}
 
 	table[idx] = *entry;
 	bt->len++;
 
-	DRV_LOG(DEBUG,
-		"Inserted MR b-tree table %p idx %d addr 0x%" PRIx64 " len %zu",
-		table, idx, entry->addr, entry->len);
+	DP_LOG(DEBUG,
+	       "Inserted MR b-tree table %p idx %d addr 0x%" PRIx64 " len %zu",
+	       table, idx, entry->addr, entry->len);
 
 	return 0;
 }
diff --git a/drivers/net/mana/rx.c b/drivers/net/mana/rx.c
index 55247889c1..10392ae292 100644
--- a/drivers/net/mana/rx.c
+++ b/drivers/net/mana/rx.c
@@ -42,7 +42,7 @@ mana_rq_ring_doorbell(struct mana_rxq *rxq, uint8_t arm)
 			 arm);
 
 	if (ret)
-		DRV_LOG(ERR, "failed to ring RX doorbell ret %d", ret);
+		DP_LOG(ERR, "failed to ring RX doorbell ret %d", ret);
 
 	return ret;
 }
@@ -66,7 +66,7 @@ mana_alloc_and_post_rx_wqe(struct mana_rxq *rxq)
 
 	mr = mana_find_pmd_mr(&rxq->mr_btree, priv, mbuf);
 	if (!mr) {
-		DRV_LOG(ERR, "failed to register RX MR");
+		DP_LOG(ERR, "failed to register RX MR");
 		rte_pktmbuf_free(mbuf);
 		return -ENOMEM;
 	}
@@ -97,7 +97,7 @@ mana_alloc_and_post_rx_wqe(struct mana_rxq *rxq)
 		desc->wqe_size_in_bu = wqe_info.wqe_size_in_bu;
 		rxq->desc_ring_head = (rxq->desc_ring_head + 1) % rxq->num_desc;
 	} else {
-		DRV_LOG(ERR, "failed to post recv ret %d", ret);
+		DP_LOG(DEBUG, "failed to post recv ret %d", ret);
 		return ret;
 	}
 
@@ -116,7 +116,7 @@ mana_alloc_and_post_rx_wqes(struct mana_rxq *rxq)
 	for (i = 0; i < rxq->num_desc; i++) {
 		ret = mana_alloc_and_post_rx_wqe(rxq);
 		if (ret) {
-			DRV_LOG(ERR, "failed to post RX ret = %d", ret);
+			DP_LOG(ERR, "failed to post RX ret = %d", ret);
 			return ret;
 		}
 	}
@@ -395,8 +395,8 @@ mana_rx_burst(void *dpdk_rxq, struct rte_mbuf **pkts, uint16_t pkts_n)
 			(struct mana_rx_comp_oob *)&comp.completion_data[0];
 
 		if (comp.work_queue_number != rxq->gdma_rq.id) {
-			DRV_LOG(ERR, "rxq comp id mismatch wqid=0x%x rcid=0x%x",
-				comp.work_queue_number, rxq->gdma_rq.id);
+			DP_LOG(ERR, "rxq comp id mismatch wqid=0x%x rcid=0x%x",
+			       comp.work_queue_number, rxq->gdma_rq.id);
 			rxq->stats.errors++;
 			break;
 		}
@@ -411,22 +411,22 @@ mana_rx_burst(void *dpdk_rxq, struct rte_mbuf **pkts, uint16_t pkts_n)
 			break;
 
 		case CQE_RX_TRUNCATED:
-			DRV_LOG(ERR, "Drop a truncated packet");
+			DP_LOG(DEBUG, "Drop a truncated packet");
 			rxq->stats.errors++;
 			rte_pktmbuf_free(mbuf);
 			goto drop;
 
 		case CQE_RX_COALESCED_4:
-			DRV_LOG(ERR, "RX coalescing is not supported");
+			DP_LOG(ERR, "RX coalescing is not supported");
 			continue;
 
 		default:
-			DRV_LOG(ERR, "Unknown RX CQE type %d",
-				oob->cqe_hdr.cqe_type);
+			DP_LOG(ERR, "Unknown RX CQE type %d",
+			       oob->cqe_hdr.cqe_type);
 			continue;
 		}
 
-		DRV_LOG(DEBUG, "mana_rx_comp_oob CQE_RX_OKAY rxq %p", rxq);
+		DP_LOG(DEBUG, "mana_rx_comp_oob CQE_RX_OKAY rxq %p", rxq);
 
 		mbuf->data_off = RTE_PKTMBUF_HEADROOM;
 		mbuf->nb_segs = 1;
@@ -470,7 +470,7 @@ mana_rx_burst(void *dpdk_rxq, struct rte_mbuf **pkts, uint16_t pkts_n)
 		/* Post another request */
 		ret = mana_alloc_and_post_rx_wqe(rxq);
 		if (ret) {
-			DRV_LOG(ERR, "failed to post rx wqe ret=%d", ret);
+			DP_LOG(ERR, "failed to post rx wqe ret=%d", ret);
 			break;
 		}
 
@@ -490,8 +490,8 @@ mana_arm_cq(struct mana_rxq *rxq, uint8_t arm)
 	uint32_t head = rxq->gdma_cq.head %
 		(rxq->gdma_cq.count << COMPLETION_QUEUE_ENTRY_OWNER_BITS_SIZE);
 
-	DRV_LOG(ERR, "Ringing completion queue ID %u head %u arm %d",
-		rxq->gdma_cq.id, head, arm);
+	DP_LOG(DEBUG, "Ringing completion queue ID %u head %u arm %d",
+	       rxq->gdma_cq.id, head, arm);
 
 	return mana_ring_doorbell(priv->db_page, GDMA_QUEUE_COMPLETION,
 				  rxq->gdma_cq.id, head, arm);
@@ -521,8 +521,8 @@ mana_rx_intr_disable(struct rte_eth_dev *dev, uint16_t rx_queue_id)
 
 	if (ret) {
 		if (ret != EAGAIN)
-			DRV_LOG(ERR, "Can't disable RX intr queue %d",
-				rx_queue_id);
+			DP_LOG(ERR, "Can't disable RX intr queue %d",
+			       rx_queue_id);
 	} else {
 		ibv_ack_cq_events(rxq->cq, 1);
 	}
diff --git a/drivers/net/mana/tx.c b/drivers/net/mana/tx.c
index 300bf27cc1..a45b5e289c 100644
--- a/drivers/net/mana/tx.c
+++ b/drivers/net/mana/tx.c
@@ -183,17 +183,17 @@ mana_tx_burst(void *dpdk_txq, struct rte_mbuf **tx_pkts, uint16_t nb_pkts)
 			(struct mana_tx_comp_oob *)&comp.completion_data[0];
 
 		if (oob->cqe_hdr.cqe_type != CQE_TX_OKAY) {
-			DRV_LOG(ERR,
-				"mana_tx_comp_oob cqe_type %u vendor_err %u",
-				oob->cqe_hdr.cqe_type, oob->cqe_hdr.vendor_err);
+			DP_LOG(ERR,
+			       "mana_tx_comp_oob cqe_type %u vendor_err %u",
+			       oob->cqe_hdr.cqe_type, oob->cqe_hdr.vendor_err);
 			txq->stats.errors++;
 		} else {
-			DRV_LOG(DEBUG, "mana_tx_comp_oob CQE_TX_OKAY");
+			DP_LOG(DEBUG, "mana_tx_comp_oob CQE_TX_OKAY");
 			txq->stats.packets++;
 		}
 
 		if (!desc->pkt) {
-			DRV_LOG(ERR, "mana_txq_desc has a NULL pkt");
+			DP_LOG(ERR, "mana_txq_desc has a NULL pkt");
 		} else {
 			txq->stats.bytes += desc->pkt->data_len;
 			rte_pktmbuf_free(desc->pkt);
@@ -214,8 +214,8 @@ mana_tx_burst(void *dpdk_txq, struct rte_mbuf **tx_pkts, uint16_t nb_pkts)
 
 		/* Drop the packet if it exceeds max segments */
 		if (m_pkt->nb_segs > priv->max_send_sge) {
-			DRV_LOG(ERR, "send packet segments %d exceeding max",
-				m_pkt->nb_segs);
+			DP_LOG(ERR, "send packet segments %d exceeding max",
+			       m_pkt->nb_segs);
 			continue;
 		}
 
@@ -257,7 +257,7 @@ mana_tx_burst(void *dpdk_txq, struct rte_mbuf **tx_pkts, uint16_t nb_pkts)
 				tcp_hdr->cksum = rte_ipv6_phdr_cksum(ip_hdr,
 							m_pkt->ol_flags);
 			} else {
-				DRV_LOG(ERR, "Invalid input for TCP CKSUM");
+				DP_LOG(ERR, "Invalid input for TCP CKSUM");
 			}
 
 			tx_oob.short_oob.tx_compute_TCP_checksum = 1;
@@ -297,7 +297,7 @@ mana_tx_burst(void *dpdk_txq, struct rte_mbuf **tx_pkts, uint16_t nb_pkts)
 							    m_pkt->ol_flags);
 
 			} else {
-				DRV_LOG(ERR, "Invalid input for UDP CKSUM");
+				DP_LOG(ERR, "Invalid input for UDP CKSUM");
 			}
 
 			tx_oob.short_oob.tx_compute_UDP_checksum = 1;
@@ -310,20 +310,20 @@ mana_tx_burst(void *dpdk_txq, struct rte_mbuf **tx_pkts, uint16_t nb_pkts)
 			get_vsq_frame_num(txq->gdma_sq.id);
 		tx_oob.short_oob.short_vport_offset = txq->tx_vp_offset;
 
-		DRV_LOG(DEBUG, "tx_oob packet_format %u ipv4 %u ipv6 %u",
-			tx_oob.short_oob.packet_format,
-			tx_oob.short_oob.tx_is_outer_ipv4,
-			tx_oob.short_oob.tx_is_outer_ipv6);
+		DP_LOG(DEBUG, "tx_oob packet_format %u ipv4 %u ipv6 %u",
+		       tx_oob.short_oob.packet_format,
+		       tx_oob.short_oob.tx_is_outer_ipv4,
+		       tx_oob.short_oob.tx_is_outer_ipv6);
 
-		DRV_LOG(DEBUG, "tx_oob checksum ip %u tcp %u udp %u offset %u",
-			tx_oob.short_oob.tx_compute_IP_header_checksum,
-			tx_oob.short_oob.tx_compute_TCP_checksum,
-			tx_oob.short_oob.tx_compute_UDP_checksum,
-			tx_oob.short_oob.tx_transport_header_offset);
+		DP_LOG(DEBUG, "tx_oob checksum ip %u tcp %u udp %u offset %u",
+		       tx_oob.short_oob.tx_compute_IP_header_checksum,
+		       tx_oob.short_oob.tx_compute_TCP_checksum,
+		       tx_oob.short_oob.tx_compute_UDP_checksum,
+		       tx_oob.short_oob.tx_transport_header_offset);
 
-		DRV_LOG(DEBUG, "pkt[%d]: buf_addr 0x%p, nb_segs %d, pkt_len %d",
-			pkt_idx, m_pkt->buf_addr, m_pkt->nb_segs,
-			m_pkt->pkt_len);
+		DP_LOG(DEBUG, "pkt[%d]: buf_addr 0x%p, nb_segs %d, pkt_len %d",
+		       pkt_idx, m_pkt->buf_addr, m_pkt->nb_segs,
+		       m_pkt->pkt_len);
 
 		/* Create SGL for packet data buffers */
 		for (seg_idx = 0; seg_idx < m_pkt->nb_segs; seg_idx++) {
@@ -331,8 +331,8 @@ mana_tx_burst(void *dpdk_txq, struct rte_mbuf **tx_pkts, uint16_t nb_pkts)
 				mana_find_pmd_mr(&txq->mr_btree, priv, m_seg);
 
 			if (!mr) {
-				DRV_LOG(ERR, "failed to get MR, pkt_idx %u",
-					pkt_idx);
+				DP_LOG(ERR, "failed to get MR, pkt_idx %u",
+				       pkt_idx);
 				break;
 			}
 
@@ -342,11 +342,11 @@ mana_tx_burst(void *dpdk_txq, struct rte_mbuf **tx_pkts, uint16_t nb_pkts)
 			sgl.gdma_sgl[seg_idx].size = m_seg->data_len;
 			sgl.gdma_sgl[seg_idx].memory_key = mr->lkey;
 
-			DRV_LOG(DEBUG,
-				"seg idx %u addr 0x%" PRIx64 " size %x key %x",
-				seg_idx, sgl.gdma_sgl[seg_idx].address,
-				sgl.gdma_sgl[seg_idx].size,
-				sgl.gdma_sgl[seg_idx].memory_key);
+			DP_LOG(DEBUG,
+			       "seg idx %u addr 0x%" PRIx64 " size %x key %x",
+			       seg_idx, sgl.gdma_sgl[seg_idx].address,
+			       sgl.gdma_sgl[seg_idx].size,
+			       sgl.gdma_sgl[seg_idx].memory_key);
 
 			m_seg = m_seg->next;
 		}
@@ -383,11 +383,11 @@ mana_tx_burst(void *dpdk_txq, struct rte_mbuf **tx_pkts, uint16_t nb_pkts)
 
 			pkt_sent++;
 
-			DRV_LOG(DEBUG, "nb_pkts %u pkt[%d] sent",
-				nb_pkts, pkt_idx);
+			DP_LOG(DEBUG, "nb_pkts %u pkt[%d] sent",
+			       nb_pkts, pkt_idx);
 		} else {
-			DRV_LOG(INFO, "pkt[%d] failed to post send ret %d",
-				pkt_idx, ret);
+			DP_LOG(DEBUG, "pkt[%d] failed to post send ret %d",
+			       pkt_idx, ret);
 			break;
 		}
 	}
@@ -409,7 +409,7 @@ mana_tx_burst(void *dpdk_txq, struct rte_mbuf **tx_pkts, uint16_t nb_pkts)
 						GDMA_WQE_ALIGNMENT_UNIT_SIZE,
 					 0);
 		if (ret)
-			DRV_LOG(ERR, "mana_ring_doorbell failed ret %d", ret);
+			DP_LOG(ERR, "mana_ring_doorbell failed ret %d", ret);
 	}
 
 	return pkt_sent;
-- 
2.32.0

Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Ferruh Yigit]

On 2/21/2023 8:42 PM, longli@linuxonhyperv.com wrote:
> diff --git a/drivers/net/mana/tx.c b/drivers/net/mana/tx.c
> index 300bf27cc1..a45b5e289c 100644
> --- a/drivers/net/mana/tx.c
> +++ b/drivers/net/mana/tx.c
> @@ -183,17 +183,17 @@ mana_tx_burst(void *dpdk_txq, struct rte_mbuf **tx_pkts, uint16_t nb_pkts)
>  			(struct mana_tx_comp_oob *)&comp.completion_data[0];
>  
>  		if (oob->cqe_hdr.cqe_type != CQE_TX_OKAY) {
> -			DRV_LOG(ERR,
> -				"mana_tx_comp_oob cqe_type %u vendor_err %u",
> -				oob->cqe_hdr.cqe_type, oob->cqe_hdr.vendor_err);
> +			DP_LOG(ERR,
> +			       "mana_tx_comp_oob cqe_type %u vendor_err %u",
> +			       oob->cqe_hdr.cqe_type, oob->cqe_hdr.vendor_err);
>  			txq->stats.errors++;
>  		} else {
> -			DRV_LOG(DEBUG, "mana_tx_comp_oob CQE_TX_OKAY");
> +			DP_LOG(DEBUG, "mana_tx_comp_oob CQE_TX_OKAY");
>  			txq->stats.packets++;
>  		}
>  
>  		if (!desc->pkt) {
> -			DRV_LOG(ERR, "mana_txq_desc has a NULL pkt");
> +			DP_LOG(ERR, "mana_txq_desc has a NULL pkt");
>  		} else {
>  			txq->stats.bytes += desc->pkt->data_len;
>  			rte_pktmbuf_free(desc->pkt);


I have some doubts about data path logging, let me use above example to
discuss this, these are not specific to this driver. TLDR; jump [1].

Above 'ERR' log will leak into the production code, since
'RTE_LOG_DP_LEVEL' value is 'RTE_LOG_INFO' by default.

Question is who will benefit from these error logs, like descriptor
having null packet etc..

I can think of following users for the dpdk logs:
a) DPDK library/driver developer
b) DPDK application developer
c) Who deploys/maintains DPDK application
d) DPDK end user

Unless DPDK packagers or who deploys DPDK application updates
'RTE_LOG_DP_LEVEL', all above parties will observe these datapath logs
but I assume intended user of it is only (a).

Overall I am not sure if anyone is interested in driver datapath logs
other than driver developers themselves.

For datapath logging I think there are two concerns,
1) It should not eat *any* cycles unless explicitly enabled
2) Capability of enable/disable them because of massive amount of log it
can generate


Currently there are two existing approaches for driver datapath logging:
i)  Controlled by 'RTE_ETHDEV_DEBUG_RX/TX' compile time flag,
    when enabled 'rte_log()' is used with Rx/Tx specific log type.
ii) 'RTE_LOG_DP' ', compile time control per logtype via
    'RTE_LOG_DP_LEVEL',
     when enabled 'rte_log()' is used with PMD logtype.


In (ii), need to re-compile code when you need to increase the log
verbosity, and it leaks to production code as mentioned above.

For (i), developer compiles once enabling debug, later can fine grain
log level dynamically. This is more DPDK developer focused approach.


[1]
According above, what do you think to retire 'RTE_LOG_DP', (at least
within ethdev datapath), and chose (i) as preferred datapath logging?

Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Stephen Hemminger]

On Thu, 23 Feb 2023 14:07:25 +0000
Ferruh Yigit <ferruh.yigit@amd.com> wrote:

> Overall I am not sure if anyone is interested in driver datapath logs
> other than driver developers themselves.
> 
> For datapath logging I think there are two concerns,
> 1) It should not eat *any* cycles unless explicitly enabled
> 2) Capability of enable/disable them because of massive amount of log it
> can generate
> 
> 
> Currently there are two existing approaches for driver datapath logging:
> i)  Controlled by 'RTE_ETHDEV_DEBUG_RX/TX' compile time flag,
>     when enabled 'rte_log()' is used with Rx/Tx specific log type.
> ii) 'RTE_LOG_DP' ', compile time control per logtype via
>     'RTE_LOG_DP_LEVEL',
>      when enabled 'rte_log()' is used with PMD logtype.
> 
> 
> In (ii), need to re-compile code when you need to increase the log
> verbosity, and it leaks to production code as mentioned above.
> 
> For (i), developer compiles once enabling debug, later can fine grain
> log level dynamically. This is more DPDK developer focused approach.
> 
> 
> [1]
> According above, what do you think to retire 'RTE_LOG_DP', (at least
> within ethdev datapath), and chose (i) as preferred datapath logging?

I agree, the current tx/rx logging is a mess.
Each driver is different, each driver has to have something to enable it;
and it really isn't useful beyond the driver developer.

Using tracing seems like a much better option. Could we agree on a common
set of trace points for drivers and fix all drivers to use the same thing.
Probably will cause some upset among driver developers:
"where did my nice printf's go, now I have to learn tracing"
but DPDK has a good facility here, lets use it.

My proposal would be:
	- agree on common set of trace points
	- apply to all drivers
	- remove RTE_LOG_DP()
	- remove per driver RX/TX options
	- side effect, more uses of RTE_LOGTYPE_PMD go away.

Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Stephen Hemminger]

On Thu, 23 Feb 2023 10:09:17 -0800
Stephen Hemminger <stephen@networkplumber.org> wrote:

> On Thu, 23 Feb 2023 14:07:25 +0000
> Ferruh Yigit <ferruh.yigit@amd.com> wrote:
> 
> > Overall I am not sure if anyone is interested in driver datapath logs
> > other than driver developers themselves.
> > 
> > For datapath logging I think there are two concerns,
> > 1) It should not eat *any* cycles unless explicitly enabled
> > 2) Capability of enable/disable them because of massive amount of log it
> > can generate
> > 
> > 
> > Currently there are two existing approaches for driver datapath logging:
> > i)  Controlled by 'RTE_ETHDEV_DEBUG_RX/TX' compile time flag,
> >     when enabled 'rte_log()' is used with Rx/Tx specific log type.
> > ii) 'RTE_LOG_DP' ', compile time control per logtype via
> >     'RTE_LOG_DP_LEVEL',
> >      when enabled 'rte_log()' is used with PMD logtype.
> > 
> > 
> > In (ii), need to re-compile code when you need to increase the log
> > verbosity, and it leaks to production code as mentioned above.
> > 
> > For (i), developer compiles once enabling debug, later can fine grain
> > log level dynamically. This is more DPDK developer focused approach.
> > 
> > 
> > [1]
> > According above, what do you think to retire 'RTE_LOG_DP', (at least
> > within ethdev datapath), and chose (i) as preferred datapath logging?  
> 
> I agree, the current tx/rx logging is a mess.
> Each driver is different, each driver has to have something to enable it;
> and it really isn't useful beyond the driver developer.
> 
> Using tracing seems like a much better option. Could we agree on a common
> set of trace points for drivers and fix all drivers to use the same thing.
> Probably will cause some upset among driver developers:
> "where did my nice printf's go, now I have to learn tracing"
> but DPDK has a good facility here, lets use it.
> 
> My proposal would be:
> 	- agree on common set of trace points
> 	- apply to all drivers
> 	- remove RTE_LOG_DP()
> 	- remove per driver RX/TX options
> 	- side effect, more uses of RTE_LOGTYPE_PMD go away.

Here is an example of using tracepoints instead.
Compile tested for example only.

Note: using tracepoints it is possible to keep some of the tracepoints
even if fastpath is not enabled.  Things like running out of Tx or Mbuf
is not something that is perf critical; but would be good for application
to see.


---
 drivers/net/ixgbe/ixgbe_ethdev.c |   7 --
 drivers/net/ixgbe/ixgbe_logs.h   |  18 -----
 drivers/net/ixgbe/ixgbe_rxtx.c   |  95 +++++++-------------------
 drivers/net/ixgbe/ixgbe_trace.h  | 110 +++++++++++++++++++++++++++++++
 4 files changed, 133 insertions(+), 97 deletions(-)
 create mode 100644 drivers/net/ixgbe/ixgbe_trace.h

diff --git a/drivers/net/ixgbe/ixgbe_ethdev.c b/drivers/net/ixgbe/ixgbe_ethdev.c
index 88118bc30560..07f8ccdd97cb 100644
--- a/drivers/net/ixgbe/ixgbe_ethdev.c
+++ b/drivers/net/ixgbe/ixgbe_ethdev.c
@@ -8317,10 +8317,3 @@ RTE_PMD_REGISTER_PARAM_STRING(net_ixgbe_vf,
 
 RTE_LOG_REGISTER_SUFFIX(ixgbe_logtype_init, init, NOTICE);
 RTE_LOG_REGISTER_SUFFIX(ixgbe_logtype_driver, driver, NOTICE);
-
-#ifdef RTE_ETHDEV_DEBUG_RX
-RTE_LOG_REGISTER_SUFFIX(ixgbe_logtype_rx, rx, DEBUG);
-#endif
-#ifdef RTE_ETHDEV_DEBUG_TX
-RTE_LOG_REGISTER_SUFFIX(ixgbe_logtype_tx, tx, DEBUG);
-#endif
diff --git a/drivers/net/ixgbe/ixgbe_logs.h b/drivers/net/ixgbe/ixgbe_logs.h
index 00ef797ca103..f70fa1fd4afd 100644
--- a/drivers/net/ixgbe/ixgbe_logs.h
+++ b/drivers/net/ixgbe/ixgbe_logs.h
@@ -12,24 +12,6 @@ extern int ixgbe_logtype_init;
 
 #define PMD_INIT_FUNC_TRACE() PMD_INIT_LOG(DEBUG, " >>")
 
-#ifdef RTE_ETHDEV_DEBUG_RX
-extern int ixgbe_logtype_rx;
-#define PMD_RX_LOG(level, fmt, args...)			\
-	rte_log(RTE_LOG_ ## level, ixgbe_logtype_rx,	\
-		"%s(): " fmt "\n", __func__, ## args)
-#else
-#define PMD_RX_LOG(level, fmt, args...) do { } while (0)
-#endif
-
-#ifdef RTE_ETHDEV_DEBUG_TX
-extern int ixgbe_logtype_tx;
-#define PMD_TX_LOG(level, fmt, args...)			\
-	rte_log(RTE_LOG_ ## level, ixgbe_logtype_tx,	\
-		"%s(): " fmt "\n", __func__, ## args)
-#else
-#define PMD_TX_LOG(level, fmt, args...) do { } while (0)
-#endif
-
 extern int ixgbe_logtype_driver;
 #define PMD_DRV_LOG_RAW(level, fmt, args...) \
 	rte_log(RTE_LOG_ ## level, ixgbe_logtype_driver, "%s(): " fmt, \
diff --git a/drivers/net/ixgbe/ixgbe_rxtx.c b/drivers/net/ixgbe/ixgbe_rxtx.c
index c9d6ca9efea4..f9f0ffebee8e 100644
--- a/drivers/net/ixgbe/ixgbe_rxtx.c
+++ b/drivers/net/ixgbe/ixgbe_rxtx.c
@@ -46,6 +46,7 @@
 #include <rte_vect.h>
 
 #include "ixgbe_logs.h"
+#include "ixgbe_trace.h"
 #include "base/ixgbe_api.h"
 #include "base/ixgbe_vf.h"
 #include "ixgbe_ethdev.h"
@@ -581,11 +582,8 @@ ixgbe_xmit_cleanup(struct ixgbe_tx_queue *txq)
 	desc_to_clean_to = sw_ring[desc_to_clean_to].last_id;
 	status = txr[desc_to_clean_to].wb.status;
 	if (!(status & rte_cpu_to_le_32(IXGBE_TXD_STAT_DD))) {
-		PMD_TX_LOG(DEBUG,
-			   "TX descriptor %4u is not done"
-			   "(port=%d queue=%d)",
-			   desc_to_clean_to,
-			   txq->port_id, txq->queue_id);
+		ixgbe_trace_tx_not_done(txq->port_id, txq->queue_id, desc_to_clean_to);
+
 		/* Failed to clean any descriptors, better luck next time */
 		return -(1);
 	}
@@ -598,11 +596,8 @@ ixgbe_xmit_cleanup(struct ixgbe_tx_queue *txq)
 		nb_tx_to_clean = (uint16_t)(desc_to_clean_to -
 						last_desc_cleaned);
 
-	PMD_TX_LOG(DEBUG,
-		   "Cleaning %4u TX descriptors: %4u to %4u "
-		   "(port=%d queue=%d)",
-		   nb_tx_to_clean, last_desc_cleaned, desc_to_clean_to,
-		   txq->port_id, txq->queue_id);
+	ixgbe_trace_tx_done(txq->port_id, txq->queue_id,
+			    nb_tx_to_clean, last_desc_cleaned, desc_to_clean_to);
 
 	/*
 	 * The last descriptor to clean is done, so that means all the
@@ -734,26 +729,14 @@ ixgbe_xmit_pkts(void *tx_queue, struct rte_mbuf **tx_pkts,
 		if (tx_last >= txq->nb_tx_desc)
 			tx_last = (uint16_t) (tx_last - txq->nb_tx_desc);
 
-		PMD_TX_LOG(DEBUG, "port_id=%u queue_id=%u pktlen=%u"
-			   " tx_first=%u tx_last=%u",
-			   (unsigned) txq->port_id,
-			   (unsigned) txq->queue_id,
-			   (unsigned) pkt_len,
-			   (unsigned) tx_id,
-			   (unsigned) tx_last);
-
+		ixgbe_trace_tx(txq->port_id, txq->queue_id, pkt_len, tx_id, tx_last);
 		/*
 		 * Make sure there are enough TX descriptors available to
 		 * transmit the entire packet.
 		 * nb_used better be less than or equal to txq->tx_rs_thresh
 		 */
 		if (nb_used > txq->nb_tx_free) {
-			PMD_TX_LOG(DEBUG,
-				   "Not enough free TX descriptors "
-				   "nb_used=%4u nb_free=%4u "
-				   "(port=%d queue=%d)",
-				   nb_used, txq->nb_tx_free,
-				   txq->port_id, txq->queue_id);
+			ixgbe_trace_tx_full(txq->port_id, txq->queue_id, nb_used, txq->nb_tx_free);
 
 			if (ixgbe_xmit_cleanup(txq) != 0) {
 				/* Could not clean any descriptors */
@@ -764,17 +747,8 @@ ixgbe_xmit_pkts(void *tx_queue, struct rte_mbuf **tx_pkts,
 
 			/* nb_used better be <= txq->tx_rs_thresh */
 			if (unlikely(nb_used > txq->tx_rs_thresh)) {
-				PMD_TX_LOG(DEBUG,
-					   "The number of descriptors needed to "
-					   "transmit the packet exceeds the "
-					   "RS bit threshold. This will impact "
-					   "performance."
-					   "nb_used=%4u nb_free=%4u "
-					   "tx_rs_thresh=%4u. "
-					   "(port=%d queue=%d)",
-					   nb_used, txq->nb_tx_free,
-					   txq->tx_rs_thresh,
-					   txq->port_id, txq->queue_id);
+				ixgbe_trace_tx_thresh(txq->port_id, txq->queue_id,
+						      nb_used, txq->nb_tx_free, txq->tx_rs_thresh);
 				/*
 				 * Loop here until there are enough TX
 				 * descriptors or until the ring cannot be
@@ -918,10 +892,7 @@ ixgbe_xmit_pkts(void *tx_queue, struct rte_mbuf **tx_pkts,
 
 		/* Set RS bit only on threshold packets' last descriptor */
 		if (txq->nb_tx_used >= txq->tx_rs_thresh) {
-			PMD_TX_LOG(DEBUG,
-				   "Setting RS bit on TXD id="
-				   "%4u (port=%d queue=%d)",
-				   tx_last, txq->port_id, txq->queue_id);
+			ixgbe_trace_tx_rs(txq->port_id, txq->queue_id, tx_last);
 
 			cmd_type_len |= IXGBE_TXD_CMD_RS;
 
@@ -944,9 +915,7 @@ ixgbe_xmit_pkts(void *tx_queue, struct rte_mbuf **tx_pkts,
 	/*
 	 * Set the Transmit Descriptor Tail (TDT)
 	 */
-	PMD_TX_LOG(DEBUG, "port_id=%u queue_id=%u tx_tail=%u nb_tx=%u",
-		   (unsigned) txq->port_id, (unsigned) txq->queue_id,
-		   (unsigned) tx_id, (unsigned) nb_tx);
+	ixgbe_trace_tx_tail(txq->port_id, txq->queue_id, tx_id, nb_tx);
 	IXGBE_PCI_REG_WC_WRITE_RELAXED(txq->tdt_reg_addr, tx_id);
 	txq->tx_tail = tx_id;
 
@@ -1717,9 +1686,7 @@ rx_recv_pkts(void *rx_queue, struct rte_mbuf **rx_pkts,
 		if (ixgbe_rx_alloc_bufs(rxq, true) != 0) {
 			int i, j;
 
-			PMD_RX_LOG(DEBUG, "RX mbuf alloc failed port_id=%u "
-				   "queue_id=%u", (unsigned) rxq->port_id,
-				   (unsigned) rxq->queue_id);
+			ixgbe_trace_rx_mbuf_alloc_failed(rxq->port_id, rxq->queue_id);
 
 			rte_eth_devices[rxq->port_id].data->rx_mbuf_alloc_failed +=
 				rxq->rx_free_thresh;
@@ -1851,17 +1818,12 @@ ixgbe_recv_pkts(void *rx_queue, struct rte_mbuf **rx_pkts,
 		 * to happen by sending specific "back-pressure" flow control
 		 * frames to its peer(s).
 		 */
-		PMD_RX_LOG(DEBUG, "port_id=%u queue_id=%u rx_id=%u "
-			   "ext_err_stat=0x%08x pkt_len=%u",
-			   (unsigned) rxq->port_id, (unsigned) rxq->queue_id,
-			   (unsigned) rx_id, (unsigned) staterr,
-			   (unsigned) rte_le_to_cpu_16(rxd.wb.upper.length));
+		ixgbe_trace_rx(rxq->port_id, rxq->queue_id, rx_id,
+			       staterr, rte_le_to_cpu_16(rxd.wb.upper.length));
 
 		nmb = rte_mbuf_raw_alloc(rxq->mb_pool);
 		if (nmb == NULL) {
-			PMD_RX_LOG(DEBUG, "RX mbuf alloc failed port_id=%u "
-				   "queue_id=%u", (unsigned) rxq->port_id,
-				   (unsigned) rxq->queue_id);
+			ixgbe_trace_rx_mbuf_alloc_failed(rxq->port_id, rxq->queue_id);
 			rte_eth_devices[rxq->port_id].data->rx_mbuf_alloc_failed++;
 			break;
 		}
@@ -1959,11 +1921,9 @@ ixgbe_recv_pkts(void *rx_queue, struct rte_mbuf **rx_pkts,
 	 */
 	nb_hold = (uint16_t) (nb_hold + rxq->nb_rx_hold);
 	if (nb_hold > rxq->rx_free_thresh) {
-		PMD_RX_LOG(DEBUG, "port_id=%u queue_id=%u rx_tail=%u "
-			   "nb_hold=%u nb_rx=%u",
-			   (unsigned) rxq->port_id, (unsigned) rxq->queue_id,
-			   (unsigned) rx_id, (unsigned) nb_hold,
-			   (unsigned) nb_rx);
+		ixgbe_trace_rx_post(rxq->port_id, rxq->queue_id,
+				    rx_id, nb_hold, nb_rx);
+
 		rx_id = (uint16_t) ((rx_id == 0) ?
 				     (rxq->nb_rx_desc - 1) : (rx_id - 1));
 		IXGBE_PCI_REG_WC_WRITE(rxq->rdt_reg_addr, rx_id);
@@ -2124,17 +2084,13 @@ ixgbe_recv_pkts_lro(void *rx_queue, struct rte_mbuf **rx_pkts, uint16_t nb_pkts,
 
 		rxd = *rxdp;
 
-		PMD_RX_LOG(DEBUG, "port_id=%u queue_id=%u rx_id=%u "
-				  "staterr=0x%x data_len=%u",
-			   rxq->port_id, rxq->queue_id, rx_id, staterr,
-			   rte_le_to_cpu_16(rxd.wb.upper.length));
+		ixgbe_trace_rx(rxq->port_id, rxq->queue_id, rx_id, staterr,
+			       rte_le_to_cpu_16(rxd.wb.upper.length));
 
 		if (!bulk_alloc) {
 			nmb = rte_mbuf_raw_alloc(rxq->mb_pool);
 			if (nmb == NULL) {
-				PMD_RX_LOG(DEBUG, "RX mbuf alloc failed "
-						  "port_id=%u queue_id=%u",
-					   rxq->port_id, rxq->queue_id);
+				ixgbe_trace_rx_mbuf_alloc_failed(rxq->port_id, rxq->queue_id);
 
 				rte_eth_devices[rxq->port_id].data->
 							rx_mbuf_alloc_failed++;
@@ -2150,10 +2106,7 @@ ixgbe_recv_pkts_lro(void *rx_queue, struct rte_mbuf **rx_pkts, uint16_t nb_pkts,
 							next_rdt);
 				nb_hold -= rxq->rx_free_thresh;
 			} else {
-				PMD_RX_LOG(DEBUG, "RX bulk alloc failed "
-						  "port_id=%u queue_id=%u",
-					   rxq->port_id, rxq->queue_id);
-
+				ixgbe_trace_rx_mbuf_alloc_failed(rxq->port_id, rxq->queue_id);
 				rte_eth_devices[rxq->port_id].data->
 							rx_mbuf_alloc_failed++;
 				break;
@@ -2307,9 +2260,7 @@ ixgbe_recv_pkts_lro(void *rx_queue, struct rte_mbuf **rx_pkts, uint16_t nb_pkts,
 	 * hardware point of view...
 	 */
 	if (!bulk_alloc && nb_hold > rxq->rx_free_thresh) {
-		PMD_RX_LOG(DEBUG, "port_id=%u queue_id=%u rx_tail=%u "
-			   "nb_hold=%u nb_rx=%u",
-			   rxq->port_id, rxq->queue_id, rx_id, nb_hold, nb_rx);
+		ixgbe_trace_rx_post(rxq->port_id, rxq->queue_id, rx_id, nb_hold, nb_rx);
 
 		rte_wmb();
 		IXGBE_PCI_REG_WC_WRITE_RELAXED(rxq->rdt_reg_addr, prev_id);
diff --git a/drivers/net/ixgbe/ixgbe_trace.h b/drivers/net/ixgbe/ixgbe_trace.h
new file mode 100644
index 000000000000..f260edd6fe3a
--- /dev/null
+++ b/drivers/net/ixgbe/ixgbe_trace.h
@@ -0,0 +1,110 @@
+/* SPDX-License-Identifier: BSD-3-Clause */
+
+#ifndef _IXGBE_TRACE_H_
+#define _IXGBE_TRACE_H_
+
+#include <rte_trace_point.h>
+
+RTE_TRACE_POINT(
+	ixgbe_trace_rx_mbuf_alloc_failed,
+	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t rx_queue_id),
+	rte_trace_point_emit_u16(port_id);
+	rte_trace_point_emit_u16(rx_queue_id);
+);
+
+RTE_TRACE_POINT_FP(
+	ixgbe_trace_rx,
+	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t rx_queue_id,
+			     uint16_t rx_id, uint32_t staterr, uint16_t len),
+	rte_trace_point_emit_u16(port_id);
+	rte_trace_point_emit_u16(rx_queue_id);
+	rte_trace_point_emit_u16(rx_id);
+	rte_trace_point_emit_u32(staterr);
+	rte_trace_point_emit_u16(len);
+);
+
+RTE_TRACE_POINT_FP(
+	ixgbe_trace_rx_post,
+	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t rx_queue_id,
+			     uint16_t rx_id, uint16_t nb_hold, uint16_t nb_rx),
+	rte_trace_point_emit_u16(port_id);
+	rte_trace_point_emit_u16(rx_queue_id);
+	rte_trace_point_emit_u16(rx_id);
+	rte_trace_point_emit_u16(nb_hold);
+	rte_trace_point_emit_u16(nb_rx);
+);
+
+RTE_TRACE_POINT_FP(
+	ixgbe_trace_tx_done,
+	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
+			     uint16_t nb_to_clean, uint16_t last_desc_cleaned,
+			     uint16_t desc_to_clean),
+	rte_trace_point_emit_u16(port_id);
+	rte_trace_point_emit_u16(tx_queue_id);
+	rte_trace_point_emit_u16(nb_to_clean);
+	rte_trace_point_emit_u16(last_desc_cleaned);
+	rte_trace_point_emit_u16(desc_to_clean);
+);
+
+RTE_TRACE_POINT_FP(
+	ixgbe_trace_tx_not_done,
+	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
+			     uint16_t desc_to_clean),
+	rte_trace_point_emit_u16(port_id);
+	rte_trace_point_emit_u16(tx_queue_id);
+	rte_trace_point_emit_u16(desc_to_clean);
+);
+
+RTE_TRACE_POINT_FP(
+	ixgbe_trace_tx,
+	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
+			     uint16_t pktlen, uint16_t tx_first, uint16_t tx_last),
+	rte_trace_point_emit_u16(port_id);
+	rte_trace_point_emit_u16(tx_queue_id);
+	rte_trace_point_emit_u16(pktlen);
+	rte_trace_point_emit_u16(tx_first);
+	rte_trace_point_emit_u16(tx_last);
+);
+
+RTE_TRACE_POINT(
+	ixgbe_trace_tx_full,
+	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
+			     uint16_t nb_used, uint16_t nb_free),
+	rte_trace_point_emit_u16(port_id);
+	rte_trace_point_emit_u16(tx_queue_id);
+	rte_trace_point_emit_u16(nb_used);
+	rte_trace_point_emit_u16(nb_free);
+);
+
+RTE_TRACE_POINT(
+	ixgbe_trace_tx_thresh,
+	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
+			     uint16_t nb_used, uint16_t nb_free,
+			     uint16_t tx_rs_thresh),
+	rte_trace_point_emit_u16(port_id);
+	rte_trace_point_emit_u16(tx_queue_id);
+	rte_trace_point_emit_u16(nb_used);
+	rte_trace_point_emit_u16(nb_free);
+	rte_trace_point_emit_u16(tx_rs_thresh);
+);
+
+RTE_TRACE_POINT_FP(
+	ixgbe_trace_tx_rs,
+	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
+			     uint16_t txd_id),
+	rte_trace_point_emit_u16(port_id);
+	rte_trace_point_emit_u16(tx_queue_id);
+	rte_trace_point_emit_u16(txd_id);
+);
+
+RTE_TRACE_POINT_FP(
+	ixgbe_trace_tx_tail,
+	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
+			     uint16_t tx_tail, uint16_t nb_tx),
+	rte_trace_point_emit_u16(port_id);
+	rte_trace_point_emit_u16(tx_queue_id);
+	rte_trace_point_emit_u16(tx_tail);
+	rte_trace_point_emit_u16(nb_tx);
+);
+
+#endif /* _IXGBE_LOGS_H_ */
-- 
2.39.1

RE: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Long Li]

> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
> 
> On Thu, 23 Feb 2023 10:09:17 -0800
> Stephen Hemminger <stephen@networkplumber.org> wrote:
> 
> > On Thu, 23 Feb 2023 14:07:25 +0000
> > Ferruh Yigit <ferruh.yigit@amd.com> wrote:
> >
> > > Overall I am not sure if anyone is interested in driver datapath
> > > logs other than driver developers themselves.
> > >
> > > For datapath logging I think there are two concerns,
> > > 1) It should not eat *any* cycles unless explicitly enabled
> > > 2) Capability of enable/disable them because of massive amount of
> > > log it can generate
> > >
> > >
> > > Currently there are two existing approaches for driver datapath logging:
> > > i)  Controlled by 'RTE_ETHDEV_DEBUG_RX/TX' compile time flag,
> > >     when enabled 'rte_log()' is used with Rx/Tx specific log type.
> > > ii) 'RTE_LOG_DP' ', compile time control per logtype via
> > >     'RTE_LOG_DP_LEVEL',
> > >      when enabled 'rte_log()' is used with PMD logtype.
> > >
> > >
> > > In (ii), need to re-compile code when you need to increase the log
> > > verbosity, and it leaks to production code as mentioned above.
> > >
> > > For (i), developer compiles once enabling debug, later can fine
> > > grain log level dynamically. This is more DPDK developer focused approach.
> > >
> > >
> > > [1]
> > > According above, what do you think to retire 'RTE_LOG_DP', (at least
> > > within ethdev datapath), and chose (i) as preferred datapath logging?
> >
> > I agree, the current tx/rx logging is a mess.
> > Each driver is different, each driver has to have something to enable
> > it; and it really isn't useful beyond the driver developer.
> >
> > Using tracing seems like a much better option. Could we agree on a
> > common set of trace points for drivers and fix all drivers to use the same
> thing.
> > Probably will cause some upset among driver developers:
> > "where did my nice printf's go, now I have to learn tracing"
> > but DPDK has a good facility here, lets use it.
> >
> > My proposal would be:
> > 	- agree on common set of trace points
> > 	- apply to all drivers
> > 	- remove RTE_LOG_DP()
> > 	- remove per driver RX/TX options
> > 	- side effect, more uses of RTE_LOGTYPE_PMD go away.
> 
> Here is an example of using tracepoints instead.
> Compile tested for example only.
> 
> Note: using tracepoints it is possible to keep some of the tracepoints even if
> fastpath is not enabled.  Things like running out of Tx or Mbuf is not something
> that is perf critical; but would be good for application to see.

Thank you for the example.

I sent another patch converting data path logs (mana) to trace points.

Long

> 
> 
> ---
>  drivers/net/ixgbe/ixgbe_ethdev.c |   7 --
>  drivers/net/ixgbe/ixgbe_logs.h   |  18 -----
>  drivers/net/ixgbe/ixgbe_rxtx.c   |  95 +++++++-------------------
>  drivers/net/ixgbe/ixgbe_trace.h  | 110
> +++++++++++++++++++++++++++++++
>  4 files changed, 133 insertions(+), 97 deletions(-)  create mode 100644
> drivers/net/ixgbe/ixgbe_trace.h
> 
> diff --git a/drivers/net/ixgbe/ixgbe_ethdev.c
> b/drivers/net/ixgbe/ixgbe_ethdev.c
> index 88118bc30560..07f8ccdd97cb 100644
> --- a/drivers/net/ixgbe/ixgbe_ethdev.c
> +++ b/drivers/net/ixgbe/ixgbe_ethdev.c
> @@ -8317,10 +8317,3 @@
> RTE_PMD_REGISTER_PARAM_STRING(net_ixgbe_vf,
> 
>  RTE_LOG_REGISTER_SUFFIX(ixgbe_logtype_init, init, NOTICE);
> RTE_LOG_REGISTER_SUFFIX(ixgbe_logtype_driver, driver, NOTICE);
> -
> -#ifdef RTE_ETHDEV_DEBUG_RX
> -RTE_LOG_REGISTER_SUFFIX(ixgbe_logtype_rx, rx, DEBUG); -#endif -#ifdef
> RTE_ETHDEV_DEBUG_TX -RTE_LOG_REGISTER_SUFFIX(ixgbe_logtype_tx, tx,
> DEBUG); -#endif diff --git a/drivers/net/ixgbe/ixgbe_logs.h
> b/drivers/net/ixgbe/ixgbe_logs.h index 00ef797ca103..f70fa1fd4afd 100644
> --- a/drivers/net/ixgbe/ixgbe_logs.h
> +++ b/drivers/net/ixgbe/ixgbe_logs.h
> @@ -12,24 +12,6 @@ extern int ixgbe_logtype_init;
> 
>  #define PMD_INIT_FUNC_TRACE() PMD_INIT_LOG(DEBUG, " >>")
> 
> -#ifdef RTE_ETHDEV_DEBUG_RX
> -extern int ixgbe_logtype_rx;
> -#define PMD_RX_LOG(level, fmt, args...)			\
> -	rte_log(RTE_LOG_ ## level, ixgbe_logtype_rx,	\
> -		"%s(): " fmt "\n", __func__, ## args)
> -#else
> -#define PMD_RX_LOG(level, fmt, args...) do { } while (0) -#endif
> -
> -#ifdef RTE_ETHDEV_DEBUG_TX
> -extern int ixgbe_logtype_tx;
> -#define PMD_TX_LOG(level, fmt, args...)			\
> -	rte_log(RTE_LOG_ ## level, ixgbe_logtype_tx,	\
> -		"%s(): " fmt "\n", __func__, ## args)
> -#else
> -#define PMD_TX_LOG(level, fmt, args...) do { } while (0) -#endif
> -
>  extern int ixgbe_logtype_driver;
>  #define PMD_DRV_LOG_RAW(level, fmt, args...) \
>  	rte_log(RTE_LOG_ ## level, ixgbe_logtype_driver, "%s(): " fmt, \ diff --
> git a/drivers/net/ixgbe/ixgbe_rxtx.c b/drivers/net/ixgbe/ixgbe_rxtx.c index
> c9d6ca9efea4..f9f0ffebee8e 100644
> --- a/drivers/net/ixgbe/ixgbe_rxtx.c
> +++ b/drivers/net/ixgbe/ixgbe_rxtx.c
> @@ -46,6 +46,7 @@
>  #include <rte_vect.h>
> 
>  #include "ixgbe_logs.h"
> +#include "ixgbe_trace.h"
>  #include "base/ixgbe_api.h"
>  #include "base/ixgbe_vf.h"
>  #include "ixgbe_ethdev.h"
> @@ -581,11 +582,8 @@ ixgbe_xmit_cleanup(struct ixgbe_tx_queue *txq)
>  	desc_to_clean_to = sw_ring[desc_to_clean_to].last_id;
>  	status = txr[desc_to_clean_to].wb.status;
>  	if (!(status & rte_cpu_to_le_32(IXGBE_TXD_STAT_DD))) {
> -		PMD_TX_LOG(DEBUG,
> -			   "TX descriptor %4u is not done"
> -			   "(port=%d queue=%d)",
> -			   desc_to_clean_to,
> -			   txq->port_id, txq->queue_id);
> +		ixgbe_trace_tx_not_done(txq->port_id, txq->queue_id,
> +desc_to_clean_to);
> +
>  		/* Failed to clean any descriptors, better luck next time */
>  		return -(1);
>  	}
> @@ -598,11 +596,8 @@ ixgbe_xmit_cleanup(struct ixgbe_tx_queue *txq)
>  		nb_tx_to_clean = (uint16_t)(desc_to_clean_to -
>  						last_desc_cleaned);
> 
> -	PMD_TX_LOG(DEBUG,
> -		   "Cleaning %4u TX descriptors: %4u to %4u "
> -		   "(port=%d queue=%d)",
> -		   nb_tx_to_clean, last_desc_cleaned, desc_to_clean_to,
> -		   txq->port_id, txq->queue_id);
> +	ixgbe_trace_tx_done(txq->port_id, txq->queue_id,
> +			    nb_tx_to_clean, last_desc_cleaned,
> desc_to_clean_to);
> 
>  	/*
>  	 * The last descriptor to clean is done, so that means all the @@ -
> 734,26 +729,14 @@ ixgbe_xmit_pkts(void *tx_queue, struct rte_mbuf
> **tx_pkts,
>  		if (tx_last >= txq->nb_tx_desc)
>  			tx_last = (uint16_t) (tx_last - txq->nb_tx_desc);
> 
> -		PMD_TX_LOG(DEBUG, "port_id=%u queue_id=%u pktlen=%u"
> -			   " tx_first=%u tx_last=%u",
> -			   (unsigned) txq->port_id,
> -			   (unsigned) txq->queue_id,
> -			   (unsigned) pkt_len,
> -			   (unsigned) tx_id,
> -			   (unsigned) tx_last);
> -
> +		ixgbe_trace_tx(txq->port_id, txq->queue_id, pkt_len, tx_id,
> tx_last);
>  		/*
>  		 * Make sure there are enough TX descriptors available to
>  		 * transmit the entire packet.
>  		 * nb_used better be less than or equal to txq->tx_rs_thresh
>  		 */
>  		if (nb_used > txq->nb_tx_free) {
> -			PMD_TX_LOG(DEBUG,
> -				   "Not enough free TX descriptors "
> -				   "nb_used=%4u nb_free=%4u "
> -				   "(port=%d queue=%d)",
> -				   nb_used, txq->nb_tx_free,
> -				   txq->port_id, txq->queue_id);
> +			ixgbe_trace_tx_full(txq->port_id, txq->queue_id,
> nb_used,
> +txq->nb_tx_free);
> 
>  			if (ixgbe_xmit_cleanup(txq) != 0) {
>  				/* Could not clean any descriptors */ @@ -
> 764,17 +747,8 @@ ixgbe_xmit_pkts(void *tx_queue, struct rte_mbuf
> **tx_pkts,
> 
>  			/* nb_used better be <= txq->tx_rs_thresh */
>  			if (unlikely(nb_used > txq->tx_rs_thresh)) {
> -				PMD_TX_LOG(DEBUG,
> -					   "The number of descriptors needed
> to "
> -					   "transmit the packet exceeds the "
> -					   "RS bit threshold. This will impact "
> -					   "performance."
> -					   "nb_used=%4u nb_free=%4u "
> -					   "tx_rs_thresh=%4u. "
> -					   "(port=%d queue=%d)",
> -					   nb_used, txq->nb_tx_free,
> -					   txq->tx_rs_thresh,
> -					   txq->port_id, txq->queue_id);
> +				ixgbe_trace_tx_thresh(txq->port_id, txq-
> >queue_id,
> +						      nb_used, txq->nb_tx_free,
> txq->tx_rs_thresh);
>  				/*
>  				 * Loop here until there are enough TX
>  				 * descriptors or until the ring cannot be @@ -
> 918,10 +892,7 @@ ixgbe_xmit_pkts(void *tx_queue, struct rte_mbuf
> **tx_pkts,
> 
>  		/* Set RS bit only on threshold packets' last descriptor */
>  		if (txq->nb_tx_used >= txq->tx_rs_thresh) {
> -			PMD_TX_LOG(DEBUG,
> -				   "Setting RS bit on TXD id="
> -				   "%4u (port=%d queue=%d)",
> -				   tx_last, txq->port_id, txq->queue_id);
> +			ixgbe_trace_tx_rs(txq->port_id, txq->queue_id,
> tx_last);
> 
>  			cmd_type_len |= IXGBE_TXD_CMD_RS;
> 
> @@ -944,9 +915,7 @@ ixgbe_xmit_pkts(void *tx_queue, struct rte_mbuf
> **tx_pkts,
>  	/*
>  	 * Set the Transmit Descriptor Tail (TDT)
>  	 */
> -	PMD_TX_LOG(DEBUG, "port_id=%u queue_id=%u tx_tail=%u
> nb_tx=%u",
> -		   (unsigned) txq->port_id, (unsigned) txq->queue_id,
> -		   (unsigned) tx_id, (unsigned) nb_tx);
> +	ixgbe_trace_tx_tail(txq->port_id, txq->queue_id, tx_id, nb_tx);
>  	IXGBE_PCI_REG_WC_WRITE_RELAXED(txq->tdt_reg_addr, tx_id);
>  	txq->tx_tail = tx_id;
> 
> @@ -1717,9 +1686,7 @@ rx_recv_pkts(void *rx_queue, struct rte_mbuf
> **rx_pkts,
>  		if (ixgbe_rx_alloc_bufs(rxq, true) != 0) {
>  			int i, j;
> 
> -			PMD_RX_LOG(DEBUG, "RX mbuf alloc failed
> port_id=%u "
> -				   "queue_id=%u", (unsigned) rxq->port_id,
> -				   (unsigned) rxq->queue_id);
> +			ixgbe_trace_rx_mbuf_alloc_failed(rxq->port_id, rxq-
> >queue_id);
> 
>  			rte_eth_devices[rxq->port_id].data-
> >rx_mbuf_alloc_failed +=
>  				rxq->rx_free_thresh;
> @@ -1851,17 +1818,12 @@ ixgbe_recv_pkts(void *rx_queue, struct
> rte_mbuf **rx_pkts,
>  		 * to happen by sending specific "back-pressure" flow control
>  		 * frames to its peer(s).
>  		 */
> -		PMD_RX_LOG(DEBUG, "port_id=%u queue_id=%u rx_id=%u "
> -			   "ext_err_stat=0x%08x pkt_len=%u",
> -			   (unsigned) rxq->port_id, (unsigned) rxq->queue_id,
> -			   (unsigned) rx_id, (unsigned) staterr,
> -			   (unsigned) rte_le_to_cpu_16(rxd.wb.upper.length));
> +		ixgbe_trace_rx(rxq->port_id, rxq->queue_id, rx_id,
> +			       staterr, rte_le_to_cpu_16(rxd.wb.upper.length));
> 
>  		nmb = rte_mbuf_raw_alloc(rxq->mb_pool);
>  		if (nmb == NULL) {
> -			PMD_RX_LOG(DEBUG, "RX mbuf alloc failed
> port_id=%u "
> -				   "queue_id=%u", (unsigned) rxq->port_id,
> -				   (unsigned) rxq->queue_id);
> +			ixgbe_trace_rx_mbuf_alloc_failed(rxq->port_id, rxq-
> >queue_id);
>  			rte_eth_devices[rxq->port_id].data-
> >rx_mbuf_alloc_failed++;
>  			break;
>  		}
> @@ -1959,11 +1921,9 @@ ixgbe_recv_pkts(void *rx_queue, struct rte_mbuf
> **rx_pkts,
>  	 */
>  	nb_hold = (uint16_t) (nb_hold + rxq->nb_rx_hold);
>  	if (nb_hold > rxq->rx_free_thresh) {
> -		PMD_RX_LOG(DEBUG, "port_id=%u queue_id=%u rx_tail=%u
> "
> -			   "nb_hold=%u nb_rx=%u",
> -			   (unsigned) rxq->port_id, (unsigned) rxq->queue_id,
> -			   (unsigned) rx_id, (unsigned) nb_hold,
> -			   (unsigned) nb_rx);
> +		ixgbe_trace_rx_post(rxq->port_id, rxq->queue_id,
> +				    rx_id, nb_hold, nb_rx);
> +
>  		rx_id = (uint16_t) ((rx_id == 0) ?
>  				     (rxq->nb_rx_desc - 1) : (rx_id - 1));
>  		IXGBE_PCI_REG_WC_WRITE(rxq->rdt_reg_addr, rx_id); @@ -
> 2124,17 +2084,13 @@ ixgbe_recv_pkts_lro(void *rx_queue, struct rte_mbuf
> **rx_pkts, uint16_t nb_pkts,
> 
>  		rxd = *rxdp;
> 
> -		PMD_RX_LOG(DEBUG, "port_id=%u queue_id=%u rx_id=%u "
> -				  "staterr=0x%x data_len=%u",
> -			   rxq->port_id, rxq->queue_id, rx_id, staterr,
> -			   rte_le_to_cpu_16(rxd.wb.upper.length));
> +		ixgbe_trace_rx(rxq->port_id, rxq->queue_id, rx_id, staterr,
> +			       rte_le_to_cpu_16(rxd.wb.upper.length));
> 
>  		if (!bulk_alloc) {
>  			nmb = rte_mbuf_raw_alloc(rxq->mb_pool);
>  			if (nmb == NULL) {
> -				PMD_RX_LOG(DEBUG, "RX mbuf alloc failed "
> -						  "port_id=%u queue_id=%u",
> -					   rxq->port_id, rxq->queue_id);
> +				ixgbe_trace_rx_mbuf_alloc_failed(rxq-
> >port_id, rxq->queue_id);
> 
>  				rte_eth_devices[rxq->port_id].data->
> 
> 	rx_mbuf_alloc_failed++;
> @@ -2150,10 +2106,7 @@ ixgbe_recv_pkts_lro(void *rx_queue, struct
> rte_mbuf **rx_pkts, uint16_t nb_pkts,
>  							next_rdt);
>  				nb_hold -= rxq->rx_free_thresh;
>  			} else {
> -				PMD_RX_LOG(DEBUG, "RX bulk alloc failed "
> -						  "port_id=%u queue_id=%u",
> -					   rxq->port_id, rxq->queue_id);
> -
> +				ixgbe_trace_rx_mbuf_alloc_failed(rxq-
> >port_id, rxq->queue_id);
>  				rte_eth_devices[rxq->port_id].data->
> 
> 	rx_mbuf_alloc_failed++;
>  				break;
> @@ -2307,9 +2260,7 @@ ixgbe_recv_pkts_lro(void *rx_queue, struct
> rte_mbuf **rx_pkts, uint16_t nb_pkts,
>  	 * hardware point of view...
>  	 */
>  	if (!bulk_alloc && nb_hold > rxq->rx_free_thresh) {
> -		PMD_RX_LOG(DEBUG, "port_id=%u queue_id=%u rx_tail=%u
> "
> -			   "nb_hold=%u nb_rx=%u",
> -			   rxq->port_id, rxq->queue_id, rx_id, nb_hold, nb_rx);
> +		ixgbe_trace_rx_post(rxq->port_id, rxq->queue_id, rx_id,
> nb_hold,
> +nb_rx);
> 
>  		rte_wmb();
>  		IXGBE_PCI_REG_WC_WRITE_RELAXED(rxq->rdt_reg_addr,
> prev_id); diff --git a/drivers/net/ixgbe/ixgbe_trace.h
> b/drivers/net/ixgbe/ixgbe_trace.h new file mode 100644 index
> 000000000000..f260edd6fe3a
> --- /dev/null
> +++ b/drivers/net/ixgbe/ixgbe_trace.h
> @@ -0,0 +1,110 @@
> +/* SPDX-License-Identifier: BSD-3-Clause */
> +
> +#ifndef _IXGBE_TRACE_H_
> +#define _IXGBE_TRACE_H_
> +
> +#include <rte_trace_point.h>
> +
> +RTE_TRACE_POINT(
> +	ixgbe_trace_rx_mbuf_alloc_failed,
> +	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t rx_queue_id),
> +	rte_trace_point_emit_u16(port_id);
> +	rte_trace_point_emit_u16(rx_queue_id);
> +);
> +
> +RTE_TRACE_POINT_FP(
> +	ixgbe_trace_rx,
> +	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t rx_queue_id,
> +			     uint16_t rx_id, uint32_t staterr, uint16_t len),
> +	rte_trace_point_emit_u16(port_id);
> +	rte_trace_point_emit_u16(rx_queue_id);
> +	rte_trace_point_emit_u16(rx_id);
> +	rte_trace_point_emit_u32(staterr);
> +	rte_trace_point_emit_u16(len);
> +);
> +
> +RTE_TRACE_POINT_FP(
> +	ixgbe_trace_rx_post,
> +	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t rx_queue_id,
> +			     uint16_t rx_id, uint16_t nb_hold, uint16_t nb_rx),
> +	rte_trace_point_emit_u16(port_id);
> +	rte_trace_point_emit_u16(rx_queue_id);
> +	rte_trace_point_emit_u16(rx_id);
> +	rte_trace_point_emit_u16(nb_hold);
> +	rte_trace_point_emit_u16(nb_rx);
> +);
> +
> +RTE_TRACE_POINT_FP(
> +	ixgbe_trace_tx_done,
> +	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
> +			     uint16_t nb_to_clean, uint16_t last_desc_cleaned,
> +			     uint16_t desc_to_clean),
> +	rte_trace_point_emit_u16(port_id);
> +	rte_trace_point_emit_u16(tx_queue_id);
> +	rte_trace_point_emit_u16(nb_to_clean);
> +	rte_trace_point_emit_u16(last_desc_cleaned);
> +	rte_trace_point_emit_u16(desc_to_clean);
> +);
> +
> +RTE_TRACE_POINT_FP(
> +	ixgbe_trace_tx_not_done,
> +	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
> +			     uint16_t desc_to_clean),
> +	rte_trace_point_emit_u16(port_id);
> +	rte_trace_point_emit_u16(tx_queue_id);
> +	rte_trace_point_emit_u16(desc_to_clean);
> +);
> +
> +RTE_TRACE_POINT_FP(
> +	ixgbe_trace_tx,
> +	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
> +			     uint16_t pktlen, uint16_t tx_first, uint16_t tx_last),
> +	rte_trace_point_emit_u16(port_id);
> +	rte_trace_point_emit_u16(tx_queue_id);
> +	rte_trace_point_emit_u16(pktlen);
> +	rte_trace_point_emit_u16(tx_first);
> +	rte_trace_point_emit_u16(tx_last);
> +);
> +
> +RTE_TRACE_POINT(
> +	ixgbe_trace_tx_full,
> +	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
> +			     uint16_t nb_used, uint16_t nb_free),
> +	rte_trace_point_emit_u16(port_id);
> +	rte_trace_point_emit_u16(tx_queue_id);
> +	rte_trace_point_emit_u16(nb_used);
> +	rte_trace_point_emit_u16(nb_free);
> +);
> +
> +RTE_TRACE_POINT(
> +	ixgbe_trace_tx_thresh,
> +	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
> +			     uint16_t nb_used, uint16_t nb_free,
> +			     uint16_t tx_rs_thresh),
> +	rte_trace_point_emit_u16(port_id);
> +	rte_trace_point_emit_u16(tx_queue_id);
> +	rte_trace_point_emit_u16(nb_used);
> +	rte_trace_point_emit_u16(nb_free);
> +	rte_trace_point_emit_u16(tx_rs_thresh);
> +);
> +
> +RTE_TRACE_POINT_FP(
> +	ixgbe_trace_tx_rs,
> +	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
> +			     uint16_t txd_id),
> +	rte_trace_point_emit_u16(port_id);
> +	rte_trace_point_emit_u16(tx_queue_id);
> +	rte_trace_point_emit_u16(txd_id);
> +);
> +
> +RTE_TRACE_POINT_FP(
> +	ixgbe_trace_tx_tail,
> +	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t tx_queue_id,
> +			     uint16_t tx_tail, uint16_t nb_tx),
> +	rte_trace_point_emit_u16(port_id);
> +	rte_trace_point_emit_u16(tx_queue_id);
> +	rte_trace_point_emit_u16(tx_tail);
> +	rte_trace_point_emit_u16(nb_tx);
> +);
> +
> +#endif /* _IXGBE_LOGS_H_ */
> --
> 2.39.1
> 
> 

Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Ferruh Yigit]

On 3/3/2023 2:16 AM, Long Li wrote:
>> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
>>
>> On Thu, 23 Feb 2023 10:09:17 -0800
>> Stephen Hemminger <stephen@networkplumber.org> wrote:
>>
>>> On Thu, 23 Feb 2023 14:07:25 +0000
>>> Ferruh Yigit <ferruh.yigit@amd.com> wrote:
>>>
>>>> Overall I am not sure if anyone is interested in driver datapath
>>>> logs other than driver developers themselves.
>>>>
>>>> For datapath logging I think there are two concerns,
>>>> 1) It should not eat *any* cycles unless explicitly enabled
>>>> 2) Capability of enable/disable them because of massive amount of
>>>> log it can generate
>>>>
>>>>
>>>> Currently there are two existing approaches for driver datapath logging:
>>>> i)  Controlled by 'RTE_ETHDEV_DEBUG_RX/TX' compile time flag,
>>>>     when enabled 'rte_log()' is used with Rx/Tx specific log type.
>>>> ii) 'RTE_LOG_DP' ', compile time control per logtype via
>>>>     'RTE_LOG_DP_LEVEL',
>>>>      when enabled 'rte_log()' is used with PMD logtype.
>>>>
>>>>
>>>> In (ii), need to re-compile code when you need to increase the log
>>>> verbosity, and it leaks to production code as mentioned above.
>>>>
>>>> For (i), developer compiles once enabling debug, later can fine
>>>> grain log level dynamically. This is more DPDK developer focused approach.
>>>>
>>>>
>>>> [1]
>>>> According above, what do you think to retire 'RTE_LOG_DP', (at least
>>>> within ethdev datapath), and chose (i) as preferred datapath logging?
>>>
>>> I agree, the current tx/rx logging is a mess.
>>> Each driver is different, each driver has to have something to enable
>>> it; and it really isn't useful beyond the driver developer.
>>>
>>> Using tracing seems like a much better option. Could we agree on a
>>> common set of trace points for drivers and fix all drivers to use the same
>> thing.
>>> Probably will cause some upset among driver developers:
>>> "where did my nice printf's go, now I have to learn tracing"
>>> but DPDK has a good facility here, lets use it.
>>>
>>> My proposal would be:
>>> 	- agree on common set of trace points
>>> 	- apply to all drivers
>>> 	- remove RTE_LOG_DP()
>>> 	- remove per driver RX/TX options
>>> 	- side effect, more uses of RTE_LOGTYPE_PMD go away.
>>
>> Here is an example of using tracepoints instead.
>> Compile tested for example only.
>>
>> Note: using tracepoints it is possible to keep some of the tracepoints even if
>> fastpath is not enabled.  Things like running out of Tx or Mbuf is not something
>> that is perf critical; but would be good for application to see.
> 
> Thank you for the example.
> 
> I sent another patch converting data path logs (mana) to trace points.
> 

Hi Long,

Thanks for the effort, you were quick on this while discussion is going on.

Although tracepoint is a good feature, I am not sure if it can fully
replace the logging.
I think usage is slightly different, trace is missing custom human
readable message, which can be very helpful for end user.

And overall, it is a high level decision to switch logging to trace, it
is inconsistent to switch only single driver, perhaps techboard (cc'ed)
can discuss this.

Until such consensus reached, I think driver should continue with logging.



And for the logging, I suggest option (i) above, I was hoping more
comments but since it is missing I hope this can be discussed in
techboard for a conclusion.

RE: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Long Li]

> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
> 
> On 3/3/2023 2:16 AM, Long Li wrote:
> >> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
> >>
> >> On Thu, 23 Feb 2023 10:09:17 -0800
> >> Stephen Hemminger <stephen@networkplumber.org> wrote:
> >>
> >>> On Thu, 23 Feb 2023 14:07:25 +0000
> >>> Ferruh Yigit <ferruh.yigit@amd.com> wrote:
> >>>
> >>>> Overall I am not sure if anyone is interested in driver datapath
> >>>> logs other than driver developers themselves.
> >>>>
> >>>> For datapath logging I think there are two concerns,
> >>>> 1) It should not eat *any* cycles unless explicitly enabled
> >>>> 2) Capability of enable/disable them because of massive amount of
> >>>> log it can generate
> >>>>
> >>>>
> >>>> Currently there are two existing approaches for driver datapath logging:
> >>>> i)  Controlled by 'RTE_ETHDEV_DEBUG_RX/TX' compile time flag,
> >>>>     when enabled 'rte_log()' is used with Rx/Tx specific log type.
> >>>> ii) 'RTE_LOG_DP' ', compile time control per logtype via
> >>>>     'RTE_LOG_DP_LEVEL',
> >>>>      when enabled 'rte_log()' is used with PMD logtype.
> >>>>
> >>>>
> >>>> In (ii), need to re-compile code when you need to increase the log
> >>>> verbosity, and it leaks to production code as mentioned above.
> >>>>
> >>>> For (i), developer compiles once enabling debug, later can fine
> >>>> grain log level dynamically. This is more DPDK developer focused
> approach.
> >>>>
> >>>>
> >>>> [1]
> >>>> According above, what do you think to retire 'RTE_LOG_DP', (at
> >>>> least within ethdev datapath), and chose (i) as preferred datapath
> logging?
> >>>
> >>> I agree, the current tx/rx logging is a mess.
> >>> Each driver is different, each driver has to have something to
> >>> enable it; and it really isn't useful beyond the driver developer.
> >>>
> >>> Using tracing seems like a much better option. Could we agree on a
> >>> common set of trace points for drivers and fix all drivers to use
> >>> the same
> >> thing.
> >>> Probably will cause some upset among driver developers:
> >>> "where did my nice printf's go, now I have to learn tracing"
> >>> but DPDK has a good facility here, lets use it.
> >>>
> >>> My proposal would be:
> >>> 	- agree on common set of trace points
> >>> 	- apply to all drivers
> >>> 	- remove RTE_LOG_DP()
> >>> 	- remove per driver RX/TX options
> >>> 	- side effect, more uses of RTE_LOGTYPE_PMD go away.
> >>
> >> Here is an example of using tracepoints instead.
> >> Compile tested for example only.
> >>
> >> Note: using tracepoints it is possible to keep some of the
> >> tracepoints even if fastpath is not enabled.  Things like running out
> >> of Tx or Mbuf is not something that is perf critical; but would be good for
> application to see.
> >
> > Thank you for the example.
> >
> > I sent another patch converting data path logs (mana) to trace points.
> >
> 
> Hi Long,
> 
> Thanks for the effort, you were quick on this while discussion is going on.
> 
> Although tracepoint is a good feature, I am not sure if it can fully replace the
> logging.
> I think usage is slightly different, trace is missing custom human readable
> message, which can be very helpful for end user.
> 
> And overall, it is a high level decision to switch logging to trace, it is
> inconsistent to switch only single driver, perhaps techboard (cc'ed) can discuss
> this.
> 
> Until such consensus reached, I think driver should continue with logging.
> 
> 
> 
> And for the logging, I suggest option (i) above, I was hoping more comments
> but since it is missing I hope this can be discussed in techboard for a
> conclusion.

Hi Ferruh,

Are you suggesting that MANA should use 'RTE_ETHDEV_DEBUG_RX/TX'?

I'm happy to implement the logging in this way.

Long

Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Ferruh Yigit]

On 3/3/2023 7:04 PM, Long Li wrote:
>> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
>>
>> On 3/3/2023 2:16 AM, Long Li wrote:
>>>> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
>>>>
>>>> On Thu, 23 Feb 2023 10:09:17 -0800
>>>> Stephen Hemminger <stephen@networkplumber.org> wrote:
>>>>
>>>>> On Thu, 23 Feb 2023 14:07:25 +0000
>>>>> Ferruh Yigit <ferruh.yigit@amd.com> wrote:
>>>>>
>>>>>> Overall I am not sure if anyone is interested in driver datapath
>>>>>> logs other than driver developers themselves.
>>>>>>
>>>>>> For datapath logging I think there are two concerns,
>>>>>> 1) It should not eat *any* cycles unless explicitly enabled
>>>>>> 2) Capability of enable/disable them because of massive amount of
>>>>>> log it can generate
>>>>>>
>>>>>>
>>>>>> Currently there are two existing approaches for driver datapath logging:
>>>>>> i)  Controlled by 'RTE_ETHDEV_DEBUG_RX/TX' compile time flag,
>>>>>>     when enabled 'rte_log()' is used with Rx/Tx specific log type.
>>>>>> ii) 'RTE_LOG_DP' ', compile time control per logtype via
>>>>>>     'RTE_LOG_DP_LEVEL',
>>>>>>      when enabled 'rte_log()' is used with PMD logtype.
>>>>>>
>>>>>>
>>>>>> In (ii), need to re-compile code when you need to increase the log
>>>>>> verbosity, and it leaks to production code as mentioned above.
>>>>>>
>>>>>> For (i), developer compiles once enabling debug, later can fine
>>>>>> grain log level dynamically. This is more DPDK developer focused
>> approach.
>>>>>>
>>>>>>
>>>>>> [1]
>>>>>> According above, what do you think to retire 'RTE_LOG_DP', (at
>>>>>> least within ethdev datapath), and chose (i) as preferred datapath
>> logging?
>>>>>
>>>>> I agree, the current tx/rx logging is a mess.
>>>>> Each driver is different, each driver has to have something to
>>>>> enable it; and it really isn't useful beyond the driver developer.
>>>>>
>>>>> Using tracing seems like a much better option. Could we agree on a
>>>>> common set of trace points for drivers and fix all drivers to use
>>>>> the same
>>>> thing.
>>>>> Probably will cause some upset among driver developers:
>>>>> "where did my nice printf's go, now I have to learn tracing"
>>>>> but DPDK has a good facility here, lets use it.
>>>>>
>>>>> My proposal would be:
>>>>> 	- agree on common set of trace points
>>>>> 	- apply to all drivers
>>>>> 	- remove RTE_LOG_DP()
>>>>> 	- remove per driver RX/TX options
>>>>> 	- side effect, more uses of RTE_LOGTYPE_PMD go away.
>>>>
>>>> Here is an example of using tracepoints instead.
>>>> Compile tested for example only.
>>>>
>>>> Note: using tracepoints it is possible to keep some of the
>>>> tracepoints even if fastpath is not enabled.  Things like running out
>>>> of Tx or Mbuf is not something that is perf critical; but would be good for
>> application to see.
>>>
>>> Thank you for the example.
>>>
>>> I sent another patch converting data path logs (mana) to trace points.
>>>
>>
>> Hi Long,
>>
>> Thanks for the effort, you were quick on this while discussion is going on.
>>
>> Although tracepoint is a good feature, I am not sure if it can fully replace the
>> logging.
>> I think usage is slightly different, trace is missing custom human readable
>> message, which can be very helpful for end user.
>>
>> And overall, it is a high level decision to switch logging to trace, it is
>> inconsistent to switch only single driver, perhaps techboard (cc'ed) can discuss
>> this.
>>
>> Until such consensus reached, I think driver should continue with logging.
>>
>>
>>
>> And for the logging, I suggest option (i) above, I was hoping more comments
>> but since it is missing I hope this can be discussed in techboard for a
>> conclusion.
> 
> Hi Ferruh,
> 
> Are you suggesting that MANA should use 'RTE_ETHDEV_DEBUG_RX/TX'?
> 
> I'm happy to implement the logging in this way.
> 

Yes, that looks to me better balance for compile time / runtime config
for drive developers.

But it prevents product code / end user to get data path logs, although
I believe this is OK I am not sure how useful datapath logs in
production code, that is why I am looking for more comment for a decision.

Let's wait for next techboard meeting, in case this is discussed there,
before making new implementation.

RE: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Long Li]

> -----Original Message-----
> From: Ferruh Yigit <ferruh.yigit@amd.com>
> Sent: Friday, March 3, 2023 5:15 PM
> To: Long Li <longli@microsoft.com>; Stephen Hemminger
> <stephen@networkplumber.org>
> Cc: longli@linuxonhyperv.com; Thomas Monjalon <thomas@monjalon.net>;
> Andrew Rybchenko <andrew.rybchenko@oktetlabs.ru>; Jerin Jacob
> Kollanukkaran <jerinj@marvell.com>; David Marchand
> <david.marchand@redhat.com>; dev@dpdk.org; Ajay Sharma
> <sharmaajay@microsoft.com>; stable@dpdk.org; Luca Boccassi
> <bluca@debian.org>; Qi Z Zhang <qi.z.zhang@intel.com>; Ajit Khaparde
> <ajit.khaparde@broadcom.com>; Bruce Richardson
> <bruce.richardson@intel.com>; Konstantin Ananyev
> <konstantin.v.ananyev@yandex.ru>; Olivier Matz <olivier.matz@6wind.com>;
> Honnappa Nagarahalli <Honnappa.Nagarahalli@arm.com>; techboard@dpdk.org
> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
> 
> On 3/3/2023 7:04 PM, Long Li wrote:
> >> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
> >>
> >> On 3/3/2023 2:16 AM, Long Li wrote:
> >>>> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
> >>>>
> >>>> On Thu, 23 Feb 2023 10:09:17 -0800
> >>>> Stephen Hemminger <stephen@networkplumber.org> wrote:
> >>>>
> >>>>> On Thu, 23 Feb 2023 14:07:25 +0000 Ferruh Yigit
> >>>>> <ferruh.yigit@amd.com> wrote:
> >>>>>
> >>>>>> Overall I am not sure if anyone is interested in driver datapath
> >>>>>> logs other than driver developers themselves.
> >>>>>>
> >>>>>> For datapath logging I think there are two concerns,
> >>>>>> 1) It should not eat *any* cycles unless explicitly enabled
> >>>>>> 2) Capability of enable/disable them because of massive amount of
> >>>>>> log it can generate
> >>>>>>
> >>>>>>
> >>>>>> Currently there are two existing approaches for driver datapath logging:
> >>>>>> i)  Controlled by 'RTE_ETHDEV_DEBUG_RX/TX' compile time flag,
> >>>>>>     when enabled 'rte_log()' is used with Rx/Tx specific log type.
> >>>>>> ii) 'RTE_LOG_DP' ', compile time control per logtype via
> >>>>>>     'RTE_LOG_DP_LEVEL',
> >>>>>>      when enabled 'rte_log()' is used with PMD logtype.
> >>>>>>
> >>>>>>
> >>>>>> In (ii), need to re-compile code when you need to increase the
> >>>>>> log verbosity, and it leaks to production code as mentioned above.
> >>>>>>
> >>>>>> For (i), developer compiles once enabling debug, later can fine
> >>>>>> grain log level dynamically. This is more DPDK developer focused
> >> approach.
> >>>>>>
> >>>>>>
> >>>>>> [1]
> >>>>>> According above, what do you think to retire 'RTE_LOG_DP', (at
> >>>>>> least within ethdev datapath), and chose (i) as preferred
> >>>>>> datapath
> >> logging?
> >>>>>
> >>>>> I agree, the current tx/rx logging is a mess.
> >>>>> Each driver is different, each driver has to have something to
> >>>>> enable it; and it really isn't useful beyond the driver developer.
> >>>>>
> >>>>> Using tracing seems like a much better option. Could we agree on a
> >>>>> common set of trace points for drivers and fix all drivers to use
> >>>>> the same
> >>>> thing.
> >>>>> Probably will cause some upset among driver developers:
> >>>>> "where did my nice printf's go, now I have to learn tracing"
> >>>>> but DPDK has a good facility here, lets use it.
> >>>>>
> >>>>> My proposal would be:
> >>>>> 	- agree on common set of trace points
> >>>>> 	- apply to all drivers
> >>>>> 	- remove RTE_LOG_DP()
> >>>>> 	- remove per driver RX/TX options
> >>>>> 	- side effect, more uses of RTE_LOGTYPE_PMD go away.
> >>>>
> >>>> Here is an example of using tracepoints instead.
> >>>> Compile tested for example only.
> >>>>
> >>>> Note: using tracepoints it is possible to keep some of the
> >>>> tracepoints even if fastpath is not enabled.  Things like running
> >>>> out of Tx or Mbuf is not something that is perf critical; but would
> >>>> be good for
> >> application to see.
> >>>
> >>> Thank you for the example.
> >>>
> >>> I sent another patch converting data path logs (mana) to trace points.
> >>>
> >>
> >> Hi Long,
> >>
> >> Thanks for the effort, you were quick on this while discussion is going on.
> >>
> >> Although tracepoint is a good feature, I am not sure if it can fully
> >> replace the logging.
> >> I think usage is slightly different, trace is missing custom human
> >> readable message, which can be very helpful for end user.
> >>
> >> And overall, it is a high level decision to switch logging to trace,
> >> it is inconsistent to switch only single driver, perhaps techboard
> >> (cc'ed) can discuss this.
> >>
> >> Until such consensus reached, I think driver should continue with logging.
> >>
> >>
> >>
> >> And for the logging, I suggest option (i) above, I was hoping more
> >> comments but since it is missing I hope this can be discussed in
> >> techboard for a conclusion.
> >
> > Hi Ferruh,
> >
> > Are you suggesting that MANA should use 'RTE_ETHDEV_DEBUG_RX/TX'?
> >
> > I'm happy to implement the logging in this way.
> >
> 
> Yes, that looks to me better balance for compile time / runtime config for drive
> developers.
> 
> But it prevents product code / end user to get data path logs, although I believe
> this is OK I am not sure how useful datapath logs in production code, that is why I
> am looking for more comment for a decision.
> 
> Let's wait for next techboard meeting, in case this is discussed there, before
> making new implementation.

HI Ferruh,

Have we reached a decision on how to implement data path logs?

Thanks,
Long

Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Ferruh Yigit]

On 4/28/2023 2:29 AM, Long Li wrote:
> 
> 
>> -----Original Message-----
>> From: Ferruh Yigit <ferruh.yigit@amd.com>
>> Sent: Friday, March 3, 2023 5:15 PM
>> To: Long Li <longli@microsoft.com>; Stephen Hemminger
>> <stephen@networkplumber.org>
>> Cc: longli@linuxonhyperv.com; Thomas Monjalon <thomas@monjalon.net>;
>> Andrew Rybchenko <andrew.rybchenko@oktetlabs.ru>; Jerin Jacob
>> Kollanukkaran <jerinj@marvell.com>; David Marchand
>> <david.marchand@redhat.com>; dev@dpdk.org; Ajay Sharma
>> <sharmaajay@microsoft.com>; stable@dpdk.org; Luca Boccassi
>> <bluca@debian.org>; Qi Z Zhang <qi.z.zhang@intel.com>; Ajit Khaparde
>> <ajit.khaparde@broadcom.com>; Bruce Richardson
>> <bruce.richardson@intel.com>; Konstantin Ananyev
>> <konstantin.v.ananyev@yandex.ru>; Olivier Matz <olivier.matz@6wind.com>;
>> Honnappa Nagarahalli <Honnappa.Nagarahalli@arm.com>; techboard@dpdk.org
>> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
>>
>> On 3/3/2023 7:04 PM, Long Li wrote:
>>>> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
>>>>
>>>> On 3/3/2023 2:16 AM, Long Li wrote:
>>>>>> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
>>>>>>
>>>>>> On Thu, 23 Feb 2023 10:09:17 -0800
>>>>>> Stephen Hemminger <stephen@networkplumber.org> wrote:
>>>>>>
>>>>>>> On Thu, 23 Feb 2023 14:07:25 +0000 Ferruh Yigit
>>>>>>> <ferruh.yigit@amd.com> wrote:
>>>>>>>
>>>>>>>> Overall I am not sure if anyone is interested in driver datapath
>>>>>>>> logs other than driver developers themselves.
>>>>>>>>
>>>>>>>> For datapath logging I think there are two concerns,
>>>>>>>> 1) It should not eat *any* cycles unless explicitly enabled
>>>>>>>> 2) Capability of enable/disable them because of massive amount of
>>>>>>>> log it can generate
>>>>>>>>
>>>>>>>>
>>>>>>>> Currently there are two existing approaches for driver datapath logging:
>>>>>>>> i)  Controlled by 'RTE_ETHDEV_DEBUG_RX/TX' compile time flag,
>>>>>>>>     when enabled 'rte_log()' is used with Rx/Tx specific log type.
>>>>>>>> ii) 'RTE_LOG_DP' ', compile time control per logtype via
>>>>>>>>     'RTE_LOG_DP_LEVEL',
>>>>>>>>      when enabled 'rte_log()' is used with PMD logtype.
>>>>>>>>
>>>>>>>>
>>>>>>>> In (ii), need to re-compile code when you need to increase the
>>>>>>>> log verbosity, and it leaks to production code as mentioned above.
>>>>>>>>
>>>>>>>> For (i), developer compiles once enabling debug, later can fine
>>>>>>>> grain log level dynamically. This is more DPDK developer focused
>>>> approach.
>>>>>>>>
>>>>>>>>
>>>>>>>> [1]
>>>>>>>> According above, what do you think to retire 'RTE_LOG_DP', (at
>>>>>>>> least within ethdev datapath), and chose (i) as preferred
>>>>>>>> datapath
>>>> logging?
>>>>>>>
>>>>>>> I agree, the current tx/rx logging is a mess.
>>>>>>> Each driver is different, each driver has to have something to
>>>>>>> enable it; and it really isn't useful beyond the driver developer.
>>>>>>>
>>>>>>> Using tracing seems like a much better option. Could we agree on a
>>>>>>> common set of trace points for drivers and fix all drivers to use
>>>>>>> the same
>>>>>> thing.
>>>>>>> Probably will cause some upset among driver developers:
>>>>>>> "where did my nice printf's go, now I have to learn tracing"
>>>>>>> but DPDK has a good facility here, lets use it.
>>>>>>>
>>>>>>> My proposal would be:
>>>>>>> 	- agree on common set of trace points
>>>>>>> 	- apply to all drivers
>>>>>>> 	- remove RTE_LOG_DP()
>>>>>>> 	- remove per driver RX/TX options
>>>>>>> 	- side effect, more uses of RTE_LOGTYPE_PMD go away.
>>>>>>
>>>>>> Here is an example of using tracepoints instead.
>>>>>> Compile tested for example only.
>>>>>>
>>>>>> Note: using tracepoints it is possible to keep some of the
>>>>>> tracepoints even if fastpath is not enabled.  Things like running
>>>>>> out of Tx or Mbuf is not something that is perf critical; but would
>>>>>> be good for
>>>> application to see.
>>>>>
>>>>> Thank you for the example.
>>>>>
>>>>> I sent another patch converting data path logs (mana) to trace points.
>>>>>
>>>>
>>>> Hi Long,
>>>>
>>>> Thanks for the effort, you were quick on this while discussion is going on.
>>>>
>>>> Although tracepoint is a good feature, I am not sure if it can fully
>>>> replace the logging.
>>>> I think usage is slightly different, trace is missing custom human
>>>> readable message, which can be very helpful for end user.
>>>>
>>>> And overall, it is a high level decision to switch logging to trace,
>>>> it is inconsistent to switch only single driver, perhaps techboard
>>>> (cc'ed) can discuss this.
>>>>
>>>> Until such consensus reached, I think driver should continue with logging.
>>>>
>>>>
>>>>
>>>> And for the logging, I suggest option (i) above, I was hoping more
>>>> comments but since it is missing I hope this can be discussed in
>>>> techboard for a conclusion.
>>>
>>> Hi Ferruh,
>>>
>>> Are you suggesting that MANA should use 'RTE_ETHDEV_DEBUG_RX/TX'?
>>>
>>> I'm happy to implement the logging in this way.
>>>
>>
>> Yes, that looks to me better balance for compile time / runtime config for drive
>> developers.
>>
>> But it prevents product code / end user to get data path logs, although I believe
>> this is OK I am not sure how useful datapath logs in production code, that is why I
>> am looking for more comment for a decision.
>>
>> Let's wait for next techboard meeting, in case this is discussed there, before
>> making new implementation.
> 
> HI Ferruh,
> 
> Have we reached a decision on how to implement data path logs?
> 

Hi Long,

I am not aware of a result on the matter, let me continue with this
patch to not block it more.

RE: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Long Li]

>Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
>
>On 4/28/2023 2:29 AM, Long Li wrote:
>>
>>
>>> -----Original Message-----
>>> From: Ferruh Yigit <ferruh.yigit@amd.com>
>>> Sent: Friday, March 3, 2023 5:15 PM
>>> To: Long Li <longli@microsoft.com>; Stephen Hemminger
>>> <stephen@networkplumber.org>
>>> Cc: longli@linuxonhyperv.com; Thomas Monjalon
><thomas@monjalon.net>;
>>> Andrew Rybchenko <andrew.rybchenko@oktetlabs.ru>; Jerin Jacob
>>> Kollanukkaran <jerinj@marvell.com>; David Marchand
>>> <david.marchand@redhat.com>; dev@dpdk.org; Ajay Sharma
>>> <sharmaajay@microsoft.com>; stable@dpdk.org; Luca Boccassi
>>> <bluca@debian.org>; Qi Z Zhang <qi.z.zhang@intel.com>; Ajit Khaparde
>>> <ajit.khaparde@broadcom.com>; Bruce Richardson
>>> <bruce.richardson@intel.com>; Konstantin Ananyev
>>> <konstantin.v.ananyev@yandex.ru>; Olivier Matz
>>> <olivier.matz@6wind.com>; Honnappa Nagarahalli
>>> <Honnappa.Nagarahalli@arm.com>; techboard@dpdk.org
>>> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
>>>
>>> On 3/3/2023 7:04 PM, Long Li wrote:
>>>>> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
>>>>>
>>>>> On 3/3/2023 2:16 AM, Long Li wrote:
>>>>>>> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on
>>>>>>> datapath
>>>>>>>
>>>>>>> On Thu, 23 Feb 2023 10:09:17 -0800 Stephen Hemminger
>>>>>>> <stephen@networkplumber.org> wrote:
>>>>>>>
>>>>>>>> On Thu, 23 Feb 2023 14:07:25 +0000 Ferruh Yigit
>>>>>>>> <ferruh.yigit@amd.com> wrote:
>>>>>>>>
>>>>>>>>> Overall I am not sure if anyone is interested in driver
>>>>>>>>> datapath logs other than driver developers themselves.
>>>>>>>>>
>>>>>>>>> For datapath logging I think there are two concerns,
>>>>>>>>> 1) It should not eat *any* cycles unless explicitly enabled
>>>>>>>>> 2) Capability of enable/disable them because of massive amount
>>>>>>>>> of log it can generate
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Currently there are two existing approaches for driver datapath
>logging:
>>>>>>>>> i)  Controlled by 'RTE_ETHDEV_DEBUG_RX/TX' compile time flag,
>>>>>>>>>     when enabled 'rte_log()' is used with Rx/Tx specific log type.
>>>>>>>>> ii) 'RTE_LOG_DP' ', compile time control per logtype via
>>>>>>>>>     'RTE_LOG_DP_LEVEL',
>>>>>>>>>      when enabled 'rte_log()' is used with PMD logtype.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> In (ii), need to re-compile code when you need to increase the
>>>>>>>>> log verbosity, and it leaks to production code as mentioned above.
>>>>>>>>>
>>>>>>>>> For (i), developer compiles once enabling debug, later can fine
>>>>>>>>> grain log level dynamically. This is more DPDK developer
>>>>>>>>> focused
>>>>> approach.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> [1]
>>>>>>>>> According above, what do you think to retire 'RTE_LOG_DP', (at
>>>>>>>>> least within ethdev datapath), and chose (i) as preferred
>>>>>>>>> datapath
>>>>> logging?
>>>>>>>>
>>>>>>>> I agree, the current tx/rx logging is a mess.
>>>>>>>> Each driver is different, each driver has to have something to
>>>>>>>> enable it; and it really isn't useful beyond the driver developer.
>>>>>>>>
>>>>>>>> Using tracing seems like a much better option. Could we agree on
>>>>>>>> a common set of trace points for drivers and fix all drivers to
>>>>>>>> use the same
>>>>>>> thing.
>>>>>>>> Probably will cause some upset among driver developers:
>>>>>>>> "where did my nice printf's go, now I have to learn tracing"
>>>>>>>> but DPDK has a good facility here, lets use it.
>>>>>>>>
>>>>>>>> My proposal would be:
>>>>>>>> 	- agree on common set of trace points
>>>>>>>> 	- apply to all drivers
>>>>>>>> 	- remove RTE_LOG_DP()
>>>>>>>> 	- remove per driver RX/TX options
>>>>>>>> 	- side effect, more uses of RTE_LOGTYPE_PMD go away.
>>>>>>>
>>>>>>> Here is an example of using tracepoints instead.
>>>>>>> Compile tested for example only.
>>>>>>>
>>>>>>> Note: using tracepoints it is possible to keep some of the
>>>>>>> tracepoints even if fastpath is not enabled.  Things like running
>>>>>>> out of Tx or Mbuf is not something that is perf critical; but
>>>>>>> would be good for
>>>>> application to see.
>>>>>>
>>>>>> Thank you for the example.
>>>>>>
>>>>>> I sent another patch converting data path logs (mana) to trace points.
>>>>>>
>>>>>
>>>>> Hi Long,
>>>>>
>>>>> Thanks for the effort, you were quick on this while discussion is going on.
>>>>>
>>>>> Although tracepoint is a good feature, I am not sure if it can
>>>>> fully replace the logging.
>>>>> I think usage is slightly different, trace is missing custom human
>>>>> readable message, which can be very helpful for end user.
>>>>>
>>>>> And overall, it is a high level decision to switch logging to
>>>>> trace, it is inconsistent to switch only single driver, perhaps
>>>>> techboard
>>>>> (cc'ed) can discuss this.
>>>>>
>>>>> Until such consensus reached, I think driver should continue with logging.
>>>>>
>>>>>
>>>>>
>>>>> And for the logging, I suggest option (i) above, I was hoping more
>>>>> comments but since it is missing I hope this can be discussed in
>>>>> techboard for a conclusion.
>>>>
>>>> Hi Ferruh,
>>>>
>>>> Are you suggesting that MANA should use 'RTE_ETHDEV_DEBUG_RX/TX'?
>>>>
>>>> I'm happy to implement the logging in this way.
>>>>
>>>
>>> Yes, that looks to me better balance for compile time / runtime
>>> config for drive developers.
>>>
>>> But it prevents product code / end user to get data path logs,
>>> although I believe this is OK I am not sure how useful datapath logs
>>> in production code, that is why I am looking for more comment for a
>decision.
>>>
>>> Let's wait for next techboard meeting, in case this is discussed
>>> there, before making new implementation.
>>
>> HI Ferruh,
>>
>> Have we reached a decision on how to implement data path logs?
>>
>
>Hi Long,
>
>I am not aware of a result on the matter, let me continue with this patch to not
>block it more.

Thank you.

I have submitted several other patches since this patch was submitted. There may be some conflicts.

Please let me know if I should rebase this patch to latest code so it will be straightforward to apply.

Long

Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Stephen Hemminger]

On Fri, 3 Mar 2023 13:54:23 +0000
Ferruh Yigit <ferruh.yigit@amd.com> wrote:

> On 3/3/2023 2:16 AM, Long Li wrote:
> >> Subject: Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath
> >>
> >> On Thu, 23 Feb 2023 10:09:17 -0800
> >> Stephen Hemminger <stephen@networkplumber.org> wrote:
> >>  
> >>> On Thu, 23 Feb 2023 14:07:25 +0000
> >>> Ferruh Yigit <ferruh.yigit@amd.com> wrote:
> >>>  
> >>>> Overall I am not sure if anyone is interested in driver datapath
> >>>> logs other than driver developers themselves.
> >>>>
> >>>> For datapath logging I think there are two concerns,
> >>>> 1) It should not eat *any* cycles unless explicitly enabled
> >>>> 2) Capability of enable/disable them because of massive amount of
> >>>> log it can generate
> >>>>
> >>>>
> >>>> Currently there are two existing approaches for driver datapath logging:
> >>>> i)  Controlled by 'RTE_ETHDEV_DEBUG_RX/TX' compile time flag,
> >>>>     when enabled 'rte_log()' is used with Rx/Tx specific log type.
> >>>> ii) 'RTE_LOG_DP' ', compile time control per logtype via
> >>>>     'RTE_LOG_DP_LEVEL',
> >>>>      when enabled 'rte_log()' is used with PMD logtype.
> >>>>
> >>>>
> >>>> In (ii), need to re-compile code when you need to increase the log
> >>>> verbosity, and it leaks to production code as mentioned above.
> >>>>
> >>>> For (i), developer compiles once enabling debug, later can fine
> >>>> grain log level dynamically. This is more DPDK developer focused approach.
> >>>>
> >>>>
> >>>> [1]
> >>>> According above, what do you think to retire 'RTE_LOG_DP', (at least
> >>>> within ethdev datapath), and chose (i) as preferred datapath logging?  
> >>>
> >>> I agree, the current tx/rx logging is a mess.
> >>> Each driver is different, each driver has to have something to enable
> >>> it; and it really isn't useful beyond the driver developer.
> >>>
> >>> Using tracing seems like a much better option. Could we agree on a
> >>> common set of trace points for drivers and fix all drivers to use the same  
> >> thing.  
> >>> Probably will cause some upset among driver developers:
> >>> "where did my nice printf's go, now I have to learn tracing"
> >>> but DPDK has a good facility here, lets use it.
> >>>
> >>> My proposal would be:
> >>> 	- agree on common set of trace points
> >>> 	- apply to all drivers
> >>> 	- remove RTE_LOG_DP()
> >>> 	- remove per driver RX/TX options
> >>> 	- side effect, more uses of RTE_LOGTYPE_PMD go away.  
> >>
> >> Here is an example of using tracepoints instead.
> >> Compile tested for example only.
> >>
> >> Note: using tracepoints it is possible to keep some of the tracepoints even if
> >> fastpath is not enabled.  Things like running out of Tx or Mbuf is not something
> >> that is perf critical; but would be good for application to see.  
> > 
> > Thank you for the example.
> > 
> > I sent another patch converting data path logs (mana) to trace points.
> >   
> 
> Hi Long,
> 
> Thanks for the effort, you were quick on this while discussion is going on.
> 
> Although tracepoint is a good feature, I am not sure if it can fully
> replace the logging.
> I think usage is slightly different, trace is missing custom human
> readable message, which can be very helpful for end user.


Agree in theory, but looking at existing drivers the datapath log messages
are all just printf's of existing variables. Plus the interpretation of
what those fields and offsets only has meaning and context for someone
familiar with the driver.

> 
> And overall, it is a high level decision to switch logging to trace, it
> is inconsistent to switch only single driver, perhaps techboard (cc'ed)
> can discuss this.

Code in existing datapath logging can be easily converted driver by driver.
The problem is the lack of testing.

Re: [PATCH] net/mana: use RTE_LOG_DP for logs on datapath

[Ferruh Yigit]

On 2/21/2023 8:42 PM, longli@linuxonhyperv.com wrote:
> From: Long Li <longli@microsoft.com>
> 
> Change all the logging statements on the datapath to use RTE_LOG_DP() to
> reduce CPU overhead when logging is not enabled for datapath.
> 
> Fixes: 517ed6e2d5 ("net/mana: add basic driver with build environment")
> Cc: stable@dpdk.org
> Signed-off-by: Long Li <longli@microsoft.com>

Applied to dpdk-next-net/main, thanks.