[dpdk-dev] [PATCH] log: do not drop debug logs at compile time
Olivier Matz
olivier.matz at 6wind.com
Fri Sep 16 09:43:52 CEST 2016
Today, all logs whose level is lower than INFO are dropped at
compile-time. This prevents from enabling debug logs at runtime using
--log-level=8.
The rationale was to remove debug logs from the data path at
compile-time, avoiding a test at run-time.
This patch changes the behavior of RTE_LOG() to avoid the compile-time
optimization, and introduces the RTE_LOG_DP() macro that has the same
behavior than the previous RTE_LOG(), for the rare cases where debug
logs are in the data path.
So it is now possible to enable debug logs at run-time by just
specifying --log-level=8. Some drivers still have special compile-time
options to enable more debug log. Maintainers may consider to
remove/reduce them.
Signed-off-by: Olivier Matz <olivier.matz at 6wind.com>
---
config/common_base | 1 +
doc/guides/faq/faq.rst | 2 +-
drivers/net/bnxt/bnxt_txr.c | 2 +-
drivers/net/nfp/nfp_net.c | 8 +++---
examples/distributor/main.c | 4 +--
examples/ipsec-secgw/esp.c | 2 +-
examples/ipsec-secgw/ipsec.c | 4 +--
examples/packet_ordering/main.c | 6 ++--
examples/quota_watermark/qw/main.c | 2 +-
examples/tep_termination/main.c | 4 +--
examples/vhost/main.c | 14 +++++-----
examples/vhost_xen/main.c | 20 +++++++-------
lib/librte_eal/common/include/rte_log.h | 49 +++++++++++++++++++++------------
13 files changed, 67 insertions(+), 51 deletions(-)
diff --git a/config/common_base b/config/common_base
index 7830535..04b71e9 100644
--- a/config/common_base
+++ b/config/common_base
@@ -89,6 +89,7 @@ CONFIG_RTE_MAX_MEMSEG=256
CONFIG_RTE_MAX_MEMZONE=2560
CONFIG_RTE_MAX_TAILQ=32
CONFIG_RTE_LOG_LEVEL=RTE_LOG_INFO
+CONFIG_RTE_LOG_DP_LEVEL=RTE_LOG_INFO
CONFIG_RTE_LOG_HISTORY=256
CONFIG_RTE_LIBEAL_USE_HPET=n
CONFIG_RTE_EAL_ALLOW_INV_SOCKET_ID=n
diff --git a/doc/guides/faq/faq.rst b/doc/guides/faq/faq.rst
index 8d1ea6c..0adc549 100644
--- a/doc/guides/faq/faq.rst
+++ b/doc/guides/faq/faq.rst
@@ -101,7 +101,7 @@ Yes, the option ``--log-level=`` accepts one of these numbers:
#define RTE_LOG_INFO 7U /* Informational. */
#define RTE_LOG_DEBUG 8U /* Debug-level messages. */
-It is also possible to change the maximum (and default level) at compile time
+It is also possible to change the default level at compile time
with ``CONFIG_RTE_LOG_LEVEL``.
diff --git a/drivers/net/bnxt/bnxt_txr.c b/drivers/net/bnxt/bnxt_txr.c
index 8bf8fee..0d15bb1 100644
--- a/drivers/net/bnxt/bnxt_txr.c
+++ b/drivers/net/bnxt/bnxt_txr.c
@@ -298,7 +298,7 @@ static int bnxt_handle_tx_cp(struct bnxt_tx_queue *txq)
if (CMP_TYPE(txcmp) == TX_CMPL_TYPE_TX_L2)
nb_tx_pkts++;
else
- RTE_LOG(DEBUG, PMD,
+ RTE_LOG_DP(DEBUG, PMD,
"Unhandled CMP type %02x\n",
CMP_TYPE(txcmp));
raw_cons = NEXT_RAW_CMP(raw_cons);
diff --git a/drivers/net/nfp/nfp_net.c b/drivers/net/nfp/nfp_net.c
index 0d60baa..11f544c 100644
--- a/drivers/net/nfp/nfp_net.c
+++ b/drivers/net/nfp/nfp_net.c
@@ -1701,7 +1701,7 @@ nfp_net_recv_pkts(void *rx_queue, struct rte_mbuf **rx_pkts, uint16_t nb_pkts)
* DPDK just checks the queue is lower than max queues
* enabled. But the queue needs to be configured
*/
- RTE_LOG(ERR, PMD, "RX Bad queue\n");
+ RTE_LOG_DP(ERR, PMD, "RX Bad queue\n");
return -EINVAL;
}
@@ -1714,7 +1714,7 @@ nfp_net_recv_pkts(void *rx_queue, struct rte_mbuf **rx_pkts, uint16_t nb_pkts)
rxb = &rxq->rxbufs[idx];
if (unlikely(rxb == NULL)) {
- RTE_LOG(ERR, PMD, "rxb does not exist!\n");
+ RTE_LOG_DP(ERR, PMD, "rxb does not exist!\n");
break;
}
@@ -1734,7 +1734,7 @@ nfp_net_recv_pkts(void *rx_queue, struct rte_mbuf **rx_pkts, uint16_t nb_pkts)
*/
new_mb = rte_pktmbuf_alloc(rxq->mem_pool);
if (unlikely(new_mb == NULL)) {
- RTE_LOG(DEBUG, PMD, "RX mbuf alloc failed port_id=%u "
+ RTE_LOG_DP(DEBUG, PMD, "RX mbuf alloc failed port_id=%u "
"queue_id=%u\n", (unsigned)rxq->port_id,
(unsigned)rxq->qidx);
nfp_net_mbuf_alloc_failed(rxq);
@@ -1765,7 +1765,7 @@ nfp_net_recv_pkts(void *rx_queue, struct rte_mbuf **rx_pkts, uint16_t nb_pkts)
* responsibility of avoiding it. But we have
* to give some info about the error
*/
- RTE_LOG(ERR, PMD,
+ RTE_LOG_DP(ERR, PMD,
"mbuf overflow likely due to the RX offset.\n"
"\t\tYour mbuf size should have extra space for"
" RX offset=%u bytes.\n"
diff --git a/examples/distributor/main.c b/examples/distributor/main.c
index 537cee1..e7641d2 100644
--- a/examples/distributor/main.c
+++ b/examples/distributor/main.c
@@ -241,7 +241,7 @@ lcore_rx(struct lcore_params *p)
uint16_t sent = rte_ring_enqueue_burst(r, (void *)bufs, nb_ret);
app_stats.rx.enqueued_pkts += sent;
if (unlikely(sent < nb_ret)) {
- RTE_LOG(DEBUG, DISTRAPP,
+ RTE_LOG_DP(DEBUG, DISTRAPP,
"%s:Packet loss due to full ring\n", __func__);
while (sent < nb_ret)
rte_pktmbuf_free(bufs[sent++]);
@@ -274,7 +274,7 @@ flush_one_port(struct output_buffer *outbuf, uint8_t outp)
app_stats.tx.tx_pkts += nb_tx;
if (unlikely(nb_tx < outbuf->count)) {
- RTE_LOG(DEBUG, DISTRAPP,
+ RTE_LOG_DP(DEBUG, DISTRAPP,
"%s:Packet loss with tx_burst\n", __func__);
do {
rte_pktmbuf_free(outbuf->mbufs[nb_tx]);
diff --git a/examples/ipsec-secgw/esp.c b/examples/ipsec-secgw/esp.c
index 05caa77..987eb3f 100644
--- a/examples/ipsec-secgw/esp.c
+++ b/examples/ipsec-secgw/esp.c
@@ -93,7 +93,7 @@ esp_inbound(struct rte_mbuf *m, struct ipsec_sa *sa,
sizeof(struct esp_hdr) - sa->iv_len - sa->digest_len;
if ((payload_len & (sa->block_size - 1)) || (payload_len <= 0)) {
- RTE_LOG(DEBUG, IPSEC_ESP, "payload %d not multiple of %u\n",
+ RTE_LOG_DP(DEBUG, IPSEC_ESP, "payload %d not multiple of %u\n",
payload_len, sa->block_size);
return -EINVAL;
}
diff --git a/examples/ipsec-secgw/ipsec.c b/examples/ipsec-secgw/ipsec.c
index 1e87d0d..4d9eff1 100644
--- a/examples/ipsec-secgw/ipsec.c
+++ b/examples/ipsec-secgw/ipsec.c
@@ -65,7 +65,7 @@ create_session(struct ipsec_ctx *ipsec_ctx __rte_unused, struct ipsec_sa *sa)
return -1;
}
- RTE_LOG(DEBUG, IPSEC, "Create session for SA spi %u on cryptodev "
+ RTE_LOG_DP(DEBUG, IPSEC, "Create session for SA spi %u on cryptodev "
"%u qp %u\n", sa->spi,
ipsec_ctx->tbl[cdev_id_qp].id,
ipsec_ctx->tbl[cdev_id_qp].qp);
@@ -89,7 +89,7 @@ enqueue_cop(struct cdev_qp *cqp, struct rte_crypto_op *cop)
ret = rte_cryptodev_enqueue_burst(cqp->id, cqp->qp,
cqp->buf, cqp->len);
if (ret < cqp->len) {
- RTE_LOG(DEBUG, IPSEC, "Cryptodev %u queue %u:"
+ RTE_LOG_DP(DEBUG, IPSEC, "Cryptodev %u queue %u:"
" enqueued %u crypto ops out of %u\n",
cqp->id, cqp->qp,
ret, cqp->len);
diff --git a/examples/packet_ordering/main.c b/examples/packet_ordering/main.c
index 3c88b86..d4dc789 100644
--- a/examples/packet_ordering/main.c
+++ b/examples/packet_ordering/main.c
@@ -229,7 +229,7 @@ flush_tx_error_callback(struct rte_mbuf **unsent, uint16_t count,
/* free the mbufs which failed from transmit */
app_stats.tx.ro_tx_failed_pkts += count;
- RTE_LOG(DEBUG, REORDERAPP, "%s:Packet loss with tx_burst\n", __func__);
+ RTE_LOG_DP(DEBUG, REORDERAPP, "%s:Packet loss with tx_burst\n", __func__);
pktmbuf_free_bulk(unsent, count);
}
@@ -410,7 +410,7 @@ rx_thread(struct rte_ring *ring_out)
nb_rx_pkts = rte_eth_rx_burst(port_id, 0,
pkts, MAX_PKTS_BURST);
if (nb_rx_pkts == 0) {
- RTE_LOG(DEBUG, REORDERAPP,
+ RTE_LOG_DP(DEBUG, REORDERAPP,
"%s():Received zero packets\n", __func__);
continue;
}
@@ -522,7 +522,7 @@ send_thread(struct send_thread_args *args)
if (ret == -1 && rte_errno == ERANGE) {
/* Too early pkts should be transmitted out directly */
- RTE_LOG(DEBUG, REORDERAPP,
+ RTE_LOG_DP(DEBUG, REORDERAPP,
"%s():Cannot reorder early packet "
"direct enqueuing to TX\n", __func__);
outp = mbufs[i]->port;
diff --git a/examples/quota_watermark/qw/main.c b/examples/quota_watermark/qw/main.c
index 8ed0214..9162e28 100644
--- a/examples/quota_watermark/qw/main.c
+++ b/examples/quota_watermark/qw/main.c
@@ -81,7 +81,7 @@ static void send_pause_frame(uint8_t port_id, uint16_t duration)
struct ether_hdr *hdr;
struct ether_addr mac_addr;
- RTE_LOG(DEBUG, USER1, "Sending PAUSE frame (duration=%d) on port %d\n",
+ RTE_LOG_DP(DEBUG, USER1, "Sending PAUSE frame (duration=%d) on port %d\n",
duration, port_id);
/* Get a mbuf from the pool */
diff --git a/examples/tep_termination/main.c b/examples/tep_termination/main.c
index 622f248..57c7541 100644
--- a/examples/tep_termination/main.c
+++ b/examples/tep_termination/main.c
@@ -567,7 +567,7 @@ virtio_tx_route(struct vhost_dev *vdev, struct rte_mbuf *m)
unsigned len, ret = 0;
const uint16_t lcore_id = rte_lcore_id();
- RTE_LOG(DEBUG, VHOST_DATA, "(%d) TX: MAC address is external\n",
+ RTE_LOG_DP(DEBUG, VHOST_DATA, "(%d) TX: MAC address is external\n",
vdev->vid);
/* Add packet to the port tx queue */
@@ -649,7 +649,7 @@ switch_worker(__rte_unused void *arg)
if (unlikely(diff_tsc > drain_tsc)) {
if (tx_q->len) {
- RTE_LOG(DEBUG, VHOST_DATA, "TX queue drained after "
+ RTE_LOG_DP(DEBUG, VHOST_DATA, "TX queue drained after "
"timeout with burst size %u\n",
tx_q->len);
ret = overlay_options.tx_handle(ports[0],
diff --git a/examples/vhost/main.c b/examples/vhost/main.c
index 92a9823..0f678f2 100644
--- a/examples/vhost/main.c
+++ b/examples/vhost/main.c
@@ -839,17 +839,17 @@ virtio_tx_local(struct vhost_dev *vdev, struct rte_mbuf *m)
return -1;
if (vdev->vid == dst_vdev->vid) {
- RTE_LOG(DEBUG, VHOST_DATA,
+ RTE_LOG_DP(DEBUG, VHOST_DATA,
"(%d) TX: src and dst MAC is same. Dropping packet.\n",
vdev->vid);
return 0;
}
- RTE_LOG(DEBUG, VHOST_DATA,
+ RTE_LOG_DP(DEBUG, VHOST_DATA,
"(%d) TX: MAC address is local\n", dst_vdev->vid);
if (unlikely(dst_vdev->remove)) {
- RTE_LOG(DEBUG, VHOST_DATA,
+ RTE_LOG_DP(DEBUG, VHOST_DATA,
"(%d) device is marked for removal\n", dst_vdev->vid);
return 0;
}
@@ -874,7 +874,7 @@ find_local_dest(struct vhost_dev *vdev, struct rte_mbuf *m,
return 0;
if (vdev->vid == dst_vdev->vid) {
- RTE_LOG(DEBUG, VHOST_DATA,
+ RTE_LOG_DP(DEBUG, VHOST_DATA,
"(%d) TX: src and dst MAC is same. Dropping packet.\n",
vdev->vid);
return -1;
@@ -888,7 +888,7 @@ find_local_dest(struct vhost_dev *vdev, struct rte_mbuf *m,
*offset = VLAN_HLEN;
*vlan_tag = vlan_tags[vdev->vid];
- RTE_LOG(DEBUG, VHOST_DATA,
+ RTE_LOG_DP(DEBUG, VHOST_DATA,
"(%d) TX: pkt to local VM device id: (%d), vlan tag: %u.\n",
vdev->vid, dst_vdev->vid, *vlan_tag);
@@ -980,7 +980,7 @@ virtio_tx_route(struct vhost_dev *vdev, struct rte_mbuf *m, uint16_t vlan_tag)
}
}
- RTE_LOG(DEBUG, VHOST_DATA,
+ RTE_LOG_DP(DEBUG, VHOST_DATA,
"(%d) TX: MAC address is external\n", vdev->vid);
queue2nic:
@@ -1048,7 +1048,7 @@ drain_mbuf_table(struct mbuf_table *tx_q)
if (unlikely(cur_tsc - prev_tsc > MBUF_TABLE_DRAIN_TSC)) {
prev_tsc = cur_tsc;
- RTE_LOG(DEBUG, VHOST_DATA,
+ RTE_LOG_DP(DEBUG, VHOST_DATA,
"TX queue drained after timeout with burst size %u\n",
tx_q->len);
do_drain_mbuf_table(tx_q);
diff --git a/examples/vhost_xen/main.c b/examples/vhost_xen/main.c
index 2e40357..c532d32 100644
--- a/examples/vhost_xen/main.c
+++ b/examples/vhost_xen/main.c
@@ -525,7 +525,7 @@ gpa_to_vva(struct virtio_net *dev, uint64_t guest_pa)
break;
}
}
- RTE_LOG(DEBUG, VHOST_DATA, "(%" PRIu64 ") GPA %p| VVA %p\n",
+ RTE_LOG_DP(DEBUG, VHOST_DATA, "(%" PRIu64 ") GPA %p| VVA %p\n",
dev->device_fh, (void*)(uintptr_t)guest_pa, (void*)(uintptr_t)vhost_va);
return vhost_va;
@@ -555,7 +555,7 @@ virtio_dev_rx(struct virtio_net *dev, struct rte_mbuf **pkts, uint32_t count)
uint8_t success = 0;
void *userdata;
- RTE_LOG(DEBUG, VHOST_DATA, "(%" PRIu64 ") virtio_dev_rx()\n", dev->device_fh);
+ RTE_LOG_DP(DEBUG, VHOST_DATA, "(%" PRIu64 ") virtio_dev_rx()\n", dev->device_fh);
vq = dev->virtqueue_rx;
count = (count > MAX_PKT_BURST) ? MAX_PKT_BURST : count;
/* As many data cores may want access to available buffers, they need to be reserved. */
@@ -580,7 +580,7 @@ virtio_dev_rx(struct virtio_net *dev, struct rte_mbuf **pkts, uint32_t count)
res_end_idx);
} while (unlikely(success == 0));
res_cur_idx = res_base_idx;
- RTE_LOG(DEBUG, VHOST_DATA, "(%" PRIu64 ") Current Index %d| End Index %d\n",
+ RTE_LOG_DP(DEBUG, VHOST_DATA, "(%" PRIu64 ") Current Index %d| End Index %d\n",
dev->device_fh, res_cur_idx, res_end_idx);
/* Prefetch available ring to retrieve indexes. */
@@ -775,7 +775,7 @@ virtio_tx_local(struct virtio_net *dev, struct rte_mbuf *m)
/* Drop the packet if the TX packet is destined for the TX device. */
if (dev_ll->dev->device_fh == dev->device_fh) {
- RTE_LOG(DEBUG, VHOST_DATA, "(%" PRIu64 ") TX: "
+ RTE_LOG_DP(DEBUG, VHOST_DATA, "(%" PRIu64 ") TX: "
"Source and destination MAC addresses are the same. "
"Dropping packet.\n",
dev_ll->dev->device_fh);
@@ -783,12 +783,12 @@ virtio_tx_local(struct virtio_net *dev, struct rte_mbuf *m)
}
- RTE_LOG(DEBUG, VHOST_DATA, "(%" PRIu64 ") TX: "
+ RTE_LOG_DP(DEBUG, VHOST_DATA, "(%" PRIu64 ") TX: "
"MAC address is local\n", dev_ll->dev->device_fh);
if (dev_ll->dev->remove) {
/*drop the packet if the device is marked for removal*/
- RTE_LOG(DEBUG, VHOST_DATA, "(%" PRIu64 ") "
+ RTE_LOG_DP(DEBUG, VHOST_DATA, "(%" PRIu64 ") "
"Device is marked for removal\n",
dev_ll->dev->device_fh);
} else {
@@ -829,7 +829,7 @@ virtio_tx_route(struct virtio_net* dev, struct rte_mbuf *m, struct rte_mempool *
return;
}
- RTE_LOG(DEBUG, VHOST_DATA, "(%" PRIu64 ") TX: "
+ RTE_LOG_DP(DEBUG, VHOST_DATA, "(%" PRIu64 ") TX: "
"MAC address is external\n", dev->device_fh);
/*Add packet to the port tx queue*/
@@ -903,7 +903,7 @@ virtio_dev_tx(struct virtio_net* dev, struct rte_mempool *mbuf_pool)
if (vq->last_used_idx == avail_idx)
return;
- RTE_LOG(DEBUG, VHOST_DATA, "(%" PRIu64 ") virtio_dev_tx()\n",
+ RTE_LOG_DP(DEBUG, VHOST_DATA, "(%" PRIu64 ") virtio_dev_tx()\n",
dev->device_fh);
/* Prefetch available ring to retrieve head indexes. */
@@ -913,7 +913,7 @@ virtio_dev_tx(struct virtio_net* dev, struct rte_mempool *mbuf_pool)
free_entries = avail_idx - vq->last_used_idx;
free_entries = unlikely(free_entries < MAX_PKT_BURST) ? free_entries : MAX_PKT_BURST;
- RTE_LOG(DEBUG, VHOST_DATA, "(%" PRIu64 ") Buffers available %d\n",
+ RTE_LOG_DP(DEBUG, VHOST_DATA, "(%" PRIu64 ") Buffers available %d\n",
dev->device_fh, free_entries);
/* Retrieve all of the head indexes first to avoid caching issues. */
for (i = 0; i < free_entries; i++)
@@ -1003,7 +1003,7 @@ switch_worker(__attribute__((unused)) void *arg)
if (unlikely(diff_tsc > drain_tsc)) {
if (tx_q->len) {
- RTE_LOG(DEBUG, VHOST_DATA,
+ RTE_LOG_DP(DEBUG, VHOST_DATA,
"TX queue drained after timeout with burst size %u\n",
tx_q->len);
diff --git a/lib/librte_eal/common/include/rte_log.h b/lib/librte_eal/common/include/rte_log.h
index 919563c..76b198f 100644
--- a/lib/librte_eal/common/include/rte_log.h
+++ b/lib/librte_eal/common/include/rte_log.h
@@ -121,9 +121,8 @@ int rte_openlog_stream(FILE *f);
/**
* Set the global log level.
*
- * After this call, all logs that are lower or equal than level and
- * lower or equal than the RTE_LOG_LEVEL configuration option will be
- * displayed.
+ * After this call, logs with a level lower or equal than the level
+ * passed as argument will be displayed.
*
* @param level
* Log level. A value between RTE_LOG_EMERG (1) and RTE_LOG_DEBUG (8).
@@ -187,9 +186,8 @@ int rte_log_cur_msg_logtype(void);
* The level argument determines if the log should be displayed or
* not, depending on the global rte_logs variable.
*
- * The preferred alternative is the RTE_LOG() function because debug logs may
- * be removed at compilation time if optimization is enabled. Moreover,
- * logs are automatically prefixed by type when using the macro.
+ * The preferred alternative is the RTE_LOG() because it adds the
+ * level and type in the logged string.
*
* @param level
* Log level. A value between RTE_LOG_EMERG (1) and RTE_LOG_DEBUG (8).
@@ -220,8 +218,8 @@ int rte_log(uint32_t level, uint32_t logtype, const char *format, ...)
* not, depending on the global rte_logs variable. A trailing
* newline may be added if needed.
*
- * The preferred alternative is the RTE_LOG() because debug logs may be
- * removed at compilation time.
+ * The preferred alternative is the RTE_LOG() because it adds the
+ * level and type in the logged string.
*
* @param level
* Log level. A value between RTE_LOG_EMERG (1) and RTE_LOG_DEBUG (8).
@@ -242,15 +240,8 @@ int rte_vlog(uint32_t level, uint32_t logtype, const char *format, va_list ap)
/**
* Generates a log message.
*
- * The RTE_LOG() is equivalent to rte_log() with two differences:
-
- * - RTE_LOG() can be used to remove debug logs at compilation time,
- * depending on RTE_LOG_LEVEL configuration option, and compilation
- * optimization level. If optimization is enabled, the tests
- * involving constants only are pre-computed. If compilation is done
- * with -O0, these tests will be done at run time.
- * - The log level and log type names are smaller, for example:
- * RTE_LOG(INFO, EAL, "this is a %s", "log");
+ * The RTE_LOG() is a helper that prefixes the string with the log level
+ * and type, and call rte_log().
*
* @param l
* Log level. A value between EMERG (1) and DEBUG (8). The short name is
@@ -266,6 +257,30 @@ int rte_vlog(uint32_t level, uint32_t logtype, const char *format, va_list ap)
* - Negative on error.
*/
#define RTE_LOG(l, t, ...) \
+ rte_log(RTE_LOG_ ## l, \
+ RTE_LOGTYPE_ ## t, # t ": " __VA_ARGS__)
+
+/**
+ * Generates a log message for data path.
+ *
+ * Similar to RTE_LOG(), except that it is removed at compilation time
+ * if the RTE_LOG_DP_LEVEL configuration option is lower than the log
+ * level argument.
+ *
+ * @param l
+ * Log level. A value between EMERG (1) and DEBUG (8). The short name is
+ * expanded by the macro, so it cannot be an integer value.
+ * @param t
+ * The log type, for example, EAL. The short name is expanded by the
+ * macro, so it cannot be an integer value.
+ * @param ...
+ * The fmt string, as in printf(3), followed by the variable arguments
+ * required by the format.
+ * @return
+ * - 0: Success.
+ * - Negative on error.
+ */
+#define RTE_LOG_DP(l, t, ...) \
(void)((RTE_LOG_ ## l <= RTE_LOG_LEVEL) ? \
rte_log(RTE_LOG_ ## l, \
RTE_LOGTYPE_ ## t, # t ": " __VA_ARGS__) : \
--
2.8.1
More information about the dev
mailing list