[v2,2/2] eal: add option to put timestamp on console output

Message ID 20230306181816.97243-3-stephen@networkplumber.org (mailing list archive)
State Superseded, archived
Delegated to: Thomas Monjalon
Headers
Series Add option to timestamp console log |

Checks

Context Check Description
ci/checkpatch success coding style OK
ci/loongarch-compilation success Compilation OK
ci/loongarch-unit-testing success Unit Testing PASS
ci/Intel-compilation fail Compilation issues
ci/intel-Testing success Testing PASS
ci/github-robot: build success github build: passed
ci/intel-Functional success Functional PASS
ci/iol-broadcom-Functional success Functional Testing PASS
ci/iol-mellanox-Performance success Performance Testing PASS
ci/iol-intel-Performance success Performance Testing PASS
ci/iol-broadcom-Performance success Performance Testing PASS
ci/iol-intel-Functional success Functional Testing PASS
ci/iol-aarch64-unit-testing success Testing PASS
ci/iol-x86_64-compile-testing fail Testing issues
ci/iol-aarch64-compile-testing success Testing PASS
ci/iol-testing success Testing PASS
ci/iol-x86_64-unit-testing success Testing PASS
ci/iol-abi-testing success Testing PASS

Commit Message

Stephen Hemminger March 6, 2023, 6:18 p.m. UTC
  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 was chosen to be the
same as the default Linux dmesg timestamp.

The messages are written using writev() which avoids unnecessary
buffering and ensures that if multiple threads are logging at
the same time that timestamp and message buffer don't get
interleaved.

Example:
[       0.000040] EAL: Probing VFIO support...

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 .../freebsd_gsg/freebsd_eal_parameters.rst    | 32 ++++++++++++++
 doc/guides/linux_gsg/linux_eal_parameters.rst |  5 +++
 lib/eal/common/eal_common_options.c           |  5 +++
 lib/eal/common/eal_internal_cfg.h             |  1 +
 lib/eal/common/eal_options.h                  |  2 +
 lib/eal/unix/eal_log.c                        | 42 +++++++++++++++++--
 6 files changed, 84 insertions(+), 3 deletions(-)
  

Patch

diff --git a/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst b/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst
index fba467a2ce92..99cff10e963c 100644
--- a/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst
+++ b/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst
@@ -18,3 +18,35 @@  FreeBSD-specific EAL parameters
 -------------------------------
 
 There are currently no FreeBSD-specific EAL command-line parameters available.
+
+Other options
+~~~~~~~~~~~~~
+
+*   ``--syslog <syslog facility>``
+
+    Set syslog facility. Valid syslog facilities are::
+
+        auth
+        cron
+        daemon
+        ftp
+        kern
+        lpr
+        mail
+        news
+        syslog
+        user
+        uucp
+        local0
+        local1
+        local2
+        local3
+        local4
+        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..2d3d8e82f7f3 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   },
@@ -1833,6 +1834,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: {
@@ -2194,6 +2198,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..33144c3619dd 100644
--- a/lib/eal/common/eal_internal_cfg.h
+++ b/lib/eal/common/eal_internal_cfg.h
@@ -85,6 +85,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/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/unix/eal_log.c b/lib/eal/unix/eal_log.c
index d44416fd6570..d8a900efedea 100644
--- a/lib/eal/unix/eal_log.c
+++ b/lib/eal/unix/eal_log.c
@@ -4,11 +4,17 @@ 
 
 #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"
+
+static struct timespec log_start_time;
 
 /*
  * default log function
@@ -16,11 +22,39 @@ 
 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 = fwrite(buf, 1, size, stderr);
-	fflush(stderr);
+	/* 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 -= 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;
+		}
+
+		/* use writev to put timestamp and buf in same 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 {
+		/* write on stderr */
+		ret = fwrite(buf, 1, size, stderr);
+		fflush(stderr);
+	}
 
 	/* Syslog error levels are from 0 to 7, so subtract 1 to convert */
 	syslog(rte_log_cur_msg_loglevel() - 1, "%.*s", (int)size, buf);
@@ -49,6 +83,8 @@  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;