From 5d8f0baf69ea1462c8cc32729c789f7278bf3dc2 Mon Sep 17 00:00:00 2001 From: Olivier Matz Date: Wed, 23 Nov 2016 16:34:25 +0100 Subject: [PATCH] log: do not drop debug logs at compile time 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 --- 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 | 51 ++++++++++++++++--------- 13 files changed, 68 insertions(+), 52 deletions(-) diff --git a/config/common_base b/config/common_base index 4bff83af7b..652a839c08 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 8d1ea6cc30..0adc549eed 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 8bf8fee312..0d15bb1e28 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 c6b1587448..de80b46a97 100644 --- a/drivers/net/nfp/nfp_net.c +++ b/drivers/net/nfp/nfp_net.c @@ -1707,7 +1707,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; } @@ -1720,7 +1720,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; } @@ -1740,7 +1740,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); @@ -1771,7 +1771,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 537cee1f7c..e7641d2c7f 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 ec5a2e627e..9715ea9bd5 100644 --- a/examples/ipsec-secgw/esp.c +++ b/examples/ipsec-secgw/esp.c @@ -78,7 +78,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 f49143b9f0..144f0aa891 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 3c88b86eca..d4dc7894eb 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 8ed021480e..9162e285ff 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 1d6d463563..bd1dc96ebe 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 0709859442..ac1f6e203c 100644 --- a/examples/vhost/main.c +++ b/examples/vhost/main.c @@ -832,17 +832,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; } @@ -867,7 +867,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; @@ -881,7 +881,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); @@ -973,7 +973,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: @@ -1041,7 +1041,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 f4dbaa486a..af05b00ccd 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 29f7d1922c..671e274141 100644 --- a/lib/librte_eal/common/include/rte_log.h +++ b/lib/librte_eal/common/include/rte_log.h @@ -118,9 +118,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). @@ -184,9 +183,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). @@ -217,8 +215,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). @@ -239,15 +237,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 @@ -263,7 +254,31 @@ int rte_vlog(uint32_t level, uint32_t logtype, const char *format, va_list ap) * - Negative on error. */ #define RTE_LOG(l, t, ...) \ - (void)((RTE_LOG_ ## l <= RTE_LOG_LEVEL) ? \ + 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_DP_LEVEL) ? \ rte_log(RTE_LOG_ ## l, \ RTE_LOGTYPE_ ## t, # t ": " __VA_ARGS__) : \ 0) -- 2.20.1