@@ -1054,6 +1054,19 @@ 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" };
+
+ /* Try running with invalid timestamp */
+ const char * const argv25[] = {prgname, prefix, mp_flag,
+ "--log-timestamp=invalid" };
+
+
/* run all tests also applicable to FreeBSD first */
if (launch_proc(argv0) == 0) {
@@ -1161,6 +1174,19 @@ 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;
+ }
+ if (launch_proc(argv25) == 0) {
+ printf("Error - process did run ok with --log-timestamp=invalid parameter\n");
+ goto fail;
+ }
+
rmdir(hugepath_dir3);
rmdir(hugepath_dir2);
@@ -59,6 +59,32 @@ For example::
Within an application, the same result can be got using the ``rte_log_set_level_pattern()`` or ``rte_log_set_level_regex()`` APIs.
+Log timestamp
+~~~~~~~~~~~~~
+
+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
+
+Multiple timestamp alternative timestamp formats are available:
+
+.. csv-table:: Log time stamp format
+ :header: "Format", "Description", "Example"
+ :widths: 6, 30, 32
+
+ "ctime", "Unix ctime", "``[Wed Mar 20 07:26:12 2024]``"
+ "delta", "Offset since last", "``[< 3.162373>]``"
+ "reltime", "Seconds since last or time if minute changed", "``[ +3.001791]`` or ``[Mar20 07:26:12]``"
+ "iso", "ISO-8601", "``[2024-03-20T07:26:12−07:00]``"
+
+To prefix all console messages with ISO format time the syntax is::
+
+ /path/to/app --log-timestamp=iso
+
+
+
Using Logging APIs to Generate Log Messages
-------------------------------------------
@@ -74,6 +74,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 },
@@ -1616,6 +1617,7 @@ eal_log_level_parse(int argc, char * const argv[])
switch (opt) {
case OPT_LOG_LEVEL_NUM:
case OPT_SYSLOG_NUM:
+ case OPT_LOG_TIMESTAMP_NUM:
if (eal_parse_common_option(opt, optarg, internal_conf) < 0)
return -1;
break;
@@ -1838,7 +1840,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 --"
@@ -1846,7 +1848,14 @@ eal_parse_common_option(int opt, const char *optarg,
return -1;
}
break;
- }
+
+ case OPT_LOG_TIMESTAMP_NUM:
+ if (eal_log_timestamp(optarg) < 0) {
+ EAL_LOG(ERR, "invalid parameters for --"
+ OPT_LOG_TIMESTAMP);
+ return -1;
+ }
+ break;
#ifndef RTE_EXEC_ENV_WINDOWS
case OPT_TRACE_NUM: {
@@ -2210,6 +2219,7 @@ eal_common_usage(void)
" --"OPT_LOG_LEVEL"=<type-match>:<level>\n"
" Set specific log level\n"
" --"OPT_LOG_LEVEL"=help Show log types and levels\n"
+ " --"OPT_LOG_TIMESTAMP"[=<format>] Timestamp log output\n"
#ifndef RTE_EXEC_ENV_WINDOWS
" --"OPT_TRACE"=<regex-match>\n"
" Enable trace based on regular expression trace name.\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"
@@ -392,8 +392,10 @@ eal_parse_args(int argc, char **argv)
goto out;
}
- /* eal_log_level_parse() already handled these */
- if (opt == OPT_LOG_LEVEL_NUM || opt == OPT_LOG_SYSLOG_NUM)
+ /* eal_log_level_parse() already handled these options */
+ if (opt == OPT_LOG_LEVEL_NUM ||
+ opt == OPT_SYSLOG_NUM ||
+ opt == OPT_LOG_TIMESTAMP_NUM)
continue;
ret = eal_parse_common_option(opt, optarg, internal_conf);
@@ -611,7 +611,9 @@ eal_parse_args(int argc, char **argv)
}
/* eal_log_level_parse() already handled these options */
- if (opt == OPT_LOG_LEVEL_NUM || opt == OPT_SYSLOG_NUM)
+ if (opt == OPT_LOG_LEVEL_NUM ||
+ opt == OPT_SYSLOG_NUM ||
+ opt == OPT_LOG_TIMESTAMP_NUM)
continue;
ret = eal_parse_common_option(opt, optarg, internal_conf);
@@ -121,7 +121,9 @@ eal_parse_args(int argc, char **argv)
}
/* eal_log_level_parse() already handled these options */
- if (opt == OPT_LOG_LEVEL_NUM || opt == OPT_SYSLOG_NUM)
+ if (opt == OPT_LOG_LEVEL_NUM ||
+ opt == OPT_SYSLOG_NUM ||
+ opt == OPT_LOG_TIMESTAMP_NUM)
continue;
ret = eal_parse_common_option(opt, optarg, internal_conf);
@@ -21,7 +21,7 @@
#include "log_private.h"
#ifdef RTE_EXEC_ENV_WINDOWS
-#define strdup _strdup
+#include <rte_os_shim.h>
#endif
struct rte_log_dynamic_type {
@@ -509,6 +509,11 @@ eal_log_syslog(const char *mode __rte_unused)
void
eal_log_init(const char *id __rte_unused)
{
+ if (log_timestamp_enabled())
+ rte_logs.print_func = log_print_with_timestamp;
+ else
+ rte_logs.print_func = vfprintf;
+
#if RTE_LOG_DP_LEVEL >= RTE_LOG_DEBUG
RTE_LOG(NOTICE, EAL,
"Debug dataplane logs available - lower performance\n");
@@ -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>
@@ -39,4 +41,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 */
@@ -3,7 +3,18 @@
#ifndef LOG_PRIVATE_H
#define LOG_PRIVATE_H
+/* Defined in limits.h on Linux */
+#ifndef LINE_MAX
+#define LINE_MAX 2048 /* _POSIX2_LINE_MAX */
+#endif
+
/* Note: same as vfprintf() */
typedef int (*log_print_t)(FILE *f, const char *fmt, va_list ap);
+bool log_timestamp_enabled(void);
+ssize_t log_timestamp(char *tsbuf, size_t tsbuflen);
+
+__rte_format_printf(2, 0)
+int log_print_with_timestamp(FILE *f, const char *format, va_list ap);
+
#endif /* LOG_PRIVATE_H */
new file mode 100644
@@ -0,0 +1,240 @@
+/* SPDX-License-Identifier: BSD-3-Clause */
+
+#include <limits.h>
+#include <stdarg.h>
+#include <stdbool.h>
+#include <stdint.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <time.h>
+
+#include <rte_common.h>
+#include <rte_stdatomic.h>
+#include <rte_time.h>
+
+#ifdef RTE_EXEC_ENV_WINDOWS
+#include <rte_os_shim.h>
+#endif
+
+#include "log_internal.h"
+#include "log_private.h"
+
+#ifndef NS_PER_SEC
+#define NS_PER_SEC 1E9
+#endif
+
+static enum {
+ LOG_TIMESTAMP_NONE = 0,
+ LOG_TIMESTAMP_TIME, /* time since start */
+ LOG_TIMESTAMP_DELTA, /* time since last message */
+ LOG_TIMESTAMP_RELTIME, /* relative time since last message */
+ LOG_TIMESTAMP_CTIME, /* Unix standard time format */
+ LOG_TIMESTAMP_ISO, /* ISO8601 time format */
+} log_time_format;
+
+static struct {
+ struct timespec started; /* when log was initialized */
+ RTE_ATOMIC(uint64_t) last_monotonic;
+ RTE_ATOMIC(uint64_t) last_realtime;
+} log_time;
+
+/* Set the log timestamp format */
+int
+eal_log_timestamp(const char *str)
+{
+ if (str == NULL)
+ log_time_format = LOG_TIMESTAMP_TIME;
+ else if (strcmp(str, "notime") == 0)
+ log_time_format = LOG_TIMESTAMP_NONE;
+ else if (strcmp(str, "reltime") == 0)
+ log_time_format = LOG_TIMESTAMP_RELTIME;
+ else if (strcmp(str, "delta") == 0)
+ log_time_format = LOG_TIMESTAMP_DELTA;
+ else if (strcmp(str, "ctime") == 0)
+ log_time_format = LOG_TIMESTAMP_CTIME;
+ else if (strcmp(str, "iso") == 0)
+ log_time_format = LOG_TIMESTAMP_ISO;
+ else
+ return -1;
+
+ return 0;
+}
+
+bool
+log_timestamp_enabled(void)
+{
+ return log_time_format != LOG_TIMESTAMP_NONE;
+}
+
+/* Subtract two timespec values and handle wraparound */
+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;
+}
+
+/*
+ * Format current timespec into ISO8601 format.
+ * Surprisingly, can't just use strftime() for this;
+ * since want microseconds and the timezone offset format differs.
+ */
+static ssize_t
+format_iso8601(char *tsbuf, size_t tsbuflen, const struct timespec *now)
+{
+ struct tm *tm, tbuf;
+ char dbuf[64]; /* "2024-05-01T22:11:00" */
+ char zbuf[16] = { }; /* "+0800" */
+
+ tm = localtime_r(&now->tv_sec, &tbuf);
+
+ /* make "2024-05-01T22:11:00,123456+0100" */
+ if (strftime(dbuf, sizeof(dbuf), "%Y-%m-%dT%H:%M:%S", tm) == 0)
+ return 0;
+
+ /* convert timezone to +hhmm */
+ if (strftime(zbuf, sizeof(zbuf), "%z", tm) == 0)
+ return 0;
+
+ /* the result for strftime is "+hhmm" but ISO wants "+hh:mm" */
+ return snprintf(tsbuf, tsbuflen, "%s,%06lu%.3s:%.2s",
+ dbuf, now->tv_nsec / 1000u,
+ zbuf, zbuf + 3);
+}
+
+/*
+ * Format a timestamp which shows time between messages.
+ */
+static ssize_t
+format_delta(char *tsbuf, size_t tsbuflen, const struct timespec *now)
+{
+ struct timespec delta;
+ uint64_t ns = rte_timespec_to_ns(now);
+ uint64_t previous;
+
+ previous = rte_atomic_exchange_explicit(&log_time.last_monotonic,
+ ns, rte_memory_order_seq_cst);
+ delta = rte_ns_to_timespec(ns - previous);
+
+ return snprintf(tsbuf, tsbuflen, "<%6lu.%06lu>",
+ (unsigned long)delta.tv_sec,
+ (unsigned long)delta.tv_nsec / 1000u);
+}
+
+/*
+ * Make a timestamp where if the minute, hour or day has
+ * changed from the last message, then print abbreviated
+ * "Month day hour:minute" format.
+ * Otherwise print delta from last printed message as +sec.usec
+ */
+static ssize_t
+format_reltime(char *tsbuf, size_t tsbuflen, const struct timespec *now)
+{
+ struct tm *tm, *last_tm, tbuf1, tbuf2;
+ time_t last_sec;
+ uint64_t ns = rte_timespec_to_ns(now);
+ uint64_t previous;
+
+ tm = localtime_r(&now->tv_sec, &tbuf1);
+
+ previous = rte_atomic_exchange_explicit(&log_time.last_realtime,
+ ns, rte_memory_order_seq_cst);
+ last_sec = previous / NS_PER_SEC;
+ last_tm = localtime_r(&last_sec, &tbuf2);
+ if (tm->tm_min == last_tm->tm_min &&
+ tm->tm_hour == last_tm->tm_hour &&
+ tm->tm_yday == last_tm->tm_yday) {
+ struct timespec elapsed;
+
+ elapsed = rte_ns_to_timespec(ns - previous);
+
+ return snprintf(tsbuf, tsbuflen, "+%3lu.%06lu",
+ (unsigned long)elapsed.tv_sec,
+ (unsigned long)elapsed.tv_nsec / 1000u);
+ } else {
+ return strftime(tsbuf, tsbuflen, "%b%d %H:%M", tm);
+ }
+}
+
+/* Format up a timestamp based on current format */
+ssize_t
+log_timestamp(char *tsbuf, size_t tsbuflen)
+{
+ struct timespec now, delta;
+
+ switch (log_time_format) {
+ case LOG_TIMESTAMP_NONE:
+ return 0;
+
+ case LOG_TIMESTAMP_TIME:
+ if (clock_gettime(CLOCK_MONOTONIC, &now) < 0)
+ return 0;
+
+ delta = timespec_sub(&now, &log_time.started);
+
+ return snprintf(tsbuf, tsbuflen, "%6lu.%06lu",
+ (unsigned long)delta.tv_sec,
+ (unsigned long)delta.tv_nsec / 1000u);
+
+ case LOG_TIMESTAMP_DELTA:
+ if (clock_gettime(CLOCK_MONOTONIC, &now) < 0)
+ return 0;
+
+ return format_delta(tsbuf, tsbuflen, &now);
+
+ case LOG_TIMESTAMP_RELTIME:
+ if (clock_gettime(CLOCK_REALTIME, &now) < 0)
+ return 0;
+
+ return format_reltime(tsbuf, tsbuflen, &now);
+
+ case LOG_TIMESTAMP_CTIME:
+ if (clock_gettime(CLOCK_REALTIME, &now) < 0)
+ return 0;
+
+ /* trncate to remove newline from ctime result */
+ return snprintf(tsbuf, tsbuflen, "%.24s", ctime(&now.tv_sec));
+
+ case LOG_TIMESTAMP_ISO:
+ if (clock_gettime(CLOCK_REALTIME, &now) < 0)
+ return 0;
+
+ return format_iso8601(tsbuf, tsbuflen, &now);
+ }
+
+ return 0;
+}
+
+/* print timestamp before message */
+int
+log_print_with_timestamp(FILE *f, const char *format, va_list ap)
+{
+ char tsbuf[128];
+ char msgbuf[LINE_MAX];
+
+ if (log_timestamp(tsbuf, sizeof(tsbuf)) > 0) {
+ vsnprintf(msgbuf, sizeof(msgbuf), format, ap);
+ return fprintf(f, "[%s] %s", tsbuf, msgbuf);
+ }
+
+ /* fall back when timestamp is unavailable */
+ return vfprintf(f, format, ap);
+}
+
+RTE_INIT_PRIO(log_timestamp_init, LOG)
+{
+ struct timespec now;
+
+ clock_gettime(CLOCK_MONOTONIC, &now);
+ log_time.started = now;
+ rte_atomic_store_explicit(&log_time.last_monotonic, rte_timespec_to_ns(&now),
+ rte_memory_order_seq_cst);
+}
@@ -2,5 +2,9 @@
# Copyright(c) 2023 Intel Corporation
includes += global_inc
-sources = files('log.c')
+sources = files(
+ 'log.c',
+ 'log_timestamp.c',
+)
+
headers = files('rte_log.h')
@@ -30,5 +30,6 @@ INTERNAL {
eal_log_save_pattern;
eal_log_save_regexp;
eal_log_syslog;
+ eal_log_timestamp;
rte_eal_log_cleanup;
};