diff mbox series

[v10,08/10] eal: add option to put timestamp on console output

Message ID 20240321161146.340421-9-stephen@networkplumber.org (mailing list archive)
State Superseded, archived
Headers
Series Logging enhancements. |

Checks

Context Check Description
ci/Intel-compilation warning apply issues

Commit Message

Stephen Hemminger March 21, 2024, 4 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.

There are multiple timestamp formats similar to Linux dmesg.
The default is time relative since startup. Other alternatives
are delta, ctime, reltime and iso formats.

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

Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
---
 app/test/test_eal_flags.c           |  17 ++++
 doc/guides/prog_guide/log_lib.rst   |  10 ++
 lib/eal/common/eal_common_options.c |  14 ++-
 lib/eal/common/eal_options.h        |   2 +
 lib/log/log_internal.h              |   9 ++
 lib/log/log_unix.c                  | 152 +++++++++++++++++++++++++++-
 lib/log/log_windows.c               |   6 ++
 lib/log/version.map                 |   1 +
 8 files changed, 205 insertions(+), 6 deletions(-)

Comments

Tyler Retzlaff March 21, 2024, 5:11 p.m. UTC | #1 
On Thu, Mar 21, 2024 at 09:00:24AM -0700, Stephen Hemminger wrote:
> 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.
> 
> There are multiple timestamp formats similar to Linux dmesg.
> The default is time relative since startup. Other alternatives
> are delta, ctime, reltime and iso formats.
> 
> Example:
> $ dpdk-testpmd --log-timestamp -- -i
> EAL: Detected CPU lcores: 8
> EAL: Detected NUMA nodes: 1
> [     0.000083] EAL: Detected static linkage of DPDK
> [     0.002000] EAL: Multi-process socket /var/run/dpdk/rte/mp_socket
> [     0.003507] EAL: Selected IOVA mode 'VA'
> [     0.006272] testpmd: No probed ethernet devices
> Interactive-mode selected
> [     0.029567] testpmd: create a new mbuf pool <mb_pool_0>: n=203456, size=2176, socket=0
> [     0.029588] testpmd: preferred mempool ops selected: ring_mp_mc
> 
> Signed-off-by: Stephen Hemminger <stephen@networkplumber.org>
> ---
>  app/test/test_eal_flags.c           |  17 ++++
>  doc/guides/prog_guide/log_lib.rst   |  10 ++
>  lib/eal/common/eal_common_options.c |  14 ++-
>  lib/eal/common/eal_options.h        |   2 +
>  lib/log/log_internal.h              |   9 ++
>  lib/log/log_unix.c                  | 152 +++++++++++++++++++++++++++-
>  lib/log/log_windows.c               |   6 ++
>  lib/log/version.map                 |   1 +
>  8 files changed, 205 insertions(+), 6 deletions(-)
> 
> diff --git a/app/test/test_eal_flags.c b/app/test/test_eal_flags.c
> index 6cb4b0675730..eeb1799381d7 100644
> --- a/app/test/test_eal_flags.c
> +++ b/app/test/test_eal_flags.c
> @@ -1055,6 +1055,14 @@ 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" };
> +
> +	/* Try running with --log-timestamp=iso */
> +	const char * const argv24[] = {prgname, prefix, mp_flag,
> +				       "--log-timestamp=iso" };
> +
>  	/* run all tests also applicable to FreeBSD first */
>  
>  	if (launch_proc(argv0) == 0) {
> @@ -1162,6 +1170,15 @@ 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;
> +	}
> +	if (launch_proc(argv24) != 0) {
> +		printf("Error - process did not run ok with --log-timestamp=iso parameter\n");
> +		goto fail;
> +	}
> +
>  
>  	rmdir(hugepath_dir3);
>  	rmdir(hugepath_dir2);
> diff --git a/doc/guides/prog_guide/log_lib.rst b/doc/guides/prog_guide/log_lib.rst
> index aacb36c36ce0..1d6b2e3cea5d 100644
> --- a/doc/guides/prog_guide/log_lib.rst
> +++ b/doc/guides/prog_guide/log_lib.rst
> @@ -73,6 +73,16 @@ For example::
>  	/path/to/app --syslog local0
>  
>  
> +Console timestamp
> +~~~~~~~~~~~~~~~~~
> +
> +On Linux and FreeBSD, an optional timestamp can be added before each
> +message by adding the ``--log-timestamp`` option.

