eal: add option to put timestamp on console output
diff mbox series

Message ID 20200814173441.23086-1-stephen@networkplumber.org
State Deferred
Delegated to: Thomas Monjalon
Headers show
Series
  • eal: add option to put timestamp on console output
Related show

Checks

Context Check Description
ci/Intel-compilation success Compilation OK
ci/iol-mellanox-Performance success Performance Testing PASS
ci/iol-testing success Testing PASS
ci/iol-intel-Performance success Performance Testing PASS
ci/checkpatch success coding style OK

Commit Message

Stephen Hemminger Aug. 14, 2020, 5:34 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.

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

Signed-off-by: Stephen Hemminger <stephen@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(-)

Comments

Dmitry Kozlyuk Aug. 14, 2020, 6:39 p.m. UTC | #1
On Fri, 14 Aug 2020 10:34:41 -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. 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 <stephen@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(-)
[snip]

> @@ -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

Seems like FreeBSD doesn't support this option as well.

It is clear that iovec approach saves a syscall on each write, but is it worth
implementing log timestamps on each platform instead of prepending it in
common code (with a second fwrite call)? For fast event stream with precise
timestamps, there is tracing framework.
Stephen Hemminger Aug. 14, 2020, 6:45 p.m. UTC | #2
On Fri, 14 Aug 2020 21:39:29 +0300
Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:

> On Fri, 14 Aug 2020 10:34:41 -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. 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 <stephen@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(-)  
> [snip]
> 
> > @@ -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  
> 
> Seems like FreeBSD doesn't support this option as well.
> 
> It is clear that iovec approach saves a syscall on each write, but is it worth
> implementing log timestamps on each platform instead of prepending it in
> common code (with a second fwrite call)? For fast event stream with precise
> timestamps, there is tracing framework.

FreeBsd doesn't go through the same log code.

Iovec is to keep timestamp and message as an atomic message.
There is no good way to use fwrite to get anything atomic.
Fwrite is unnecessary here anyway saving a copy and avoid issues with library
getting corrupted is good.
Dmitry Kozlyuk Aug. 14, 2020, 7:09 p.m. UTC | #3
On Fri, 14 Aug 2020 11:45:49 -0700, Stephen Hemminger wrote:
> On Fri, 14 Aug 2020 21:39:29 +0300
> Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:
[...]
> FreeBsd doesn't go through the same log code.

Then --log-timestamp shouldn't appear on FreeBSD if it's unsupported.

> Iovec is to keep timestamp and message as an atomic message.
> There is no good way to use fwrite to get anything atomic.
> Fwrite is unnecessary here anyway saving a copy and avoid issues with library
> getting corrupted is good.

Got it, thanks.
Stephen Hemminger Aug. 14, 2020, 7:20 p.m. UTC | #4
On Fri, 14 Aug 2020 22:09:11 +0300
Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:

> On Fri, 14 Aug 2020 11:45:49 -0700, Stephen Hemminger wrote:
> > On Fri, 14 Aug 2020 21:39:29 +0300
> > Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:  
> [...]
> > FreeBsd doesn't go through the same log code.  
> 
> Then --log-timestamp shouldn't appear on FreeBSD if it's unsupported.

Was using same ifdef that is already there. There are several options already
(like syslog facility) which do nothing on FreeBSD anyway.

> 
> > Iovec is to keep timestamp and message as an atomic message.
> > There is no good way to use fwrite to get anything atomic.
> > Fwrite is unnecessary here anyway saving a copy and avoid issues with library
> > getting corrupted is good.  
> 
> Got it, thanks.
Bruce Richardson Aug. 17, 2020, 10:37 a.m. UTC | #5
On Fri, Aug 14, 2020 at 12:20:28PM -0700, Stephen Hemminger wrote:
> On Fri, 14 Aug 2020 22:09:11 +0300
> Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:
> 
> > On Fri, 14 Aug 2020 11:45:49 -0700, Stephen Hemminger wrote:
> > > On Fri, 14 Aug 2020 21:39:29 +0300
> > > Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:  
> > [...]
> > > FreeBsd doesn't go through the same log code.  
> > 
> > Then --log-timestamp shouldn't appear on FreeBSD if it's unsupported.
> 
> Was using same ifdef that is already there. There are several options already
> (like syslog facility) which do nothing on FreeBSD anyway.
> 
While that is correct, I think that we really should support this on
FreeBSD also, since I don't think there is any technical reason we can't do
so, right? Even a sub-optimal solution where the timestamp write and log
write are non-atomic would be better than nothing.

/Bruce
Stephen Hemminger Aug. 17, 2020, 3:11 p.m. UTC | #6
On Mon, 17 Aug 2020 11:37:40 +0100
Bruce Richardson <bruce.richardson@intel.com> wrote:

