eal: add option to put timestamp on console output
Checks
Commit Message
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
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.
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.
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.
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.
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
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.
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.
>
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?
19/10/2020 17:25, Stephen Hemminger:
> 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?
OK
On 2024-03-24 03:33, Stephen Hemminger wrote:
> Improvements and unification of logging library (for 24.07 release).
> This version works on all platforms: Linux, Windows and FreeBSD.
>
> This is update to rework patch set. It adds several new features
> to the console log output.
>
> * Putting a timestamp on console output which is useful for
> analyzing performance of startup codes. Timestamp is optional
> and must be enabled on command line.
>
> * Displaying console output with colors.
> It uses the standard conventions used by many other Linux commands
> for colorized display. The default is to enable color if the
> console output is going to a terminal. But it can be always
> on or disabled by command line flag. This default was chosen
> based on what dmesg(1) command does.
>
> I find color helpful because DPDK drivers and libraries print
> lots of not very useful messages. And having error messages
> highlighted in bold face helps. This might also get users to
> pay more attention to error messages. Many bug reports have
> earlier messages that are lost because there are so many
> info messages.
>
> * Use of syslog on Linux is replaced by using journal
> API (over unix domain socket). This replaces legacy syslog;
> (almost) all Linux distros have switched to journal.
>
Is "switched to journal" the same as "switched to systemd", or are there
non-systemd journal API implementations?
I'm guessing there are quite a few Linux-based embedded systems that
doesn't use systemd.
Ideally, you would like to have journal as the Linux default, and then
syslog as a build-time option.
> Will add a release note in next release (after this is merged)
>
> v11 - rework to be portable to Windows
> drop syslog support and support journal instead
>
> Stephen Hemminger (9):
> windows: make getopt functions have const properties
> eal: make eal_log_level_parse common
> eal: do not duplicate rte_init_alert() messages
> eal: change rte_exit() output to match rte_log()
> log: drop syslog support, and make code common
> log: add hook for printing log messages
> log: add timestamp option
> log: add support for systemd journal
> log: colorize log output
>
> app/test/test_eal_flags.c | 38 +-
> doc/guides/linux_gsg/linux_eal_parameters.rst | 27 -
> .../prog_guide/env_abstraction_layer.rst | 5 +-
> doc/guides/prog_guide/log_lib.rst | 41 +-
> lib/eal/common/eal_common_debug.c | 11 +-
> lib/eal/common/eal_common_options.c | 123 ++---
> lib/eal/common/eal_internal_cfg.h | 2 +-
> lib/eal/common/eal_options.h | 7 +-
> lib/eal/freebsd/eal.c | 54 +-
> lib/eal/linux/eal.c | 52 +-
> lib/eal/unix/eal_debug.c | 3 +-
> lib/eal/windows/eal.c | 39 +-
> lib/eal/windows/getopt.c | 23 +-
> lib/eal/windows/include/getopt.h | 8 +-
> lib/log/log.c | 513 ++++++++++++++++--
> lib/log/log_freebsd.c | 12 -
> lib/log/log_internal.h | 16 +-
> lib/log/log_linux.c | 61 ---
> lib/log/log_windows.c | 18 -
> lib/log/meson.build | 5 +-
> lib/log/version.map | 2 +
> 21 files changed, 656 insertions(+), 404 deletions(-)
> delete mode 100644 lib/log/log_freebsd.c
> delete mode 100644 lib/log/log_linux.c
> delete mode 100644 lib/log/log_windows.c
>
@@ -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.
@@ -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"
@@ -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 */
@@ -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"
@@ -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;