@@ -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;
@@ -1843,7 +1845,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 --"
@@ -1851,7 +1853,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: {
@@ -2216,6 +2225,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);
@@ -11,6 +11,7 @@
#include <regex.h>
#include <fnmatch.h>
#include <sys/queue.h>
+#include <unistd.h>
#include <rte_log.h>
#include <rte_per_lcore.h>
@@ -18,7 +19,7 @@
#include "log_internal.h"
#ifdef RTE_EXEC_ENV_WINDOWS
-#define strdup _strdup
+#include <rte_os_shim.h>
#endif
struct rte_log_dynamic_type {
@@ -26,6 +27,15 @@ struct rte_log_dynamic_type {
uint32_t loglevel;
};
+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,
+};
+
typedef int (*log_print_t)(FILE *f, uint32_t level, const char *fmt, va_list ap);
static int log_print(FILE *f, uint32_t level, const char *format, va_list ap);
@@ -35,6 +45,11 @@ static struct rte_logs {
uint32_t level; /**< Log level. */
FILE *file; /**< Output file set by rte_openlog_stream, or NULL. */
log_print_t print_func;
+
+ enum eal_log_time_format time_format;
+ struct timespec started; /* when log was initialized */
+ struct timespec previous; /* when last msg was printed */
+
size_t dynamic_types_len;
struct rte_log_dynamic_type *dynamic_types;
} rte_logs = {
@@ -375,6 +390,9 @@ RTE_INIT_PRIO(log_init, LOG)
{
uint32_t i;
+ clock_gettime(CLOCK_MONOTONIC, &rte_logs.started);
+ rte_logs.previous = rte_logs.started;
+
rte_log_set_global_level(RTE_LOG_DEBUG);
rte_logs.dynamic_types = calloc(RTE_LOGTYPE_FIRST_EXT_ID,
@@ -519,6 +537,152 @@ eal_log_syslog(const char *mode __rte_unused)
return -1;
}
+/* Set the log timestamp format */
+int
+eal_log_timestamp(const char *str)
+{
+ if (str == NULL)
+ rte_logs.time_format = EAL_LOG_TIMESTAMP_TIME;
+ else if (strcmp(str, "notime") == 0)
+ rte_logs.time_format = EAL_LOG_TIMESTAMP_NONE;
+ else if (strcmp(str, "reltime") == 0)
+ rte_logs.time_format = EAL_LOG_TIMESTAMP_RELTIME;
+ else if (strcmp(str, "delta") == 0)
+ rte_logs.time_format = EAL_LOG_TIMESTAMP_DELTA;
+ else if (strcmp(str, "ctime") == 0)
+ rte_logs.time_format = EAL_LOG_TIMESTAMP_CTIME;
+ else if (strcmp(str, "iso") == 0)
+ rte_logs.time_format = EAL_LOG_TIMESTAMP_ISO;
+ else
+ return -1;
+
+ return 0;
+}
+
+/* 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 */
+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);
+}
+
+/*
+ * 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, tbuf;
+ static struct tm last_tm;
+ struct timespec delta;
+
+ tm = localtime_r(&now->tv_sec, &tbuf);
+ delta = timespec_sub(now, &rte_logs.previous);
+ rte_logs.previous = *now;
+
+ /* if minute, day, hour hasn't changed then print delta */
+ if (tm->tm_min != last_tm.tm_min ||
+ tm->tm_hour != last_tm.tm_hour ||
+ tm->tm_yday != last_tm.tm_yday) {
+ last_tm = *tm;
+ return strftime(tsbuf, tsbuflen, "%b%d %H:%M", tm);
+ } else {
+ return snprintf(tsbuf, tsbuflen, "+%3lu.%06lu",
+ (unsigned long)delta.tv_sec,
+ (unsigned long)delta.tv_nsec / 1000u);
+ }
+}
+
+/* Format up a timestamp based on current format */
+static ssize_t
+format_timestamp(char *tsbuf, size_t tsbuflen)
+{
+ struct timespec now, delta;
+
+ switch (rte_logs.time_format) {
+ case EAL_LOG_TIMESTAMP_NONE:
+ return 0;
+
+ case EAL_LOG_TIMESTAMP_TIME:
+ if (clock_gettime(CLOCK_MONOTONIC, &now) < 0)
+ return 0;
+
+ delta = timespec_sub(&now, &rte_logs.started);
+
+ return snprintf(tsbuf, tsbuflen, "%6lu.%06lu",
+ (unsigned long)delta.tv_sec,
+ (unsigned long)delta.tv_nsec / 1000u);
+
+ case EAL_LOG_TIMESTAMP_DELTA:
+ if (clock_gettime(CLOCK_MONOTONIC, &now) < 0)
+ return 0;
+
+ delta = timespec_sub(&now, &rte_logs.previous);
+ rte_logs.previous = now;
+
+ return snprintf(tsbuf, tsbuflen, "<%6lu.%06lu>",
+ (unsigned long)delta.tv_sec,
+ (unsigned long)delta.tv_nsec / 1000u);
+
+ case EAL_LOG_TIMESTAMP_RELTIME:
+ if (clock_gettime(CLOCK_REALTIME, &now) < 0)
+ return 0;
+
+ return format_reltime(tsbuf, tsbuflen, &now);
+
+ case EAL_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 EAL_LOG_TIMESTAMP_ISO:
+ if (clock_gettime(CLOCK_REALTIME, &now) < 0)
+ return 0;
+
+ return format_iso8601(tsbuf, tsbuflen, &now);
+ }
+
+ return 0;
+}
+
/* default log print function */
__rte_format_printf(3, 0)
static int
@@ -528,12 +692,29 @@ log_print(FILE *f, uint32_t level __rte_unused,
return vfprintf(f, format, ap);
}
+/* print timestamp before message */
+__rte_format_printf(3, 0)
+static int
+log_print_with_timestamp(FILE *f, uint32_t level,
+ const char *format, va_list ap)
+{
+ char tsbuf[128];
+
+ if (format_timestamp(tsbuf, sizeof(tsbuf)) > 0)
+ fprintf(f, "[%s] ", tsbuf);
+
+ return log_print(f, level, format, ap);
+}
+
/*
* Called by rte_eal_init
*/
void
eal_log_init(const char *id __rte_unused)
{
+ if (rte_logs.time_format != EAL_LOG_TIMESTAMP_NONE)
+ rte_logs.print_func = log_print_with_timestamp;
+
default_log_stream = stderr;
#if RTE_LOG_DP_LEVEL >= RTE_LOG_DEBUG
@@ -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 */
@@ -30,5 +30,6 @@ INTERNAL {
eal_log_save_pattern;
eal_log_save_regexp;
eal_log_syslog;
+ eal_log_timestamp;
rte_eal_log_cleanup;
};