[v7,5/5] eal: add option to put timestamp on console output

Message ID 20230705224805.286156-6-stephen@networkplumber.org (mailing list archive)
State Superseded, archived
Delegated to: Thomas Monjalon
Headers
Series Logging timetamp and related patches |

Checks

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

Commit Message

Stephen Hemminger July 5, 2023, 10:48 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 is chosen to look
like the default Linux dmesg timestamp.

The first few lines are not timestamped because the flag is stored
in internal configuration which is stored in shared memory
which is not setup up until a little later in startup process.

This logging skips the unnecessary step of going through stdio,
which makes it more robust against being called in interrupt
handlers etc.

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

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 app/test/test_eal_flags.c                     |  9 ++++
 .../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/unix/eal_log.c                        | 45 ++++++++++++++++---
 7 files changed, 70 insertions(+), 5 deletions(-)
  

Patch

diff --git a/app/test/test_eal_flags.c b/app/test/test_eal_flags.c
index d2b91e20750e..57637728d811 100644
--- a/app/test/test_eal_flags.c
+++ b/app/test/test_eal_flags.c
@@ -1055,6 +1055,10 @@  test_misc_flags(void)
 	const char * const argv22[] = {prgname, prefix, mp_flag,
 				       "--huge-worker-stack=512"};
 
+	/* Try running with --log-timestamp */
+	const char * const argv23[] = {prgname, prefix, mp_flag,
+				       "--log-timestamp" };
+
 	/* run all tests also applicable to FreeBSD first */
 
 	if (launch_proc(argv0) == 0) {
@@ -1162,6 +1166,11 @@  test_misc_flags(void)
 		printf("Error - process did not run ok with --huge-worker-stack=size parameter\n");
 		goto fail;
 	}
+	if (launch_proc(argv23) != 0) {
+		printf("Error - process did not run ok with --log-timestamp parameter\n");
+		goto fail;
+	}
+
 
 	rmdir(hugepath_dir3);
 	rmdir(hugepath_dir2);
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 005da4d12001..67fe6efb4526 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"=<facility> 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..ca502d5dd365 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.
 	 */
+	uint8_t log_timestamp;          /**< add timestamp to console output */
+	struct timespec log_start_time; /**< monotonic clock when started */
 	volatile int syslog_facility;	  /**< facility passed to openlog() */
+
 	/** 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 e66bcc68d07f..1ee94a5ee1e6 100644
--- a/lib/eal/unix/eal_log.c
+++ b/lib/eal/unix/eal_log.c
@@ -4,7 +4,10 @@ 
 
 #include <stdio.h>
 #include <sys/types.h>
+#include <sys/uio.h>
 #include <syslog.h>
+#include <time.h>
+#include <unistd.h>
 
 #include <rte_log.h>
 
@@ -16,13 +19,38 @@ 
  * default log function
  */
 static ssize_t
-console_log_write(__rte_unused void *c, const char *buf, size_t size)
+console_log_write(void *c, const char *buf, size_t size)
 {
+	const struct internal_config *internal_conf = c;
 	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 -= 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);
@@ -58,13 +86,20 @@  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;
 
 	/* has user has already setup a log stream */
 	if (eal_log_get_default())
 		return 0;
 
-	log_stream = fopencookie(NULL, "w+", console_log_func);
+	if (internal_conf->process_type == RTE_PROC_PRIMARY &&
+	    internal_conf->log_timestamp) {
+		if (clock_gettime(CLOCK_MONOTONIC, &internal_conf->log_start_time) < 0)
+			return -1;
+	}
+
+	log_stream = fopencookie(internal_conf, "w+", console_log_func);
 	if (log_stream == NULL)
 		return -1;