From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mails.dpdk.org (mails.dpdk.org [217.70.189.124]) by inbox.dpdk.org (Postfix) with ESMTP id 9418245B56; Wed, 16 Oct 2024 22:25:00 +0200 (CEST) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id 9826440691; Wed, 16 Oct 2024 22:24:11 +0200 (CEST) Received: from mail-pl1-f175.google.com (mail-pl1-f175.google.com [209.85.214.175]) by mails.dpdk.org (Postfix) with ESMTP id 181F540674 for ; Wed, 16 Oct 2024 22:24:06 +0200 (CEST) Received: by mail-pl1-f175.google.com with SMTP id d9443c01a7336-20c6f492d2dso2755225ad.0 for ; Wed, 16 Oct 2024 13:24:06 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=networkplumber-org.20230601.gappssmtp.com; s=20230601; t=1729110245; x=1729715045; darn=dpdk.org; h=content-transfer-encoding:mime-version:references:in-reply-to :message-id:date:subject:cc:to:from:from:to:cc:subject:date :message-id:reply-to; bh=0cjDjbvC8HxZYhR6sTFrBHgo0ziQMm8yJHHewnTyxx0=; b=Ois396dB19jdyUUK6Yq91gjx8fLlKEdbWYGqwT5+EiD83y9eEO0wFuEDeqjT34fjvC CHPnAQNQ4BX7ROgbc7AqbN2A9tphjXHM2mKPPhumM1enTcSu0sC8VY2hSx+NTphTPAhA WU/OUe0b45rZiJtCXC1baYthBiay+DkvciD37CcS4dZ4ivyB5tuBjHQQ95c9b2XDkMTI mACFpamoV73EA9Z4HIIDhvUrsZdVBA8uXEssj9AQ53ydkLQdbcIidvT9ab1KCsC+kfPK RwFe6iiPNQ5x1raaRmte7ABOQu1U8dwIsxS+A+BGVZKDqg1byizuo42wvLappLmgdZsN iXYA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1729110245; x=1729715045; h=content-transfer-encoding:mime-version:references:in-reply-to :message-id:date:subject:cc:to:from:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=0cjDjbvC8HxZYhR6sTFrBHgo0ziQMm8yJHHewnTyxx0=; b=i7H9mIYjVx7LdZnw4SYlRF0hTLiASjGHMFcwV3+ucMficU0Pj+YeYU8EYIak69KJ8x VVGWI3738CdmxBlvAoL+BwhWjWvyCzxWHo2NyDf5ZArGNerma7PmvepWOE7FvNh6nlmq OHCnfp+ilaOa7B3KQ1pTDCFHRUg2DRlWQZFbTDNZZWh7ehsWUuy+NKgBB4FHdTXY/djO w0aefCcJ8tNQ7lQ03J6Zh311XcZXd9X2Ex/lqk1cPOO+0z9dp5Naw87SdsQmtH5paYNv ttcQ1b4N08GIX3l9THrn5ru+E1w7e+2fVO5UeeaUUT3TzvQc0U4EZuOW39zHL7DZ1mKU 4wSg== X-Gm-Message-State: AOJu0YzHlsu8ttMyYGRcc7FDUCQCW2AwkDaXPnrNsUAy9xm7rw4LFESZ fmKhQFeri0bgm2UD8uYeOtVpuoqUyiwG2wX/BB78yxmoyynDBROiG2r/aMf2v6E5zK6uibiR/Ot j X-Google-Smtp-Source: AGHT+IEBIlOeDqiHKzQ8nhKsseI17Ax0VSWBUQ+aEqzJOKOfC8Q2gvhRYXE/jOp7kvIgOgwGqwefLA== X-Received: by 2002:a17:902:e882:b0:20b:bd8d:427c with SMTP id d9443c01a7336-20cbb1cbf7bmr252191735ad.23.1729110245071; Wed, 16 Oct 2024 13:24:05 -0700 (PDT) Received: from hermes.local (204-195-96-226.wavecable.com. [204.195.96.226]) by smtp.gmail.com with ESMTPSA id d9443c01a7336-20d180361e5sm32308825ad.120.2024.10.16.13.24.04 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 16 Oct 2024 13:24:04 -0700 (PDT) From: Stephen Hemminger To: dev@dpdk.org Cc: Stephen Hemminger , =?UTF-8?q?Morten=20Br=C3=B8rup?= , Bruce Richardson , Tyler Retzlaff , Dmitry Kozlyuk , Pallavi Kadam Subject: [PATCH v26 11/15] log: add timestamp option Date: Wed, 16 Oct 2024 13:20:38 -0700 Message-ID: <20241016202343.190653-12-stephen@networkplumber.org> X-Mailer: git-send-email 2.45.2 In-Reply-To: <20241016202343.190653-1-stephen@networkplumber.org> References: <20200814173441.23086-1-stephen@networkplumber.org> <20241016202343.190653-1-stephen@networkplumber.org> MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-BeenThere: dev@dpdk.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: DPDK patches and discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: dev-bounces@dpdk.org 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 (when first step of logging initialization is done by constructor). Other alternative formats are delta, ctime, reltime and iso formats. Example: $ dpdk-testpmd --log-timestamp -- -i [ 0.008610] EAL: Detected CPU lcores: 8 [ 0.008634] EAL: Detected NUMA nodes: 1 [ 0.008792] EAL: Detected static linkage of DPDK [ 0.010620] EAL: Multi-process socket /var/run/dpdk/rte/mp_socket [ 0.012618] EAL: Selected IOVA mode 'VA' [ 0.016675] testpmd: No probed ethernet devices Interactive-mode selected Signed-off-by: Stephen Hemminger Acked-by: Morten Brørup Acked-by: Bruce Richardson --- app/test/test_eal_flags.c | 26 +++ doc/guides/prog_guide/log_lib.rst | 26 +++ lib/eal/common/eal_common_options.c | 14 +- lib/eal/common/eal_options.h | 2 + lib/eal/freebsd/eal.c | 6 +- lib/eal/linux/eal.c | 4 +- lib/eal/windows/eal.c | 4 +- lib/log/log.c | 7 +- lib/log/log_internal.h | 9 ++ lib/log/log_private.h | 11 ++ lib/log/log_timestamp.c | 240 ++++++++++++++++++++++++++++ lib/log/meson.build | 6 +- lib/log/version.map | 1 + 13 files changed, 348 insertions(+), 8 deletions(-) create mode 100644 lib/log/log_timestamp.c diff --git a/app/test/test_eal_flags.c b/app/test/test_eal_flags.c index a5c0c67357..40dd288d5f 100644 --- a/app/test/test_eal_flags.c +++ b/app/test/test_eal_flags.c @@ -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); diff --git a/doc/guides/prog_guide/log_lib.rst b/doc/guides/prog_guide/log_lib.rst index ff9d1b54a2..504eefe1d2 100644 --- a/doc/guides/prog_guide/log_lib.rst +++ b/doc/guides/prog_guide/log_lib.rst @@ -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 ------------------------------------------- diff --git a/lib/eal/common/eal_common_options.c b/lib/eal/common/eal_common_options.c index ea45c79d5c..ec3b5c3dfd 100644 --- a/lib/eal/common/eal_common_options.c +++ b/lib/eal/common/eal_common_options.c @@ -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"=:\n" " Set specific log level\n" " --"OPT_LOG_LEVEL"=help Show log types and levels\n" + " --"OPT_LOG_TIMESTAMP"[=] Timestamp log output\n" #ifndef RTE_EXEC_ENV_WINDOWS " --"OPT_TRACE"=\n" " Enable trace based on regular expression trace name.\n" diff --git a/lib/eal/common/eal_options.h b/lib/eal/common/eal_options.h index f3f2e104f6..e24c9eca53 100644 --- a/lib/eal/common/eal_options.h +++ b/lib/eal/common/eal_options.h @@ -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" diff --git a/lib/eal/freebsd/eal.c b/lib/eal/freebsd/eal.c index 118c1f593b..06bccbd026 100644 --- a/lib/eal/freebsd/eal.c +++ b/lib/eal/freebsd/eal.c @@ -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); diff --git a/lib/eal/linux/eal.c b/lib/eal/linux/eal.c index 62d3d281c4..cf2f0fcab9 100644 --- a/lib/eal/linux/eal.c +++ b/lib/eal/linux/eal.c @@ -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); diff --git a/lib/eal/windows/eal.c b/lib/eal/windows/eal.c index c9648b7da7..0fda2abb97 100644 --- a/lib/eal/windows/eal.c +++ b/lib/eal/windows/eal.c @@ -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); diff --git a/lib/log/log.c b/lib/log/log.c index 48543ee941..6ab856272c 100644 --- a/lib/log/log.c +++ b/lib/log/log.c @@ -21,7 +21,7 @@ #include "log_private.h" #ifdef RTE_EXEC_ENV_WINDOWS -#define strdup _strdup +#include #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"); diff --git a/lib/log/log_internal.h b/lib/log/log_internal.h index 3c46328e7b..7c7d44eed2 100644 --- a/lib/log/log_internal.h +++ b/lib/log/log_internal.h @@ -5,8 +5,10 @@ #ifndef LOG_INTERNAL_H #define LOG_INTERNAL_H +#include #include #include +#include #include @@ -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 */ diff --git a/lib/log/log_private.h b/lib/log/log_private.h index 67d2463b2f..67cfe72fc6 100644 --- a/lib/log/log_private.h +++ b/lib/log/log_private.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 */ diff --git a/lib/log/log_timestamp.c b/lib/log/log_timestamp.c new file mode 100644 index 0000000000..b4b0bca6a8 --- /dev/null +++ b/lib/log/log_timestamp.c @@ -0,0 +1,240 @@ +/* SPDX-License-Identifier: BSD-3-Clause */ + +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include +#include + +#ifdef RTE_EXEC_ENV_WINDOWS +#include +#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); +} diff --git a/lib/log/meson.build b/lib/log/meson.build index 891f77a237..04235f6ee5 100644 --- a/lib/log/meson.build +++ b/lib/log/meson.build @@ -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') diff --git a/lib/log/version.map b/lib/log/version.map index a0341196d4..155f8b3bbe 100644 --- a/lib/log/version.map +++ b/lib/log/version.map @@ -30,5 +30,6 @@ INTERNAL { eal_log_save_pattern; eal_log_save_regexp; eal_log_syslog; + eal_log_timestamp; rte_eal_log_cleanup; }; -- 2.45.2