DPDK patches and discussions
 help / color / mirror / Atom feed
From: Stephen Hemminger <stephen@networkplumber.org>
To: dev@dpdk.org
Cc: Stephen Hemminger <stephen@networkplumber.org>
Subject: [dpdk-dev] [PATCH] eal: add option to put timestamp on console output
Date: Fri, 14 Aug 2020 10:34:41 -0700
Message-ID: <20200814173441.23086-1-stephen@networkplumber.org> (raw)

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(-)

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


             reply	other threads:[~2020-08-14 17:34 UTC|newest]

Thread overview: 9+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2020-08-14 17:34 Stephen Hemminger [this message]
2020-08-14 18:39 ` Dmitry Kozlyuk
2020-08-14 18:45   ` Stephen Hemminger
2020-08-14 19:09     ` Dmitry Kozlyuk
2020-08-14 19:20       ` Stephen Hemminger
2020-08-17 10:37         ` Bruce Richardson
2020-08-17 15:11           ` Stephen Hemminger
2020-10-19 14:11             ` Thomas Monjalon
2020-10-19 15:25               ` Stephen Hemminger

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20200814173441.23086-1-stephen@networkplumber.org \
    --to=stephen@networkplumber.org \
    --cc=dev@dpdk.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

DPDK patches and discussions

This inbox may be cloned and mirrored by anyone:

	git clone --mirror https://inbox.dpdk.org/dev/0 dev/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 dev dev/ https://inbox.dpdk.org/dev \
		dev@dpdk.org
	public-inbox-index dev

Example config snippet for mirrors.
Newsgroup available over NNTP:
	nntp://inbox.dpdk.org/inbox.dpdk.dev


AGPL code for this site: git clone https://public-inbox.org/public-inbox.git