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

[Long Li <longli@microsoft.com>]

> 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
> 
>