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

[Stephen Hemminger <stephen@networkplumber.org>]

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