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:
[ 0.000040] EAL: Probing VFIO support...
Signed-off-by: Stephen Hemminger <step...@networkplumber.org>
---
doc/guides/linux_gsg/linux_eal_parameters.rst | 5 +++
lib/librte_eal/common/eal_common_options.c | 5 +++
lib/librte_eal/common/eal_internal_cfg.h | 1 +
lib/librte_eal/common/eal_options.h | 2 +
lib/librte_eal/linux/eal_log.c | 41 +++++++++++++++++--
5 files changed, 51 insertions(+), 3 deletions(-)
diff --git a/doc/guides/linux_gsg/linux_eal_parameters.rst
b/doc/guides/linux_gsg/linux_eal_parameters.rst
index bd3977cb3d91..9336046c63a9 100644
--- a/doc/guides/linux_gsg/linux_eal_parameters.rst
+++ b/doc/guides/linux_gsg/linux_eal_parameters.rst
@@ -118,3 +118,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/librte_eal/common/eal_common_options.c
b/lib/librte_eal/common/eal_common_options.c
index a5426e12346a..240610770ee1 100644
--- a/lib/librte_eal/common/eal_common_options.c
+++ b/lib/librte_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 },
@@ -1626,6 +1627,9 @@ eal_parse_common_option(int opt, const char *optarg,
}
break;
}
+ case OPT_LOG_TIMESTAMP_NUM:
+ conf->log_timestamp = 1;
+ break;
#ifndef RTE_EXEC_ENV_WINDOWS
case OPT_TRACE_NUM: {
@@ -1945,6 +1949,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"=<int> Set global log level\n"
" --"OPT_LOG_LEVEL"=<type-match>:<int>\n"
diff --git a/lib/librte_eal/common/eal_internal_cfg.h
b/lib/librte_eal/common/eal_internal_cfg.h
index 13f93388a781..75c476870c57 100644
--- a/lib/librte_eal/common/eal_internal_cfg.h
+++ b/lib/librte_eal/common/eal_internal_cfg.h
@@ -70,6 +70,7 @@ struct internal_config {
* per-node) non-legacy mode only.
*/
volatile int syslog_facility; /**< facility passed to openlog() */
+ volatile uint8_t log_timestamp; /**< add timestamp to console output
*/
/** 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/librte_eal/common/eal_options.h
b/lib/librte_eal/common/eal_options.h
index 89769d48b487..7c86f2e19109 100644
--- a/lib/librte_eal/common/eal_options.h
+++ b/lib/librte_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/librte_eal/linux/eal_log.c b/lib/librte_eal/linux/eal_log.c
index 43c8460bfb07..cbd0924ec847 100644
--- a/lib/librte_eal/linux/eal_log.c
+++ b/lib/librte_eal/linux/eal_log.c
@@ -5,9 +5,12 @@
#include <string.h>
#include <stdio.h>
#include <stdint.h>
+#include <unistd.h>
+#include <time.h>
#include <sys/types.h>
#include <syslog.h>
#include <sys/queue.h>
+#include <sys/uio.h>
#include <rte_memory.h>
#include <rte_eal.h>
@@ -18,6 +21,9 @@
#include <rte_log.h>
#include "eal_private.h"
+#include "eal_internal_cfg.h"
+
+static struct timespec log_start_time;
/*
* default log function
@@ -25,11 +31,38 @@
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;
+ char tbuf[64];
+ struct iovec iov[2];
+
+ if (internal_conf->log_timestamp) {
+ struct timespec ts;
+
+ /* format up monotonic timestamp */
+ clock_gettime(CLOCK_MONOTONIC, &ts);
+ ts.tv_sec -= log_start_time.tv_sec;
+ ts.tv_nsec -= log_start_time.tv_nsec;
+ if (ts.tv_nsec < 0) {
+ --ts.tv_sec;
+ ts.tv_nsec += 1000000000ul;
+ }
- /* write on stdout */
- ret = fwrite(buf, 1, size, stdout);
- fflush(stdout);
+ iov[0].iov_base = tbuf;
+ iov[0].iov_len = snprintf(tbuf, sizeof(tbuf), "[%8lu.%06lu] ",
+ ts.tv_sec, ts.tv_nsec / 1000u);
+
+ /* extra cast is workaround to remove const quallifier */
+ iov[1].iov_base = (void *)(uintptr_t)buf;
+ iov[1].iov_len = size;
+
+ fflush(stdout);
+ ret = writev(STDOUT_FILENO, iov, 2);
+ } else {
+ /* write on stdout */
+ ret = fwrite(buf, 1, size, stdout);
+ }
/* Syslog error levels are from 0 to 7, so subtract 1 to convert */
syslog(rte_log_cur_msg_loglevel() - 1, "%.*s", (int)size, buf);
@@ -50,6 +83,8 @@ rte_eal_log_init(const char *id, int facility)
{
FILE *log_stream;
+ clock_gettime(CLOCK_MONOTONIC, &log_start_time);
+
log_stream = fopencookie(NULL, "w+", console_log_func);
if (log_stream == NULL)
return -1;
--
2.27.0
