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 2A54F43D4E; Tue, 26 Mar 2024 02:59:41 +0100 (CET) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id 74C8640EDF; Tue, 26 Mar 2024 02:58:56 +0100 (CET) Received: from mail-pl1-f180.google.com (mail-pl1-f180.google.com [209.85.214.180]) by mails.dpdk.org (Postfix) with ESMTP id 5F30D40E25 for ; Tue, 26 Mar 2024 02:58:49 +0100 (CET) Received: by mail-pl1-f180.google.com with SMTP id d9443c01a7336-1dddbe47ac1so37762175ad.1 for ; Mon, 25 Mar 2024 18:58:49 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=networkplumber-org.20230601.gappssmtp.com; s=20230601; t=1711418328; x=1712023128; 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=5NEetilwhR4Q/D6gAt1h7WlScvJ3pu4XZM/NJM6EmTI=; b=HTvAKaXHP663vyaiB/sgwhHz2DOm0if3mtv1R301OpNSIQ25KE4WoBqw3Fgt8oFH9P Xe0t5LE5257w3vJCZ1/bs/EeZabk54XcRvtAPL+LnA1eKzS9CcHSwbt6kJ33Z+m4F7F7 UmGii06bqWMz5XCp3lTuP40JFWHBg3E6MIDLeXZjRCXLIbwdxGaNcasGShBRVkS0eXmC C2K7QLHCX/terDtR/cQVEpKtRfKQKT7Xv99Gfx/4QvhhZXg9+20/FxwCmaAAxRikSXUd R0//fpT8hCrEdwys+MlvVf+22jOEiO9y6rpJlWpf5sxIpH9jzD29IM1SPPxGNmI2gp3b DhzA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1711418328; x=1712023128; 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=5NEetilwhR4Q/D6gAt1h7WlScvJ3pu4XZM/NJM6EmTI=; b=KnrLNx2h/tukz/JqLKcVF93yEemOzTbKYILY4MYwFK7TSdKm6/u+yu/zMwmQLwjBRz EHRWeMpjj5s2cH9/oxvsU4z9D0ZXAWPAM3rdagjQjjqvHCAvZwLXg3a16/OgcUOVWcbF e2d81yeeLWFA96j4B91oXB1Q8dH1PxteKPD+AtafGntCzjMWoEQNMeWI8f+92yOADYYF GOWxYYaKxkrH0dN+ERt0BzcW30Ys/mPpG3kdo2d3ZSSVyUYDL/M6Ub/oMlKu1uWb1N2d 7KzocO3oydUxKHExTs63J/AdeiaqxE1WEJOIywWn6Xn5mj4VhDtPzmmBm4swZKjz/4lL 7rxA== X-Gm-Message-State: AOJu0YywwY0CPX9h0xbWu1cz7rjbMenoL+UngWLLNA2rxom67ga0OSnk MVWcwMEyIjHHTrhyQBo6tJvO1jt18BlszPweUuNdVzSnCHKL4TRWIgVt0OJYpWH6EiPku/ThJBq u X-Google-Smtp-Source: AGHT+IFUaxQgK7VgjZwrNYIrp08nTcpS6sEIF8V/NM2V1apEamzJgyQwUxQbx8U0cpfaDxNvuvlvxw== X-Received: by 2002:a17:902:c451:b0:1dd:dcd3:662c with SMTP id m17-20020a170902c45100b001dddcd3662cmr149369plm.4.1711418328480; Mon, 25 Mar 2024 18:58:48 -0700 (PDT) Received: from hermes.local (204-195-123-203.wavecable.com. [204.195.123.203]) by smtp.gmail.com with ESMTPSA id u19-20020a63d353000000b005dc88b232a5sm6571541pgi.26.2024.03.25.18.58.47 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 25 Mar 2024 18:58:48 -0700 (PDT) From: Stephen Hemminger To: dev@dpdk.org Cc: Stephen Hemminger , Bruce Richardson , Dmitry Kozlyuk , Tyler Retzlaff , Pallavi Kadam Subject: [PATCH v13 10/11] log: add timestamp option Date: Mon, 25 Mar 2024 18:57:05 -0700 Message-ID: <20240326015827.825648-11-stephen@networkplumber.org> X-Mailer: git-send-email 2.43.0 In-Reply-To: <20240326015827.825648-1-stephen@networkplumber.org> References: <20200814173441.23086-1-stephen@networkplumber.org> <20240326015827.825648-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 --- 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 | 183 +++++++++++++++++++++++++++- lib/log/log_internal.h | 9 ++ lib/log/version.map | 1 + 10 files changed, 268 insertions(+), 7 deletions(-) diff --git a/app/test/test_eal_flags.c b/app/test/test_eal_flags.c index 36e3185a10..e54f6e8b7f 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 9ab512e8a1..5173835c2c 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; @@ -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"=:\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 55ff27a4da..662a829ce8 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 b9a0fb1742..8cbea480e0 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 74b3ece30c..4283c920c8 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 acd4c320b6..2dca91306e 100644 --- a/lib/log/log.c +++ b/lib/log/log.c @@ -11,6 +11,7 @@ #include #include #include +#include #include #include @@ -18,7 +19,7 @@ #include "log_internal.h" #ifdef RTE_EXEC_ENV_WINDOWS -#define strdup _strdup +#include #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 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/version.map b/lib/log/version.map index 32b9680c31..14d6681a5f 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.43.0