log: do not drop debug logs at compile time
authorOlivier Matz <olivier.matz@6wind.com>
Wed, 23 Nov 2016 15:34:25 +0000 (16:34 +0100)
committerThomas Monjalon <thomas.monjalon@6wind.com>
Thu, 1 Dec 2016 17:09:13 +0000 (18:09 +0100)
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@6wind.com>
13 files changed:
config/common_base
doc/guides/faq/faq.rst
drivers/net/bnxt/bnxt_txr.c
drivers/net/nfp/nfp_net.c
examples/distributor/main.c
examples/ipsec-secgw/esp.c
examples/ipsec-secgw/ipsec.c
examples/packet_ordering/main.c
examples/quota_watermark/qw/main.c
examples/tep_termination/main.c
examples/vhost/main.c
examples/vhost_xen/main.c
lib/librte_eal/common/include/rte_log.h

index 4bff83a..652a839 100644 (file)
@@ -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
index 8d1ea6c..0adc549 100644 (file)
@@ -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``.
 
 
index 8bf8fee..0d15bb1 100644 (file)
@@ -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);
index c6b1587..de80b46 100644 (file)
@@ -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"
index 537cee1..e7641d2 100644 (file)
@@ -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]);
index ec5a2e6..9715ea9 100644 (file)
@@ -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;
        }
index f49143b..144f0aa 100644 (file)
@@ -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);
index 3c88b86..d4dc789 100644 (file)
@@ -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;
index 8ed0214..9162e28 100644 (file)
@@ -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 */
index 1d6d463..bd1dc96 100644 (file)
@@ -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],
index 0709859..ac1f6e2 100644 (file)
@@ -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);
index f4dbaa4..af05b00 100644 (file)
@@ -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);
 
index 29f7d19..671e274 100644 (file)
@@ -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)