When debugging driver or startup issues, it is useful to have
a timestamp on each message printed. The messages in syslog
already have a timestamp, but often syslog is not available
during testing. The timestamp format is chosen to look
like the default Linux dmesg timestamp.

Example:
$ dpdk-testpmd --log-timestamp -- -i
[       0.007615] EAL: Detected CPU lcores: 16
[       0.007657] EAL: Detected NUMA nodes: 1
[       0.007878] EAL: Detected static linkage of DPDK
[       0.009469] EAL: Multi-process socket /var/run/dpdk/rte/mp_socket
[       0.012175] EAL: Selected IOVA mode 'VA'
[       0.120016] testpmd: No probed ethernet devices
Interactive-mode selected
[       0.155959] testpmd: create a new mbuf pool <mb_pool_0>: n=267456, 
size=2176, socket=0
[       0.155990] testpmd: preferred mempool ops selected: ring_mp_mc

Signed-off-by: Stephen Hemminger <step...@networkplumber.org>
---
 .../freebsd_gsg/freebsd_eal_parameters.rst    |  5 +++
 doc/guides/linux_gsg/linux_eal_parameters.rst |  5 +++
 lib/eal/common/eal_common_options.c           |  6 ++++
 lib/eal/common/eal_internal_cfg.h             |  3 ++
 lib/eal/common/eal_options.h                  |  2 ++
 lib/eal/freebsd/eal.c                         |  4 ++-
 lib/eal/linux/eal.c                           |  4 ++-
 lib/eal/unix/eal_log.c                        | 36 +++++++++++++++++--
 8 files changed, 61 insertions(+), 4 deletions(-)

diff --git a/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst 
b/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst
index 9270d9fa3bfc..99cff10e963c 100644
--- a/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst
+++ b/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst
@@ -45,3 +45,8 @@ Other options
         local5
         local6
         local7
+
+*   ``--log-timestamp``
+
+    Add a timestamp of seconds and microseconds to each log message
+    written to standard output.
diff --git a/doc/guides/linux_gsg/linux_eal_parameters.rst 
b/doc/guides/linux_gsg/linux_eal_parameters.rst
index ea8f38139119..719ca6851625 100644
--- a/doc/guides/linux_gsg/linux_eal_parameters.rst
+++ b/doc/guides/linux_gsg/linux_eal_parameters.rst
@@ -135,3 +135,8 @@ Other options
         local5
         local6
         local7