i don't think Windows should be excluded from the feature, in general
core libraries that get features should cover all platforms.
Stephen Hemminger March 21, 2024, 5:16 p.m. UTC | #2 
On Thu, 21 Mar 2024 10:11:31 -0700
Tyler Retzlaff <roretzla@linux.microsoft.com> wrote:

> >  
> >  
> > +Console timestamp
> > +~~~~~~~~~~~~~~~~~
> > +
> > +On Linux and FreeBSD, an optional timestamp can be added before each
> > +message by adding the ``--log-timestamp`` option.  
> 
> i don't think Windows should be excluded from the feature, in general
> core libraries that get features should cover all platforms.

The problem is that current Linux/FreeBSD log code depends on fopencookie()
to work. I could not find a way to do that on Windows.
Tyler Retzlaff March 21, 2024, 5:49 p.m. UTC | #3 
On Thu, Mar 21, 2024 at 10:16:36AM -0700, Stephen Hemminger wrote:
> On Thu, 21 Mar 2024 10:11:31 -0700
> Tyler Retzlaff <roretzla@linux.microsoft.com> wrote:
> 
> > >  
> > >  
> > > +Console timestamp
> > > +~~~~~~~~~~~~~~~~~
> > > +
> > > +On Linux and FreeBSD, an optional timestamp can be added before each
> > > +message by adding the ``--log-timestamp`` option.  
> > 
> > i don't think Windows should be excluded from the feature, in general
> > core libraries that get features should cover all platforms.
> 
> The problem is that current Linux/FreeBSD log code depends on fopencookie()
> to work. I could not find a way to do that on Windows.

but that looks like it is part of general log initialization. surely
when we are talking about logging a timestamp to a console we're just
talking about a standard stream and a format string for Windows?

i'll try to study more to gain a better understanding.

thanks
Stephen Hemminger March 22, 2024, 12:30 a.m. UTC | #4 
On Thu, 21 Mar 2024 10:49:06 -0700
Tyler Retzlaff <roretzla@linux.microsoft.com> wrote:

> On Thu, Mar 21, 2024 at 10:16:36AM -0700, Stephen Hemminger wrote:
> > On Thu, 21 Mar 2024 10:11:31 -0700
> > Tyler Retzlaff <roretzla@linux.microsoft.com> wrote:
> >   
> > > >  
> > > >  
> > > > +Console timestamp
> > > > +~~~~~~~~~~~~~~~~~
> > > > +
> > > > +On Linux and FreeBSD, an optional timestamp can be added before each
> > > > +message by adding the ``--log-timestamp`` option.    
> > > 
> > > i don't think Windows should be excluded from the feature, in general
> > > core libraries that get features should cover all platforms.  
> > 
> > The problem is that current Linux/FreeBSD log code depends on fopencookie()
> > to work. I could not find a way to do that on Windows.  
> 
> but that looks like it is part of general log initialization. surely
> when we are talking about logging a timestamp to a console we're just
> talking about a standard stream and a format string for Windows?
> 
> i'll try to study more to gain a better understanding.
> 
> thanks

What the code does is take what rte_log created and add more data before
actual printing it. The other option is doing this at rte_log() but
that will break the syslog side.

I am not sure that having log go directly to syslog makes sense anyway
on a modern Linux system. If DPDK is being used by a daemon, that daemon
will be a systemd service. And systemd has simple way to make stderr go
to syslog.  So if we drop the syslog support, then the whole thing gets
more generic and simpler.
diff mbox series

Patch

