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 21CD143D36; Sun, 24 Mar 2024 03:42:15 +0100 (CET) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id D1D764069F; Sun, 24 Mar 2024 03:41:32 +0100 (CET) Received: from mail-pj1-f53.google.com (mail-pj1-f53.google.com [209.85.216.53]) by mails.dpdk.org (Postfix) with ESMTP id B58B2402EC for ; Sun, 24 Mar 2024 03:41:26 +0100 (CET) Received: by mail-pj1-f53.google.com with SMTP id 98e67ed59e1d1-29de4c33441so2337750a91.1 for ; Sat, 23 Mar 2024 19:41:26 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=networkplumber-org.20230601.gappssmtp.com; s=20230601; t=1711248086; x=1711852886; 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=KMFs2nnZQjuUChC7i9aa4h6YtbRdRwzjMnZM5qcjWqY=; b=U2N5SLEK+6Q5gVCOzH2HwAomBMst83XK6/5F0ph8Zaa9X/jpbWu3JFtT4ZZ7htznfJ JOycA3Rha5uhT8hZ6bbNcLhKDVN0Y9rVae5c1onpL2OOsLBAene2vVf1ovhmIUAUzIam 6W61R5EGEnuM4E6fvb7Er3my9MniE4GYSWxPEnEDMpfmUsMjrPLCxYcQ4CvU8EBDGLKM Z9/vMTH9/icY5TuiNOKPbGGN7JX3Igci2VZqaNtZL/0kIn/wytee/uXTafBXnJpNVDeb lEC+sy8rxfn9O8MBhFZAcwQq7Wm460L1UI6Q2fvDn3aIknIMmZwXZAJrLYSnXtTpPGMI ZSoQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1711248086; x=1711852886; 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=KMFs2nnZQjuUChC7i9aa4h6YtbRdRwzjMnZM5qcjWqY=; b=bwmE/BXqhBVL+sCAkOpVO+CuC2Gpp9XzgVN4gGkABpL6birck2pjTYpi7mWtA0JVMC Q1uYCXx446wjOdbaI0Zqvub/s2+Emcham6oaPVMMLp8HafFPf1bJMxSYqx8PG5+zcFH+ P6zKKvS0MF5BQijaYGjaxfw/N9c7RuqjUlO0Di4fo8QtOnp2wjGqZaMbPYMd2CH6Ck7I uigSkG1vawg6XdR81+EmVp6H7DLaZdrFf7SYArra8qJsyoJHeysTpH9eXh1/hw/5gUVI pg9rq1Jhm8wfpb6rtvjCRC8xoe0YR4FmgqLruqzlYEgeWhNk8Lk01AEeoyGLXQDaqXa7 kJ4g== X-Gm-Message-State: AOJu0YwgKButONUkiJ9HsitisJA0nev5kkkIWnAwlQOf+BbNgz0lACBC UW0SVgj/c5wq/nKwzKzz+5UEEd8t1YYShnV+yJKW6cWl3qnTlWx14y4IP4FMN4qQha0pjg3c6rn F X-Google-Smtp-Source: AGHT+IH+gwzOM+SwucIHLDpTB1zs9pHHoGcuuo6q0q5Pu097fJB2KPNhwQbb7o0WduGQ490GLYpEKw== X-Received: by 2002:a05:6a20:7344:b0:1a3:c4ea:f528 with SMTP id v4-20020a056a20734400b001a3c4eaf528mr115537pzc.43.1711248085879; Sat, 23 Mar 2024 19:41:25 -0700 (PDT) Received: from hermes.local (204-195-123-203.wavecable.com. [204.195.123.203]) by smtp.gmail.com with ESMTPSA id q17-20020a17090311d100b001dc3c4e7a12sm2244980plh.14.2024.03.23.19.41.25 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sat, 23 Mar 2024 19:41:25 -0700 (PDT) From: Stephen Hemminger To: dev@dpdk.org Cc: Stephen Hemminger Subject: [PATCH v11 7/9] log: add timestamp option Date: Sat, 23 Mar 2024 19:33:29 -0700 Message-ID: <20240324024109.306614-8-stephen@networkplumber.org> X-Mailer: git-send-email 2.43.0 In-Reply-To: <20240324024109.306614-1-stephen@networkplumber.org> References: <20200814173441.23086-1-stephen@networkplumber.org> <20240324024109.306614-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 | 17 +++ doc/guides/prog_guide/log_lib.rst | 26 +++++ lib/eal/common/eal_common_options.c | 14 ++- lib/eal/common/eal_options.h | 2 + lib/log/log.c | 168 +++++++++++++++++++++++++++- lib/log/log_internal.h | 9 ++ lib/log/version.map | 1 + 7 files changed, 234 insertions(+), 3 deletions(-) diff --git a/app/test/test_eal_flags.c b/app/test/test_eal_flags.c index bea5465168..def74e34d5 100644 --- a/app/test/test_eal_flags.c +++ b/app/test/test_eal_flags.c @@ -1048,6 +1048,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) { @@ -1143,6 +1151,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 17ed8426b2..83949cce35 100644 --- a/doc/guides/prog_guide/log_lib.rst +++ b/doc/guides/prog_guide/log_lib.rst @@ -58,6 +58,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. +Console timestamp +~~~~~~~~~~~~~~~~~ + +An optional timestamp can be added before each message when printing on the console +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 73167d4603..bc6d87266d 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 }, @@ -1614,6 +1615,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; @@ -1831,7 +1833,7 @@ eal_parse_common_option(int opt, const char *optarg, } break; - case OPT_LOG_LEVEL_NUM: { + case OPT_LOG_LEVEL_NUM: if (eal_parse_log_level(optarg) < 0) { EAL_LOG(ERR, "invalid parameters for --" @@ -1839,7 +1841,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: { @@ -2204,6 +2213,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 6b204d6698..197b7b25ef 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/log/log.c b/lib/log/log.c index 4cc871911c..bd488dff1b 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,12 @@ 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 */ + struct tm last_tm; /* in local time format */ + size_t dynamic_types_len; struct rte_log_dynamic_type *dynamic_types; } rte_logs = { @@ -362,6 +378,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, @@ -513,6 +532,132 @@ rte_eal_log_cleanup(void) } } +/* 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 up a timestamp based on current format */ +static ssize_t +format_timestamp(char *tsbuf, size_t tsbuflen) +{ + struct timespec now, delta; + struct tm *tm; + + 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; + + tm = localtime(&now.tv_sec); + 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 != rte_logs +.last_tm.tm_min || + tm->tm_hour != rte_logs.last_tm.tm_hour || + tm->tm_yday != rte_logs.last_tm.tm_yday) { + rte_logs.last_tm = *tm; + return strftime(tsbuf, tsbuflen, "%b%d %H:%M", tm); + } else { + return snprintf(tsbuf, tsbuflen, "+%4lu.%06lu", + (unsigned long)delta.tv_sec, + (unsigned long)delta.tv_nsec / 1000u); + } + + 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: { + char dbuf[64]; /* "2024-05-01T22:11:00" */ + char zbuf[16]; /* "+0800" */ + + if (clock_gettime(CLOCK_REALTIME, &now) < 0) + return 0; + + tm = localtime(&now.tv_sec); + + /* 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 +HH:MM */ + if (strftime(zbuf, sizeof(zbuf), "%z", tm) == 0) + return 0; + /* insert : required in ISO */ + memmove(zbuf + 3, zbuf + 4, 2); + zbuf[3] = ':'; + zbuf[6] = '\0'; + + return snprintf(tsbuf, tsbuflen, "%s,%06lu%s", + dbuf, now.tv_nsec / 1000u, zbuf); + } + } + + return 0; +} + /* default log print function */ __rte_format_printf(3, 0) static int @@ -522,10 +667,31 @@ 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); +} + /* initialize logging */ void eal_log_init(const char *id __rte_unused) { + /* skip if user has already setup a log stream */ + if (rte_logs.file != NULL) + return; + + if (rte_logs.time_format != EAL_LOG_TIMESTAMP_NONE) + rte_logs.print_func = log_print_with_timestamp; + #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 4f1ffe999e..3544ae49ac 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 @@ -42,4 +44,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 0648f8831a..7fd5b39e3a 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_set_default; + eal_log_timestamp; rte_eal_log_cleanup; }; -- 2.43.0