[v9,5/5] 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.
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 ++++++++
doc/guides/prog_guide/log_lib.rst | 10 +++++++++
lib/eal/common/eal_common_options.c | 10 +++++++--
lib/eal/common/eal_options.h | 2 ++
lib/log/log_internal.h | 9 ++++++++
lib/log/log_unix.c | 32 +++++++++++++++++++++++++++--
lib/log/log_windows.c | 6 ++++++
lib/log/version.map | 1 +
8 files changed, 75 insertions(+), 4 deletions(-)
Comments
> From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> Sent: Monday, 18 March 2024 23.03
>
> 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>
> ---
[...]
> static ssize_t
> console_log_write(__rte_unused void *c, const char *buf, size_t size)
> {
> + struct timespec ts;
> ssize_t ret;
>
> - /* write on stderr */
> - ret = fwrite(buf, 1, size, stderr);
> + if (timestamp_enabled) {
> + clock_gettime(CLOCK_MONOTONIC, &ts);
> + ts.tv_sec -= log_started.tv_sec;
> + ts.tv_nsec -= log_started.tv_nsec;
Please log the absolute CLOCK_MONOTONIC instead of subtracting log_started, so timestamps can be easily compared with timestamps from other processes.
> + if (ts.tv_nsec < 0) {
> + --ts.tv_sec;
> + ts.tv_nsec += 1000000000ul;
> + }
> +
> + ret = fprintf(stderr, "[%8lu.%06lu] %.*s",
> + ts.tv_sec, ts.tv_nsec / 1000u,
> + (int) size, buf);
With the above change,
For the series,
Acked-by: Morten Brørup <mb@smartsharesystems.com>
On Tue, 19 Mar 2024 08:37:30 +0100
Morten Brørup <mb@smartsharesystems.com> wrote:
> > static ssize_t
> > console_log_write(__rte_unused void *c, const char *buf, size_t size)
> > {
> > + struct timespec ts;
> > ssize_t ret;
> >
> > - /* write on stderr */
> > - ret = fwrite(buf, 1, size, stderr);
> > + if (timestamp_enabled) {
> > + clock_gettime(CLOCK_MONOTONIC, &ts);
> > + ts.tv_sec -= log_started.tv_sec;
> > + ts.tv_nsec -= log_started.tv_nsec;
>
> Please log the absolute CLOCK_MONOTONIC instead of subtracting log_started, so timestamps can be easily compared with timestamps from other processes.
No, was trying to do what kernel dmesg does.
> From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> Sent: Tuesday, 19 March 2024 16.52
>
> On Tue, 19 Mar 2024 08:37:30 +0100
> Morten Brørup <mb@smartsharesystems.com> wrote:
>
> > > static ssize_t
> > > console_log_write(__rte_unused void *c, const char *buf, size_t
> size)
> > > {
> > > + struct timespec ts;
> > > ssize_t ret;
> > >
> > > - /* write on stderr */
> > > - ret = fwrite(buf, 1, size, stderr);
> > > + if (timestamp_enabled) {
> > > + clock_gettime(CLOCK_MONOTONIC, &ts);
> > > + ts.tv_sec -= log_started.tv_sec;
> > > + ts.tv_nsec -= log_started.tv_nsec;
> >
> > Please log the absolute CLOCK_MONOTONIC instead of subtracting
> log_started, so timestamps can be easily compared with timestamps from
> other processes.
>
>
> No, was trying to do what kernel dmesg does.
What do you mean? Doesn't the kernel output CLOCK_MONOTONIC timestamps (without offset)?
And by "timestamps from other processes" I also mean timestamps in log messages from the kernel itself.
On Tue, 19 Mar 2024 17:13:35 +0100
Morten Brørup <mb@smartsharesystems.com> wrote:
> > From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> > Sent: Tuesday, 19 March 2024 16.52
> >
> > On Tue, 19 Mar 2024 08:37:30 +0100
> > Morten Brørup <mb@smartsharesystems.com> wrote:
> >
> > > > static ssize_t
> > > > console_log_write(__rte_unused void *c, const char *buf, size_t
> > size)
> > > > {
> > > > + struct timespec ts;
> > > > ssize_t ret;
> > > >
> > > > - /* write on stderr */
> > > > - ret = fwrite(buf, 1, size, stderr);
> > > > + if (timestamp_enabled) {
> > > > + clock_gettime(CLOCK_MONOTONIC, &ts);
> > > > + ts.tv_sec -= log_started.tv_sec;
> > > > + ts.tv_nsec -= log_started.tv_nsec;
> > >
> > > Please log the absolute CLOCK_MONOTONIC instead of subtracting
> > log_started, so timestamps can be easily compared with timestamps from
> > other processes.
> >
> >
> > No, was trying to do what kernel dmesg does.
>
> What do you mean? Doesn't the kernel output CLOCK_MONOTONIC timestamps (without offset)?
>
> And by "timestamps from other processes" I also mean timestamps in log messages from the kernel itself.
>
If you look at dmesg command that formats the messages, it has lots of timestamp options.
Next version will support more of these.
--time-format format
Print timestamps using the given format, which can be ctime,
reltime, delta or iso. The first three formats are aliases of
the time-format-specific options. The iso format is a dmesg
implementation of the ISO-8601 timestamp format. The purpose
of this format is to make the comparing of timestamps between
two systems, and any other parsing, easy. The definition of
the iso timestamp is:
YYYY-MM-DD<T>HH:MM:SS,<microseconds>←+><timezone offset from
UTC>.
> From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> Sent: Wednesday, 20 March 2024 04.34
>
> On Tue, 19 Mar 2024 17:13:35 +0100
> Morten Brørup <mb@smartsharesystems.com> wrote:
>
> > > From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> > > Sent: Tuesday, 19 March 2024 16.52
> > >
> > > On Tue, 19 Mar 2024 08:37:30 +0100
> > > Morten Brørup <mb@smartsharesystems.com> wrote:
> > >
> > > > > static ssize_t
> > > > > console_log_write(__rte_unused void *c, const char *buf, size_t
> > > size)
> > > > > {
> > > > > + struct timespec ts;
> > > > > ssize_t ret;
> > > > >
> > > > > - /* write on stderr */
> > > > > - ret = fwrite(buf, 1, size, stderr);
> > > > > + if (timestamp_enabled) {
> > > > > + clock_gettime(CLOCK_MONOTONIC, &ts);
> > > > > + ts.tv_sec -= log_started.tv_sec;
> > > > > + ts.tv_nsec -= log_started.tv_nsec;
> > > >
> > > > Please log the absolute CLOCK_MONOTONIC instead of subtracting
> > > log_started, so timestamps can be easily compared with timestamps from
> > > other processes.
> > >
> > >
> > > No, was trying to do what kernel dmesg does.
> >
> > What do you mean? Doesn't the kernel output CLOCK_MONOTONIC timestamps
> (without offset)?
> >
> > And by "timestamps from other processes" I also mean timestamps in log
> messages from the kernel itself.
> >
>
> If you look at dmesg command that formats the messages, it has lots of
> timestamp options.
> Next version will support more of these.
>
> --time-format format
> Print timestamps using the given format, which can be ctime,
> reltime, delta or iso. The first three formats are aliases of
> the time-format-specific options. The iso format is a dmesg
> implementation of the ISO-8601 timestamp format. The purpose
> of this format is to make the comparing of timestamps between
> two systems, and any other parsing, easy. The definition of
> the iso timestamp is:
> YYYY-MM-DD<T>HH:MM:SS,<microseconds>←+><timezone offset from
> UTC>.
That's formatting.
I'm talking about the initial offset.
The kernel's "log start time" is set to system start timestamp.
Your "log start time" is set to application start timestamp:
+void
+eal_log_enable_timestamp(void)
+{
+ timestamp_enabled = true;
+ clock_gettime(CLOCK_MONOTONIC, &log_started);
+}
So, different offset. I prefer using the same offset.
On Wed, 20 Mar 2024 09:34:21 +0100
Morten Brørup <mb@smartsharesystems.com> wrote:
> > From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> > Sent: Wednesday, 20 March 2024 04.34
> >
> > On Tue, 19 Mar 2024 17:13:35 +0100
> > Morten Brørup <mb@smartsharesystems.com> wrote:
> >
> > > > From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> > > > Sent: Tuesday, 19 March 2024 16.52
> > > >
> > > > On Tue, 19 Mar 2024 08:37:30 +0100
> > > > Morten Brørup <mb@smartsharesystems.com> wrote:
> > > >
> > > > > > static ssize_t
> > > > > > console_log_write(__rte_unused void *c, const char *buf, size_t
> > > > size)
> > > > > > {
> > > > > > + struct timespec ts;
> > > > > > ssize_t ret;
> > > > > >
> > > > > > - /* write on stderr */
> > > > > > - ret = fwrite(buf, 1, size, stderr);
> > > > > > + if (timestamp_enabled) {
> > > > > > + clock_gettime(CLOCK_MONOTONIC, &ts);
> > > > > > + ts.tv_sec -= log_started.tv_sec;
> > > > > > + ts.tv_nsec -= log_started.tv_nsec;
> > > > >
> > > > > Please log the absolute CLOCK_MONOTONIC instead of subtracting
> > > > log_started, so timestamps can be easily compared with timestamps from
> > > > other processes.
> > > >
> > > >
> > > > No, was trying to do what kernel dmesg does.
> > >
> > > What do you mean? Doesn't the kernel output CLOCK_MONOTONIC timestamps
> > (without offset)?
> > >
> > > And by "timestamps from other processes" I also mean timestamps in log
> > messages from the kernel itself.
> > >
> >
> > If you look at dmesg command that formats the messages, it has lots of
> > timestamp options.
> > Next version will support more of these.
> >
> > --time-format format
> > Print timestamps using the given format, which can be ctime,
> > reltime, delta or iso. The first three formats are aliases of
> > the time-format-specific options. The iso format is a dmesg
> > implementation of the ISO-8601 timestamp format. The purpose
> > of this format is to make the comparing of timestamps between
> > two systems, and any other parsing, easy. The definition of
> > the iso timestamp is:
> > YYYY-MM-DD<T>HH:MM:SS,<microseconds>←+><timezone offset from
> > UTC>.
>
> That's formatting.
>
> I'm talking about the initial offset.
>
> The kernel's "log start time" is set to system start timestamp.
>
> Your "log start time" is set to application start timestamp:
>
> +void
> +eal_log_enable_timestamp(void)
> +{
> + timestamp_enabled = true;
> + clock_gettime(CLOCK_MONOTONIC, &log_started);
> +}
>
> So, different offset. I prefer using the same offset.
Monotonic has no absolute zero time and can be quite large so offsetting
seemed most logical. Also, the kernel does not make boot time monotonic
clock value available. Other options are REALTIME or BOOTTIME.
But both of these get quite large.
> From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> Sent: Wednesday, 20 March 2024 15.39
>
> On Wed, 20 Mar 2024 09:34:21 +0100
> Morten Brørup <mb@smartsharesystems.com> wrote:
>
> > > From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> > > Sent: Wednesday, 20 March 2024 04.34
> > >
> > > On Tue, 19 Mar 2024 17:13:35 +0100
> > > Morten Brørup <mb@smartsharesystems.com> wrote:
> > >
> > > > > From: Stephen Hemminger [mailto:stephen@networkplumber.org]
> > > > > Sent: Tuesday, 19 March 2024 16.52
> > > > >
> > > > > On Tue, 19 Mar 2024 08:37:30 +0100
> > > > > Morten Brørup <mb@smartsharesystems.com> wrote:
> > > > >
> > > > > > > static ssize_t
> > > > > > > console_log_write(__rte_unused void *c, const char *buf,
> size_t
> > > > > size)
> > > > > > > {
> > > > > > > + struct timespec ts;
> > > > > > > ssize_t ret;
> > > > > > >
> > > > > > > - /* write on stderr */
> > > > > > > - ret = fwrite(buf, 1, size, stderr);
> > > > > > > + if (timestamp_enabled) {
> > > > > > > + clock_gettime(CLOCK_MONOTONIC, &ts);
> > > > > > > + ts.tv_sec -= log_started.tv_sec;
> > > > > > > + ts.tv_nsec -= log_started.tv_nsec;
> > > > > >
> > > > > > Please log the absolute CLOCK_MONOTONIC instead of subtracting
> > > > > log_started, so timestamps can be easily compared with
> timestamps from
> > > > > other processes.
> > > > >
> > > > >
> > > > > No, was trying to do what kernel dmesg does.
> > > >
> > > > What do you mean? Doesn't the kernel output CLOCK_MONOTONIC
> timestamps
> > > (without offset)?
> > > >
> > > > And by "timestamps from other processes" I also mean timestamps in
> log
> > > messages from the kernel itself.
> > > >
> > >
> > > If you look at dmesg command that formats the messages, it has lots
> of
> > > timestamp options.
> > > Next version will support more of these.
> > >
> > > --time-format format
> > > Print timestamps using the given format, which can be
> ctime,
> > > reltime, delta or iso. The first three formats are
> aliases of
> > > the time-format-specific options. The iso format is a
> dmesg
> > > implementation of the ISO-8601 timestamp format. The
> purpose
> > > of this format is to make the comparing of timestamps
> between
> > > two systems, and any other parsing, easy. The definition
> of
> > > the iso timestamp is:
> > > YYYY-MM-DD<T>HH:MM:SS,<microseconds>←+><timezone offset
> from
> > > UTC>.
> >
> > That's formatting.
> >
> > I'm talking about the initial offset.
> >
> > The kernel's "log start time" is set to system start timestamp.
> >
> > Your "log start time" is set to application start timestamp:
> >
> > +void
> > +eal_log_enable_timestamp(void)
> > +{
> > + timestamp_enabled = true;
> > + clock_gettime(CLOCK_MONOTONIC, &log_started);
> > +}
> >
> > So, different offset. I prefer using the same offset.
>
>
> Monotonic has no absolute zero time and can be quite large so offsetting
> seemed most logical. Also, the kernel does not make boot time monotonic
> clock value available. Other options are REALTIME or BOOTTIME.
> But both of these get quite large.
I don't think that having a large tv_sec is a problem.
I think the ability to correlate log timestamps with other applications is more important.
If we choose one of the standard clocks, applications might choose the same clock. If we subtract the start time of this specific application, it's not in sync with anything else.
The question really is: Which clock is most popular for debug logging to the console? We should use that clock.
@@ -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);
@@ -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
-------------------------------------------
@@ -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, 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 },
@@ -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,7 +1900,10 @@ eal_parse_common_option(int opt, const char *optarg,
return -1;
}
break;
- }
+
+ case OPT_LOG_TIMESTAMP_NUM:
+ eal_log_enable_timestamp();
+ break;
#ifndef RTE_EXEC_ENV_WINDOWS
case OPT_TRACE_NUM: {
@@ -2261,6 +2266,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"
@@ -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,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
+void eal_log_enable_timestamp(void);
+
+
#endif /* LOG_INTERNAL_H */
@@ -2,24 +2,52 @@
* Copyright(c) 2010-2014 Intel Corporation
*/
+#include <stdbool.h>
#include <stdio.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"
+static bool timestamp_enabled;
+static struct timespec log_started;
+
+void
+eal_log_enable_timestamp(void)
+{
+ timestamp_enabled = true;
+ clock_gettime(CLOCK_MONOTONIC, &log_started);
+}
+
/*
* default log function
*/
static ssize_t
console_log_write(__rte_unused void *c, const char *buf, size_t size)
{
+ struct timespec ts;
ssize_t ret;
- /* write on stderr */
- ret = fwrite(buf, 1, size, stderr);
+ if (timestamp_enabled) {
+ clock_gettime(CLOCK_MONOTONIC, &ts);
+ ts.tv_sec -= log_started.tv_sec;
+ ts.tv_nsec -= log_started.tv_nsec;
+ if (ts.tv_nsec < 0) {
+ --ts.tv_sec;
+ ts.tv_nsec += 1000000000ul;
+ }
+
+ ret = fprintf(stderr, "[%8lu.%06lu] %.*s",
+ ts.tv_sec, ts.tv_nsec / 1000u,
+ (int) size, buf);
+ } else {
+ ret = fwrite(buf, 1, size, stderr);
+ }
fflush(stderr);
/* Syslog error levels are from 0 to 7, so subtract 1 to convert */
@@ -6,6 +6,12 @@
#include <rte_log.h>
#include "log_internal.h"
+void
+eal_log_enable_timestamp(void)
+{
+ /* 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)
@@ -25,6 +25,7 @@ DPDK_24 {
INTERNAL {
global:
+ eal_log_enable_timestamp;
eal_log_get_default;
eal_log_init;
eal_log_level2str;