diff --git a/app/test/test_eal_flags.c b/app/test/test_eal_flags.c
index 6cb4b0675730..eeb1799381d7 100644
--- a/app/test/test_eal_flags.c
+++ b/app/test/test_eal_flags.c
@@ -1055,6 +1055,14 @@  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" };
+
+	/* Try running with --log-timestamp=iso */
+	const char * const argv24[] = {prgname, prefix, mp_flag,
+				       "--log-timestamp=iso" };
+
 	/* run all tests also applicable to FreeBSD first */
 
 	if (launch_proc(argv0) == 0) {
@@ -1162,6 +1170,15 @@  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;
+	}
+	if (launch_proc(argv24) != 0) {
+		printf("Error - process did not run ok with --log-timestamp=iso parameter\n");
+		goto fail;
+	}
+
 
 	rmdir(hugepath_dir3);
 	rmdir(hugepath_dir2);
diff --git a/doc/guides/prog_guide/log_lib.rst b/doc/guides/prog_guide/log_lib.rst
index aacb36c36ce0..1d6b2e3cea5d 100644
--- a/doc/guides/prog_guide/log_lib.rst
+++ b/doc/guides/prog_guide/log_lib.rst
@@ -73,6 +73,16 @@  For example::
 	/path/to/app --syslog local0
 
 
+Console timestamp
+~~~~~~~~~~~~~~~~~
+
+On Linux and FreeBSD, an optional timestamp can be added before each
+message by adding the ``--log-timestamp`` option.
+For example::
+
+	/path/to/app --log-level=lib.*:debug --log-timestamp
+
+
 Using Logging APIs to Generate Log Messages
 -------------------------------------------
 
