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 2C07142D5F; Mon, 26 Jun 2023 20:43:26 +0200 (CEST) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id ACBC342D2F; Mon, 26 Jun 2023 20:42:59 +0200 (CEST) Received: from mail-pj1-f51.google.com (mail-pj1-f51.google.com [209.85.216.51]) by mails.dpdk.org (Postfix) with ESMTP id D447C42D0C for ; Mon, 26 Jun 2023 20:42:56 +0200 (CEST) Received: by mail-pj1-f51.google.com with SMTP id 98e67ed59e1d1-262c6718d14so742169a91.2 for ; Mon, 26 Jun 2023 11:42:56 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=networkplumber-org.20221208.gappssmtp.com; s=20221208; t=1687804976; x=1690396976; 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=wMqTqBB9Kct1SM96bVI30Qu0Qv4SGifI7jxxJhBYRgo=; b=ljxsaqScTFbh/HDBEEulqjK9YVC2IFJPCiakV57yEwBNfrW0H9Kae8YljdcPMxWDn0 +sy77wrxF9Nz0kUEQSEShICn+bjHR1KxciUu6biqfZGoN/Z0EWuCZjXz8d4lnh3m8ewV V1Si0OpGNRJyoYZ6dKe5w3PWyJhNhjDVCor88JIfV3hlGlC6MJ5Z9S1IPPGRZ9Vhcw1S XUWct4VEklva95/J+NGsJJ97wTC1rNIAKb6S5vGu5gZqi7/dE0GcdFg/KAC9QgVLm8Cl pncOjzb2sArKCA1lZe8S9fL7v23ykuKoO569x216sqX5PZ16XhM2+WdVrc6BEAMzU6jZ YeNg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20221208; t=1687804976; x=1690396976; 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=wMqTqBB9Kct1SM96bVI30Qu0Qv4SGifI7jxxJhBYRgo=; b=Sw+DJAvU58Uc3Tftl8fccwiW7dbkY9GIq1sD/iROq4OnwK78eLKuA2HTCt59e5NM0A SDuxu3nEF5yOv3SmVzCXWu5ChJyDj9pagGdG0+3t6sV4HxpyfT7ihtXQ/8K8piD/cCRB 4SPe/Zz52NVJrRZkFVvoqW7zjdzgheKOmTRWJYoZnSagu7vjC58J2QQ3b0uQU4n7BHDl 69ND1w1tpmgnBTw8KREHyWbuRyt5YjNvzzOpCw/jCCosNecFc+HFXo5HogGwwHl87uIC FO6ibHMsUu7B04r8zVEAcC2oyMN3bYDxGDe1jxlWUxNmdxQcZBjPAMq2+A9hXLtBRRjg +P3w== X-Gm-Message-State: AC+VfDwcwan+2wvJo1SKpQdJknVQ93u7Dm8ee0wa43zYdaa3LVT1Hra6 EQgh8/BG7CkvfKFQCoOjU1YymwgQOgAOFfTlBOISRA== X-Google-Smtp-Source: ACHHUZ6NEPe4CcGoE+pdJ9FCylO0GQ/raJj8FiEREMurNsdy20UMwBWJ7vosrLjaLkx6bH1Hrwz0vA== X-Received: by 2002:a17:90a:19ca:b0:261:3202:3c4e with SMTP id 10-20020a17090a19ca00b0026132023c4emr6682108pjj.25.1687804975760; Mon, 26 Jun 2023 11:42:55 -0700 (PDT) Received: from hermes.local (204-195-120-218.wavecable.com. [204.195.120.218]) by smtp.gmail.com with ESMTPSA id h17-20020a17090adb9100b0024e37e0a67dsm4846577pjv.20.2023.06.26.11.42.54 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 26 Jun 2023 11:42:55 -0700 (PDT) From: Stephen Hemminger To: dev@dpdk.org Cc: Stephen Hemminger , Bruce Richardson Subject: [PATCH v4 5/5] eal: add option to put timestamp on console output Date: Mon, 26 Jun 2023 11:42:16 -0700 Message-Id: <20230626184223.155390-6-stephen@networkplumber.org> X-Mailer: git-send-email 2.39.2 In-Reply-To: <20230626184223.155390-1-stephen@networkplumber.org> References: <20200814173441.23086-1-stephen@networkplumber.org> <20230626184223.155390-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. Example: $ dpdk-testpmd --log-timestamp -- -i [ 0.007615] EAL: Detected CPU lcores: 16 [ 0.007657] EAL: Detected NUMA nodes: 1 [ 0.007878] EAL: Detected static linkage of DPDK [ 0.009469] EAL: Multi-process socket /var/run/dpdk/rte/mp_socket [ 0.012175] EAL: Selected IOVA mode 'VA' [ 0.120016] testpmd: No probed ethernet devices Interactive-mode selected [ 0.155959] testpmd: create a new mbuf pool : n=267456, size=2176, socket=0 [ 0.155990] testpmd: preferred mempool ops selected: ring_mp_mc Signed-off-by: Stephen Hemminger --- .../freebsd_gsg/freebsd_eal_parameters.rst | 5 +++ doc/guides/linux_gsg/linux_eal_parameters.rst | 5 +++ lib/eal/common/eal_common_options.c | 6 ++++ lib/eal/common/eal_internal_cfg.h | 3 ++ lib/eal/common/eal_options.h | 2 ++ lib/eal/freebsd/eal.c | 4 ++- lib/eal/linux/eal.c | 4 ++- lib/eal/unix/eal_log.c | 36 +++++++++++++++++-- 8 files changed, 61 insertions(+), 4 deletions(-) diff --git a/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst b/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst index 9270d9fa3bfc..99cff10e963c 100644 --- a/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst +++ b/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst @@ -45,3 +45,8 @@ Other options local5 local6 local7 + +* ``--log-timestamp`` + + Add a timestamp of seconds and microseconds to each log message + written to standard output. diff --git a/doc/guides/linux_gsg/linux_eal_parameters.rst b/doc/guides/linux_gsg/linux_eal_parameters.rst index ea8f38139119..719ca6851625 100644 --- a/doc/guides/linux_gsg/linux_eal_parameters.rst +++ b/doc/guides/linux_gsg/linux_eal_parameters.rst @@ -135,3 +135,8 @@ Other options local5 local6 local7 + +* ``--log-timestamp`` + + Add a timestamp of seconds and microseconds to each log message + written to standard output. diff --git a/lib/eal/common/eal_common_options.c b/lib/eal/common/eal_common_options.c index 03059336987d..c6c74cc31e9c 100644 --- a/lib/eal/common/eal_common_options.c +++ b/lib/eal/common/eal_common_options.c @@ -76,6 +76,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 }, @@ -1835,6 +1836,10 @@ eal_parse_common_option(int opt, const char *optarg, } #ifndef RTE_EXEC_ENV_WINDOWS + case OPT_LOG_TIMESTAMP_NUM: + conf->log_timestamp = 1; + break; + case OPT_TRACE_NUM: { if (eal_trace_args_save(optarg) < 0) { RTE_LOG(ERR, EAL, "invalid parameters for --" @@ -2194,6 +2199,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_internal_cfg.h b/lib/eal/common/eal_internal_cfg.h index 167ec501fa79..1a1a7fdcfa8c 100644 --- a/lib/eal/common/eal_internal_cfg.h +++ b/lib/eal/common/eal_internal_cfg.h @@ -84,7 +84,10 @@ struct internal_config { /**< true if storing all pages within single files (per-page-size, * per-node) non-legacy mode only. */ + volatile uint8_t log_timestamp; /**< add timestamp to console output */ volatile int syslog_facility; /**< facility passed to openlog() */ + struct timespec log_start_time; /**< when logging was started */ + /** default interrupt mode for VFIO */ volatile enum rte_intr_mode vfio_intr_mode; /** the shared VF token for VFIO-PCI bound PF and VFs devices */ diff --git a/lib/eal/common/eal_options.h b/lib/eal/common/eal_options.h index 3cc9cb641284..cc9723868e3c 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 d3aac3d628a8..5c7cea8809bd 100644 --- a/lib/eal/freebsd/eal.c +++ b/lib/eal/freebsd/eal.c @@ -388,6 +388,7 @@ eal_log_level_parse(int argc, char **argv) switch (opt) { case OPT_SYSLOG_NUM: /* fallthrough */ + case OPT_LOG_TIMESTAMP_NUM: /* fallthrough */ case OPT_LOG_LEVEL_NUM: if (eal_parse_common_option(opt, optarg, internal_conf) < 0) goto error; @@ -436,7 +437,8 @@ eal_parse_args(int argc, char **argv) } /* eal_log_level_parse() already handled these */ - if (opt == OPT_LOG_LEVEL_NUM || opt == OPT_SYSLOG_NUM) + if (opt == OPT_SYSLOG_NUM || + opt == OPT_LOG_TIMESTAMP_NUM || opt == OPT_LOG_LEVEL_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 51c4ec75d57b..051f9ad7f5bf 100644 --- a/lib/eal/linux/eal.c +++ b/lib/eal/linux/eal.c @@ -568,6 +568,7 @@ eal_log_level_parse(int argc, char **argv) switch (opt) { case OPT_SYSLOG_NUM: /* fallthrough */ + case OPT_LOG_TIMESTAMP_NUM: /* fallthrough */ case OPT_LOG_LEVEL_NUM: if (eal_parse_common_option(opt, optarg, internal_conf) < 0) goto error; @@ -650,7 +651,8 @@ eal_parse_args(int argc, char **argv) } /* eal_log_level_parse() already handled these */ - if (opt == OPT_LOG_LEVEL_NUM || opt == OPT_SYSLOG_NUM) + if (opt == OPT_SYSLOG_NUM || + opt == OPT_LOG_TIMESTAMP_NUM || opt == OPT_LOG_LEVEL_NUM) continue; ret = eal_parse_common_option(opt, optarg, internal_conf); diff --git a/lib/eal/unix/eal_log.c b/lib/eal/unix/eal_log.c index baa721021991..f65a22612310 100644 --- a/lib/eal/unix/eal_log.c +++ b/lib/eal/unix/eal_log.c @@ -4,12 +4,15 @@ #include #include +#include #include +#include #include #include #include "eal_log.h" +#include "eal_private.h" /* * default log function @@ -17,10 +20,36 @@ static ssize_t console_log_write(__rte_unused void *c, const char *buf, size_t size) { + const struct internal_config *internal_conf = eal_get_internal_configuration(); ssize_t ret; - /* write on stderr */ - ret = write(STDERR_FILENO, buf, size); + /* add optional timestamp for stderr */ + if (internal_conf->log_timestamp) { + struct iovec iov[2]; + struct timespec ts; + char tbuf[64]; + + /* format up monotonic timestamp */ + clock_gettime(CLOCK_MONOTONIC, &ts); + ts.tv_sec -= internal_conf->log_start_time.tv_sec; + ts.tv_nsec -= internal_conf->log_start_time.tv_nsec; + if (ts.tv_nsec < 0) { + --ts.tv_sec; + ts.tv_nsec += 1000000000ul; + } + + /* use writev to put timestamp and buf in single operation */ + iov[0].iov_base = tbuf; + iov[0].iov_len = snprintf(tbuf, sizeof(tbuf), "[%8lu.%06lu] ", + ts.tv_sec, ts.tv_nsec / 1000u); + + /* casts are to unconstify the buf */ + iov[1].iov_base = (void *)(uintptr_t)buf; + iov[1].iov_len = size; + ret = writev(STDERR_FILENO, iov, 2); + } else { + ret = write(STDERR_FILENO, buf, size); + } /* Syslog error levels are from 0 to 7, so subtract 1 to convert */ syslog(rte_log_cur_msg_loglevel() - 1, "%.*s", (int)size, buf); @@ -47,8 +76,11 @@ static cookie_io_functions_t console_log_func = { int eal_log_init(const char *id, int facility) { + struct internal_config *internal_conf = eal_get_internal_configuration(); FILE *log_stream; + clock_gettime(CLOCK_MONOTONIC, &internal_conf->log_start_time); + log_stream = fopencookie(NULL, "w+", console_log_func); if (log_stream == NULL) return -1; -- 2.39.2