+
+*   ``--log-timestamp``
+
+    Add a timestamp of seconds and microseconds to each log message
+    written to standard output.
diff --git a/lib/eal/common/eal_common_options.c 
b/lib/eal/common/eal_common_options.c
index 03059336987d..c6c74cc31e9c 100644
--- a/lib/eal/common/eal_common_options.c
+++ b/lib/eal/common/eal_common_options.c
@@ -76,6 +76,7 @@ eal_long_options[] = {
        {OPT_IOVA_MODE,         1, NULL, OPT_IOVA_MODE_NUM        },
        {OPT_LCORES,            1, NULL, OPT_LCORES_NUM           },
        {OPT_LOG_LEVEL,         1, NULL, OPT_LOG_LEVEL_NUM        },
+       {OPT_LOG_TIMESTAMP,     0, NULL, OPT_LOG_TIMESTAMP_NUM    },
        {OPT_TRACE,             1, NULL, OPT_TRACE_NUM            },
        {OPT_TRACE_DIR,         1, NULL, OPT_TRACE_DIR_NUM        },
        {OPT_TRACE_BUF_SIZE,    1, NULL, OPT_TRACE_BUF_SIZE_NUM   },
@@ -1835,6 +1836,10 @@ eal_parse_common_option(int opt, const char *optarg,
        }
 
 #ifndef RTE_EXEC_ENV_WINDOWS
+       case OPT_LOG_TIMESTAMP_NUM:
+               conf->log_timestamp = 1;
+               break;
+
        case OPT_TRACE_NUM: {
                if (eal_trace_args_save(optarg) < 0) {
                        RTE_LOG(ERR, EAL, "invalid parameters for --"
@@ -2194,6 +2199,7 @@ eal_common_usage(void)
               "  --"OPT_PROC_TYPE"         Type of this process 
(primary|secondary|auto)\n"
 #ifndef RTE_EXEC_ENV_WINDOWS
               "  --"OPT_SYSLOG"            Set syslog facility\n"
+              "  --"OPT_LOG_TIMESTAMP"     Timestamp log output\n"
 #endif
               "  --"OPT_LOG_LEVEL"=<level> Set global log level\n"
               "  --"OPT_LOG_LEVEL"=<type-match>:<level>\n"
diff --git a/lib/eal/common/eal_internal_cfg.h 
b/lib/eal/common/eal_internal_cfg.h
index 167ec501fa79..1a1a7fdcfa8c 100644
--- a/lib/eal/common/eal_internal_cfg.h
+++ b/lib/eal/common/eal_internal_cfg.h
@@ -84,7 +84,10 @@ struct internal_config {
        /**< true if storing all pages within single files (per-page-size,
         * per-node) non-legacy mode only.
         */
+       volatile uint8_t log_timestamp;   /**< add timestamp to console output 
*/
        volatile int syslog_facility;     /**< facility passed to openlog() */
+       struct timespec log_start_time;   /**< when logging was started */
+
        /** default interrupt mode for VFIO */
        volatile enum rte_intr_mode vfio_intr_mode;
        /** the shared VF token for VFIO-PCI bound PF and VFs devices */
diff --git a/lib/eal/common/eal_options.h b/lib/eal/common/eal_options.h
index 3cc9cb641284..cc9723868e3c 100644
--- a/lib/eal/common/eal_options.h
+++ b/lib/eal/common/eal_options.h
@@ -35,6 +35,8 @@ enum {
        OPT_LCORES_NUM,
 #define OPT_LOG_LEVEL         "log-level"
        OPT_LOG_LEVEL_NUM,
+#define OPT_LOG_TIMESTAMP     "log-timestamp"
+       OPT_LOG_TIMESTAMP_NUM,
 #define OPT_TRACE             "trace"
        OPT_TRACE_NUM,
 #define OPT_TRACE_DIR         "trace-dir"
diff --git a/lib/eal/freebsd/eal.c b/lib/eal/freebsd/eal.c
index d3aac3d628a8..5c7cea8809bd 100644
--- a/lib/eal/freebsd/eal.c
+++ b/lib/eal/freebsd/eal.c
@@ -388,6 +388,7 @@ eal_log_level_parse(int argc, char **argv)
 
                switch (opt) {
                case OPT_SYSLOG_NUM:            /* fallthrough */
+               case OPT_LOG_TIMESTAMP_NUM:     /* fallthrough */
                case OPT_LOG_LEVEL_NUM:
                        if (eal_parse_common_option(opt, optarg, internal_conf) 
< 0)
                                goto error;
@@ -436,7 +437,8 @@ eal_parse_args(int argc, char **argv)
                }
 
                /* eal_log_level_parse() already handled these */
-               if (opt == OPT_LOG_LEVEL_NUM || opt == OPT_SYSLOG_NUM)
+               if (opt == OPT_SYSLOG_NUM ||
+                   opt == OPT_LOG_TIMESTAMP_NUM || opt == OPT_LOG_LEVEL_NUM)
                        continue;
 
                ret = eal_parse_common_option(opt, optarg, internal_conf);
diff --git a/lib/eal/linux/eal.c b/lib/eal/linux/eal.c
index 51c4ec75d57b..051f9ad7f5bf 100644
--- a/lib/eal/linux/eal.c
+++ b/lib/eal/linux/eal.c
@@ -568,6 +568,7 @@ eal_log_level_parse(int argc, char **argv)
 
                switch (opt) {
                case OPT_SYSLOG_NUM:            /* fallthrough */
+               case OPT_LOG_TIMESTAMP_NUM:     /* fallthrough */
                case OPT_LOG_LEVEL_NUM:
                        if (eal_parse_common_option(opt, optarg, internal_conf) 
< 0)
                                goto error;
@@ -650,7 +651,8 @@ eal_parse_args(int argc, char **argv)
                }
 
                /* eal_log_level_parse() already handled these */
-               if (opt == OPT_LOG_LEVEL_NUM || opt == OPT_SYSLOG_NUM)
+               if (opt == OPT_SYSLOG_NUM ||
+                   opt == OPT_LOG_TIMESTAMP_NUM || opt == OPT_LOG_LEVEL_NUM)
                        continue;
 
                ret = eal_parse_common_option(opt, optarg, internal_conf);
diff --git a/lib/eal/unix/eal_log.c b/lib/eal/unix/eal_log.c
index baa721021991..f65a22612310 100644
--- a/lib/eal/unix/eal_log.c
+++ b/lib/eal/unix/eal_log.c
@@ -4,12 +4,15 @@
 
 #include <stdio.h>
 #include <sys/types.h>
+#include <sys/uio.h>
 #include <syslog.h>
+#include <time.h>
 #include <unistd.h>
 
 #include <rte_log.h>
 
 #include "eal_log.h"
+#include "eal_private.h"
 
 /*
  * default log function
@@ -17,10 +20,36 @@
 static ssize_t
 console_log_write(__rte_unused void *c, const char *buf, size_t size)
 {
+       const struct internal_config *internal_conf = 
eal_get_internal_configuration();
        ssize_t ret;
 
-       /* write on stderr */
-       ret = write(STDERR_FILENO, buf, size);
+       /* add optional timestamp for stderr */
+       if (internal_conf->log_timestamp) {
+               struct iovec iov[2];
+               struct timespec ts;
+               char tbuf[64];
+
+               /* format up monotonic timestamp */
+               clock_gettime(CLOCK_MONOTONIC, &ts);
+               ts.tv_sec -= internal_conf->log_start_time.tv_sec;
+               ts.tv_nsec -= internal_conf->log_start_time.tv_nsec;
+               if (ts.tv_nsec < 0) {
+                       --ts.tv_sec;
+                       ts.tv_nsec += 1000000000ul;
+               }
+
+               /* use writev to put timestamp and buf in single operation */
+               iov[0].iov_base = tbuf;
+               iov[0].iov_len  = snprintf(tbuf, sizeof(tbuf), "[%8lu.%06lu] ",
+                                          ts.tv_sec, ts.tv_nsec / 1000u);
+
+               /* casts are to unconstify the buf */
+               iov[1].iov_base = (void *)(uintptr_t)buf;
+               iov[1].iov_len = size;
+               ret = writev(STDERR_FILENO, iov, 2);
+       } else {
+               ret = write(STDERR_FILENO, buf, size);
+       }
 
        /* Syslog error levels are from 0 to 7, so subtract 1 to convert */
        syslog(rte_log_cur_msg_loglevel() - 1, "%.*s", (int)size, buf);
@@ -47,8 +76,11 @@ static cookie_io_functions_t console_log_func = {
 int
 eal_log_init(const char *id, int facility)
 {
+       struct internal_config *internal_conf = 
eal_get_internal_configuration();
        FILE *log_stream;
 
+       clock_gettime(CLOCK_MONOTONIC, &internal_conf->log_start_time);
+
        log_stream = fopencookie(NULL, "w+", console_log_func);
        if (log_stream == NULL)
                return -1;
-- 
2.39.2

Reply via email to