diff --git a/lib/eal/common/eal_common_options.c b/lib/eal/common/eal_common_options.c
index 7310d10dfd78..4e2c3d0f255c 100644
--- a/lib/eal/common/eal_common_options.c
+++ b/lib/eal/common/eal_common_options.c
@@ -77,6 +77,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,     2, 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   },
@@ -1663,6 +1664,7 @@  eal_log_level_parse(int argc, char * const argv[])
 
 		switch (opt) {
 		case OPT_LOG_LEVEL_NUM:
+		case OPT_LOG_TIMESTAMP_NUM:
 			if (eal_parse_common_option(opt, optarg, internal_conf) < 0)
 				return -1;
 			break;
@@ -1890,7 +1892,7 @@  eal_parse_common_option(int opt, const char *optarg,
 		break;
 #endif
 
-	case OPT_LOG_LEVEL_NUM: {
+	case OPT_LOG_LEVEL_NUM:
 		if (eal_parse_log_level(optarg) < 0) {
 			EAL_LOG(ERR,
 				"invalid parameters for --"
@@ -1898,9 +1900,16 @@  eal_parse_common_option(int opt, const char *optarg,
 			return -1;
 		}
 		break;
-	}
 
 #ifndef RTE_EXEC_ENV_WINDOWS
+	case OPT_LOG_TIMESTAMP_NUM:
+		if (eal_log_timestamp(optarg) < 0) {
+			EAL_LOG(ERR, "invalid parameters for --"
+				OPT_LOG_TIMESTAMP);
+			return -1;
+		}
+		break;
+
 	case OPT_TRACE_NUM: {
 		if (eal_trace_args_save(optarg) < 0) {
 			EAL_LOG(ERR, "invalid parameters for --"
@@ -2261,6 +2270,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_options.h b/lib/eal/common/eal_options.h
index f3f2e104f6d7..e24c9eca53ca 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/log/log_internal.h b/lib/log/log_internal.h
index c77e687e28bc..0e18d147cf98 100644
--- a/lib/log/log_internal.h
+++ b/lib/log/log_internal.h
@@ -5,8 +5,10 @@ 
 #ifndef LOG_INTERNAL_H
 #define LOG_INTERNAL_H
 
+#include <stdbool.h>
 #include <stdio.h>
 #include <stdint.h>
+#include <time.h>
 
 #include <rte_compat.h>
 
@@ -44,4 +46,11 @@  const char *eal_log_level2str(uint32_t level);
 __rte_internal
 void rte_eal_log_cleanup(void);
 
+/*
+ * Add timestamp to console logs
+ */
+__rte_internal
+int eal_log_timestamp(const char *fmt);
+
+
 #endif /* LOG_INTERNAL_H */
diff --git a/lib/log/log_unix.c b/lib/log/log_unix.c
index c56f80ac6967..cb8f17bc83ef 100644
--- a/lib/log/log_unix.c
+++ b/lib/log/log_unix.c
@@ -2,28 +2,169 @@ 
  * Copyright(c) 2010-2014 Intel Corporation
  */
 
+#include <stdbool.h>
 #include <stdio.h>
+#include <string.h>
 #include <sys/types.h>
+#include <sys/uio.h>
 #include <syslog.h>
+#include <time.h>
+#include <unistd.h>
 
 #include <rte_log.h>
 
 #include "log_internal.h"
 
+enum eal_log_time_format {
+	EAL_LOG_TIMESTAMP_NONE = 0,
+	EAL_LOG_TIMESTAMP_TIME,		/* time since start */
+	EAL_LOG_TIMESTAMP_DELTA,	/* time since last message */
+	EAL_LOG_TIMESTAMP_RELTIME,
+	EAL_LOG_TIMESTAMP_CTIME,
+	EAL_LOG_TIMESTAMP_ISO,
+};
+
+static struct {
+	enum eal_log_time_format time_format;
+	struct timespec start_time;
+	struct timespec last_time;
+	struct tm last_tm;
+} log = {
+	.time_format = EAL_LOG_TIMESTAMP_NONE,
+};
+
+int
+eal_log_timestamp(const char *str)
+{
+	if (str == NULL)
+		log.time_format = EAL_LOG_TIMESTAMP_TIME;
+	else if (strcmp(str, "notime") == 0)
+		log.time_format = EAL_LOG_TIMESTAMP_NONE;
+	else if (strcmp(str, "reltime") == 0)
+		log.time_format = EAL_LOG_TIMESTAMP_RELTIME;
+	else if (strcmp(str, "delta") == 0)
+		log.time_format = EAL_LOG_TIMESTAMP_DELTA;
+	else if (strcmp(str, "ctime") == 0)
+		log.time_format =  EAL_LOG_TIMESTAMP_CTIME;
+	else if (strcmp(str, "iso") == 0)
+		log.time_format = EAL_LOG_TIMESTAMP_ISO;
+	else
+		return -1;
+
+	return 0;
+}
+
+static struct timespec
+timespec_sub(const struct timespec *t0, const struct timespec *t1)
+{
+	struct timespec ts;
+
+	ts.tv_sec = t0->tv_sec - t1->tv_sec;
+	ts.tv_nsec = t0->tv_nsec - t1->tv_nsec;
+	if (ts.tv_nsec < 0) {
+		ts.tv_sec--;
+		ts.tv_nsec += 1000000000L;
+	}
+	return ts;
+}
+
+static ssize_t
+console_log_timestamp(char *tsbuf, size_t tsbuflen)
+{
+	struct timespec now, ts;
+	struct tm *tm, cur;
+
+	switch (log.time_format) {
+	case EAL_LOG_TIMESTAMP_NONE:
+		return 0;
+
+	case EAL_LOG_TIMESTAMP_TIME:
+		if (clock_gettime(CLOCK_MONOTONIC, &now) < 0)
+			return 0;
+
+		ts = timespec_sub(&now, &log.start_time);
+
+		return snprintf(tsbuf, tsbuflen, "%6lu.%06lu",
+				ts.tv_sec, ts.tv_nsec / 1000u);
+
+	case EAL_LOG_TIMESTAMP_DELTA:
+		if (clock_gettime(CLOCK_MONOTONIC, &now) < 0)
+			return 0;
+
+		ts = timespec_sub(&now, &log.last_time);
+		log.last_time = now;
+
+		return snprintf(tsbuf, tsbuflen, "<%6lu.%06lu>",
+				ts.tv_sec, ts.tv_nsec / 1000u);
+
+	case EAL_LOG_TIMESTAMP_RELTIME:
+		if (clock_gettime(CLOCK_REALTIME, &now) < 0)
+			return 0;
+
+		tm = localtime_r(&now.tv_sec, &cur);
+		ts = timespec_sub(&now, &log.last_time);
+		log.last_time = now;
+
+		/* if minute, day, hour hasn't changed then print delta */
+		if (cur.tm_min != log.last_tm.tm_min ||
+		    cur.tm_hour != log.last_tm.tm_hour ||
+		    cur.tm_yday != log.last_tm.tm_yday) {
+			log.last_tm = cur;
+			return strftime(tsbuf, tsbuflen, "%b%e %H:%M", tm);
+		} else {
+			return snprintf(tsbuf, tsbuflen, "+%4lu.%06lu",
+					ts.tv_sec, ts.tv_nsec / 1000u);
+		}
+
+	case EAL_LOG_TIMESTAMP_CTIME: {
+		char cbuf[32]; /* "Wed Jun 30 21:49:08 1993\n" */
+
+		if (clock_gettime(CLOCK_REALTIME, &now) < 0)
+			return 0;
+
+		/* .24s is to remove newline from ctime result */
+		return snprintf(tsbuf, tsbuflen, "%.24s",
+				ctime_r(&now.tv_sec, cbuf));
+	}
+
+	case EAL_LOG_TIMESTAMP_ISO: {
+		char dbuf[64]; /* "2024-05-01T22:11:00" */
+		if (clock_gettime(CLOCK_REALTIME, &now) < 0)
+			return 0;
+		tm = localtime_r(&now.tv_sec, &cur);
+
+		/* make "2024-05-01T22:11:00,123456+0100" */
+		if (strftime(dbuf, sizeof(dbuf), "%Y-%m-%dT%H:%M:%S", tm) == 0)
+			return 0;
+
+		return snprintf(tsbuf, tsbuflen, "%s,%06lu%+03ld:%02ld", dbuf,
+				now.tv_nsec / 1000u,
+				tm->tm_gmtoff / 3600,
+				(tm->tm_gmtoff / 60) % 60);
+	}
+	}
+
+	return 0;
+}
+
 /*
  * default log function
  */
 static ssize_t
-console_log_write(__rte_unused void *c, const char *buf, size_t size)
+console_log_write(__rte_unused void *c, const char *msg, size_t size)
 {
+	char buf[128];
 	ssize_t ret;
 
-	/* write on stderr */
-	ret = fwrite(buf, 1, size, stderr);
+	ret = console_log_timestamp(buf, sizeof(buf));
+	if (ret == 0)
+		ret = fwrite(msg, 1, size, stderr);
+	else
+		ret = fprintf(stderr, "[%s] %.*s", buf, (int)size, msg);
 	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);
+	syslog(rte_log_cur_msg_loglevel() - 1, "%.*s", (int)size, msg);
 
 	return ret;
 }
@@ -49,6 +190,9 @@  eal_log_init(const char *id, int facility)
 {
 	FILE *log_stream;
 
+	clock_gettime(CLOCK_MONOTONIC, &log.start_time);
+	log.last_time = log.start_time;
+
 	/* skip if user has already setup a log stream */
 	if (eal_log_get_default())
 		return 0;
diff --git a/lib/log/log_windows.c b/lib/log/log_windows.c
index a6a08895501e..8aa68a181bec 100644
--- a/lib/log/log_windows.c
+++ b/lib/log/log_windows.c
@@ -6,6 +6,12 @@ 
 #include <rte_log.h>
 #include "log_internal.h"
 
+int
+eal_log_timestamp(__rte_unused const char *fmt)
+{
+	return -1; /* not implemented */
+}
+
 /* set the log to default function, called during eal init process. */
 int
 eal_log_init(__rte_unused const char *id, __rte_unused int facility)
diff --git a/lib/log/version.map b/lib/log/version.map
index 6ecc656d1d65..697cdb3cb1b2 100644
--- a/lib/log/version.map
+++ b/lib/log/version.map
@@ -31,5 +31,6 @@  INTERNAL {
 	eal_log_save_pattern;
 	eal_log_save_regexp;
 	eal_log_set_default;
+	eal_log_timestamp;
 	rte_eal_log_cleanup;
 };