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 03CFE43CE8; Mon, 18 Mar 2024 19:33:15 +0100 (CET) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id 32F0B40A79; Mon, 18 Mar 2024 19:32:53 +0100 (CET) Received: from mail-pf1-f177.google.com (mail-pf1-f177.google.com [209.85.210.177]) by mails.dpdk.org (Postfix) with ESMTP id 5D72E406A2 for ; Mon, 18 Mar 2024 19:32:48 +0100 (CET) Received: by mail-pf1-f177.google.com with SMTP id d2e1a72fcca58-6e6ca2ac094so4266147b3a.0 for ; Mon, 18 Mar 2024 11:32:48 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=networkplumber-org.20230601.gappssmtp.com; s=20230601; t=1710786767; x=1711391567; 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=mm+yD9goF61yhxXIeT7u6e0EGZS37olmLkVeOSQvEYg=; b=VVawW5vydty+MDUacFMppxrfCQyct94gJpc3HxCgBxnfFKE3skNSsj9i4Z551587/W XpPWLwDmkTHi9+xsE6mTgytBhIaASD4laIlZAN++eHjX2m3a+/Qkg2k+VSwyJVWDXmiM OBNVO9QGrJ8Oi9QyInFV6X3hPUVZjWpdzjpqEko2tOHmOEnUH9RWk4szQiIgO0wvo9yp FS+u4oOkkLFdHFcL9AqjEAX2AAVwtKwXqK2ZU0gMN0mliCTOKuOGxaMrwc0uV1tg8aUz 9xUwXAKsvK2yf879MaGZcJQ9SR3Iqz6g0tmlQZtH1aWHgOuPDEHiXhg6Ei2Wu7Db4QUo 5/OQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1710786767; x=1711391567; 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=mm+yD9goF61yhxXIeT7u6e0EGZS37olmLkVeOSQvEYg=; b=pwjrhUkOc/J+fjazZaRlg3WBlSo/tIp+3dqdAlzm2NmwnKJhZOGtj6Mue3B1LB46uB 61aGO4nJaLHQAkukrcBFIvz523J6+mQLUeoCK1GRiL0miJ1i5n07ljxyabYxYEfuU7qZ GkuUhaaXz9/UmrikXREstLtH9UHpIXWUZhvsrH1jqMG/rjXh7KfGnPH4uQKCXIWN6XQI cAUwb7DP+wWoMH3mLoVr2xGOrEHb0/Qz54jE5vpi/9NxMkCOLS7DU4K5RCqDLEcVDePM TBo/Q6SPV9wro2d00UpTU+cO2Am3oV+kE0s4KIydexsrCfkTlf3DJgXW2JnnUCWfLrnV 3hIg== X-Gm-Message-State: AOJu0YwzeL97ZOLgH8FUN6xVCH+J7U3QGmPIvm5babf2CvvckdmipplV 9CfkqIOHCbyRFdBXneDE8CCH15WdT13CHnVACEBGqu3hYPNdzG0anDGaDabGXnzPINYmQz8BTtw X X-Google-Smtp-Source: AGHT+IEBNJNHMiSovK/hg/kCczFPji7pZ86SRmPGD/2RMJauqxYFCXlNg+ci69QVNIh/BiWqmzUz6Q== X-Received: by 2002:a05:6a00:3d4d:b0:6e6:269d:1a38 with SMTP id lp13-20020a056a003d4d00b006e6269d1a38mr569673pfb.25.1710786767527; Mon, 18 Mar 2024 11:32:47 -0700 (PDT) Received: from hermes.local (204-195-123-141.wavecable.com. [204.195.123.141]) by smtp.gmail.com with ESMTPSA id x6-20020aa784c6000000b006e4e93f4f17sm8186593pfn.117.2024.03.18.11.32.46 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 18 Mar 2024 11:32:46 -0700 (PDT) From: Stephen Hemminger To: dev@dpdk.org Cc: Stephen Hemminger Subject: [PATCH v8 4/5] eal: add option to put timestamp on console output Date: Mon, 18 Mar 2024 11:30:05 -0700 Message-ID: <20240318183233.142330-5-stephen@networkplumber.org> X-Mailer: git-send-email 2.43.0 In-Reply-To: <20240318183233.142330-1-stephen@networkplumber.org> References: <20200814173441.23086-1-stephen@networkplumber.org> <20240318183233.142330-1-stephen@networkplumber.org> MIME-Version: 1.0 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. The timestamp format is chosen to look like the default Linux dmesg timestamp. The first few lines are not timestamped because the flag is stored in internal configuration which is stored in shared memory which is not setup up until a little later in startup process. This logging skips the unnecessary step of going through stdio, which makes it more robust against being called in interrupt handlers etc. Example: $ dpdk-testpmd --log-timestamp -- -i EAL: Detected CPU lcores: 16 EAL: Detected NUMA nodes: 1 EAL: Detected static linkage of DPDK EAL: Multi-process socket /var/run/dpdk/rte/mp_socket EAL: Selected IOVA mode 'VA' [ 0.112264] testpmd: No probed ethernet devices Interactive-mode selected [ 0.184573] testpmd: create a new mbuf pool : n=163456, size=2176, socket=0 [ 0.184612] testpmd: preferred mempool ops selected: ring_mp_mc Signed-off-by: Stephen Hemminger --- app/test/test_eal_flags.c | 9 ++++++++ doc/guides/prog_guide/log_lib.rst | 10 +++++++++ lib/eal/common/eal_common_options.c | 10 +++++++-- lib/eal/common/eal_options.h | 2 ++ lib/log/log_internal.h | 9 ++++++++ lib/log/log_unix.c | 32 +++++++++++++++++++++++++++-- lib/log/log_windows.c | 6 ++++++ lib/log/version.map | 1 + 8 files changed, 75 insertions(+), 4 deletions(-) diff --git a/app/test/test_eal_flags.c b/app/test/test_eal_flags.c index 6cb4b0675730..07a038fb6051 100644 --- a/app/test/test_eal_flags.c +++ b/app/test/test_eal_flags.c @@ -1055,6 +1055,10 @@ 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" }; + /* run all tests also applicable to FreeBSD first */ if (launch_proc(argv0) == 0) { @@ -1162,6 +1166,11 @@ 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; + } + 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 aacb36c36ce0..1d6b2e3cea5d 100644 --- a/doc/guides/prog_guide/log_lib.rst +++ b/doc/guides/prog_guide/log_lib.rst @@ -73,6 +73,16 @@ For example:: /path/to/app --syslog local0 +Console timestamp +~~~~~~~~~~~~~~~~~ + +On Linux and FreeBSD, 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 + + 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 7310d10dfd78..9bc95433d27c 100644 --- a/lib/eal/common/eal_common_options.c +++ b/lib/eal/common/eal_common_options.c @@ -77,6 +77,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, 0, 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 }, @@ -1663,6 +1664,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; @@ -1890,7 +1892,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 --" @@ -1898,7 +1900,10 @@ eal_parse_common_option(int opt, const char *optarg, return -1; } break; - } + + case OPT_LOG_TIMESTAMP_NUM: + eal_log_enable_timestamp(); + break; #ifndef RTE_EXEC_ENV_WINDOWS case OPT_TRACE_NUM: { @@ -2261,6 +2266,7 @@ eal_common_usage(void) " --"OPT_PROC_TYPE" Type of this process (primary|secondary|auto)\n" #ifndef RTE_EXEC_ENV_WINDOWS " --"OPT_SYSLOG" Set syslog facility\n" + " --"OPT_LOG_TIMESTAMP" Timestamp log output\n" #endif " --"OPT_LOG_LEVEL"= Set global log level\n" " --"OPT_LOG_LEVEL"=:\n" diff --git a/lib/eal/common/eal_options.h b/lib/eal/common/eal_options.h index f3f2e104f6d7..e24c9eca53ca 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_internal.h b/lib/log/log_internal.h index c77e687e28bc..1af27fe8f9d3 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 @@ -44,4 +46,11 @@ const char *eal_log_level2str(uint32_t level); __rte_internal void rte_eal_log_cleanup(void); +/* + * Add timestamp to console logs + */ +__rte_internal +void eal_log_enable_timestamp(void); + + #endif /* LOG_INTERNAL_H */ diff --git a/lib/log/log_unix.c b/lib/log/log_unix.c index a415bae5774d..71ce366b6825 100644 --- a/lib/log/log_unix.c +++ b/lib/log/log_unix.c @@ -2,24 +2,52 @@ * Copyright(c) 2010-2014 Intel Corporation */ +#include #include #include +#include #include +#include +#include #include #include "log_internal.h" +static bool timestamp_enabled; +static struct timespec log_started; + +void +eal_log_enable_timestamp(void) +{ + timestamp_enabled = true; + clock_gettime(CLOCK_MONOTONIC, &log_started); +} + /* * default log function */ static ssize_t console_log_write(__rte_unused void *c, const char *buf, size_t size) { + struct timespec ts; ssize_t ret; - /* write on stderr */ - ret = fwrite(buf, 1, size, stderr); + if (timestamp_enabled) { + clock_gettime(CLOCK_MONOTONIC, &ts); + ts.tv_sec -= log_started.tv_sec; + ts.tv_nsec -= log_started.tv_nsec; + if (ts.tv_nsec < 0) { + --ts.tv_sec; + ts.tv_nsec += 1000000000ul; + } + + ret = fprintf(stderr, "[%8lu.%06lu] %.*s", + ts.tv_sec, ts.tv_nsec / 1000u, + (int) size, buf); + } else { + ret = fwrite(buf, 1, size, stderr); + } fflush(stderr); /* Syslog error levels are from 0 to 7, so subtract 1 to convert */ diff --git a/lib/log/log_windows.c b/lib/log/log_windows.c index a6a08895501e..0c471bfb15f6 100644 --- a/lib/log/log_windows.c +++ b/lib/log/log_windows.c @@ -6,6 +6,12 @@ #include #include "log_internal.h" +void +eal_log_enable_timestamp(void) +{ + /* not implemented */ +} + /* set the log to default function, called during eal init process. */ int eal_log_init(__rte_unused const char *id, __rte_unused int facility) diff --git a/lib/log/version.map b/lib/log/version.map index 6ecc656d1d65..32c555f29e79 100644 --- a/lib/log/version.map +++ b/lib/log/version.map @@ -25,6 +25,7 @@ DPDK_24 { INTERNAL { global: + eal_log_enable_timestamp; eal_log_get_default; eal_log_init; eal_log_level2str; -- 2.43.0