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.
@@ -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);
@@ -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, 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"
@@ -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
+int eal_log_timestamp(const char *fmt);
+
+
#endif /* LOG_INTERNAL_H */
@@ -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;
@@ -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)
@@ -31,5 +31,6 @@ INTERNAL {
eal_log_save_pattern;
eal_log_save_regexp;
eal_log_set_default;
+ eal_log_timestamp;
rte_eal_log_cleanup;
};