From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from proxy.6wind.com (host.76.145.23.62.rev.coltfrance.com [62.23.145.76]) by dpdk.org (Postfix) with ESMTP id A195DE6D for ; Fri, 16 Sep 2016 09:44:03 +0200 (CEST) Received: from glumotte.dev.6wind.com (unknown [10.16.0.195]) by proxy.6wind.com (Postfix) with ESMTP id 5F4DD251C9; Fri, 16 Sep 2016 09:44:03 +0200 (CEST) From: Olivier Matz To: dev@dpdk.org, david.marchand@6wind.com Date: Fri, 16 Sep 2016 09:43:52 +0200 Message-Id: <1474011832-29987-1-git-send-email-olivier.matz@6wind.com> X-Mailer: git-send-email 2.8.1 Subject: [dpdk-dev] [PATCH] log: do not drop debug logs at compile time X-BeenThere: dev@dpdk.org X-Mailman-Version: 2.1.15 Precedence: list List-Id: patches and discussions about DPDK List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 16 Sep 2016 07:44:03 -0000 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 | 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