> On Fri, Aug 14, 2020 at 12:20:28PM -0700, Stephen Hemminger wrote:
> > On Fri, 14 Aug 2020 22:09:11 +0300
> > Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:
> >   
> > > On Fri, 14 Aug 2020 11:45:49 -0700, Stephen Hemminger wrote:  
> > > > On Fri, 14 Aug 2020 21:39:29 +0300
> > > > Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:    
> > > [...]  
> > > > FreeBsd doesn't go through the same log code.    
> > > 
> > > Then --log-timestamp shouldn't appear on FreeBSD if it's unsupported.  
> > 
> > Was using same ifdef that is already there. There are several options already
> > (like syslog facility) which do nothing on FreeBSD anyway.
> >   
> While that is correct, I think that we really should support this on
> FreeBSD also, since I don't think there is any technical reason we can't do
> so, right? Even a sub-optimal solution where the timestamp write and log
> write are non-atomic would be better than nothing.
> 
> /Bruce

FreeBSD now just uses default log stream (stdout).
Linux has log stream to syslog and stdout.

There is nothing Linux specific in the old or new code.
The Linux code could just be moved to common, and both could use it.
That is a separate patch, and someone with expertise and build setup for FreeBSD needs to do it.
Thomas Monjalon Oct. 19, 2020, 2:11 p.m. UTC | #7
There was no ack or conclusion for this patch.

17/08/2020 17:11, Stephen Hemminger:
> On Mon, 17 Aug 2020 11:37:40 +0100
> Bruce Richardson <bruce.richardson@intel.com> wrote:
> 
> > On Fri, Aug 14, 2020 at 12:20:28PM -0700, Stephen Hemminger wrote:
> > > On Fri, 14 Aug 2020 22:09:11 +0300
> > > Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:
> > >   
> > > > On Fri, 14 Aug 2020 11:45:49 -0700, Stephen Hemminger wrote:  
> > > > > On Fri, 14 Aug 2020 21:39:29 +0300
> > > > > Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:    
> > > > [...]  
> > > > > FreeBsd doesn't go through the same log code.    
> > > > 
> > > > Then --log-timestamp shouldn't appear on FreeBSD if it's unsupported.  
> > > 
> > > Was using same ifdef that is already there. There are several options already
> > > (like syslog facility) which do nothing on FreeBSD anyway.
> > >   
> > While that is correct, I think that we really should support this on
> > FreeBSD also, since I don't think there is any technical reason we can't do
> > so, right? Even a sub-optimal solution where the timestamp write and log
> > write are non-atomic would be better than nothing.
> > 
> > /Bruce
> 
> FreeBSD now just uses default log stream (stdout).
> Linux has log stream to syslog and stdout.
> 
> There is nothing Linux specific in the old or new code.
> The Linux code could just be moved to common, and both could use it.
> That is a separate patch, and someone with expertise and build setup for FreeBSD needs to do it.
>
Stephen Hemminger Oct. 19, 2020, 3:25 p.m. UTC | #8
On Mon, 19 Oct 2020 16:11:19 +0200
Thomas Monjalon <thomas@monjalon.net> wrote:

> There was no ack or conclusion for this patch.
> 
> 17/08/2020 17:11, Stephen Hemminger:
> > On Mon, 17 Aug 2020 11:37:40 +0100
> > Bruce Richardson <bruce.richardson@intel.com> wrote:
> >   
> > > On Fri, Aug 14, 2020 at 12:20:28PM -0700, Stephen Hemminger wrote:  
> > > > On Fri, 14 Aug 2020 22:09:11 +0300
> > > > Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:
> > > >     
> > > > > On Fri, 14 Aug 2020 11:45:49 -0700, Stephen Hemminger wrote:    
> > > > > > On Fri, 14 Aug 2020 21:39:29 +0300
> > > > > > Dmitry Kozlyuk <dmitry.kozliuk@gmail.com> wrote:      
> > > > > [...]    
> > > > > > FreeBsd doesn't go through the same log code.      
> > > > > 
> > > > > Then --log-timestamp shouldn't appear on FreeBSD if it's unsupported.    
> > > > 
> > > > Was using same ifdef that is already there. There are several options already
> > > > (like syslog facility) which do nothing on FreeBSD anyway.
> > > >     
> > > While that is correct, I think that we really should support this on
> > > FreeBSD also, since I don't think there is any technical reason we can't do
> > > so, right? Even a sub-optimal solution where the timestamp write and log
> > > write are non-atomic would be better than nothing.
> > > 
> > > /Bruce  
> > 
> > FreeBSD now just uses default log stream (stdout).
> > Linux has log stream to syslog and stdout.
> > 
> > There is nothing Linux specific in the old or new code.
> > The Linux code could just be moved to common, and both could use it.
> > That is a separate patch, and someone with expertise and build setup for FreeBSD needs to do it.
> >   

Lets fix FreeBSD to use common code for logging, then timestamp option can be added?

Patch
diff mbox series

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;