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 0CF7B41DD9; Mon, 6 Mar 2023 19:18:34 +0100 (CET) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id D1DA941149; Mon, 6 Mar 2023 19:18:24 +0100 (CET) Received: from mail-pl1-f171.google.com (mail-pl1-f171.google.com [209.85.214.171]) by mails.dpdk.org (Postfix) with ESMTP id 1C3E740A8A for ; Mon, 6 Mar 2023 19:18:22 +0100 (CET) Received: by mail-pl1-f171.google.com with SMTP id u5so11375667plq.7 for ; Mon, 06 Mar 2023 10:18:22 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=networkplumber-org.20210112.gappssmtp.com; s=20210112; t=1678126701; 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=/d/WjqCMEOnIt0TYycMwgW8xLzHmROVJwJuuv/G46Cw=; b=Jb3TPScW4hjlmGQ7F2C2wyIAND69onOrNWZhig5s2Eh9sGvU9z6EkeoSD04FaDvf3Z 3S0I9pGMyGi/xcyCejQbZuBnjePFfbX9TOfoFDwkVTMyx1pAb+J+KjvJ2PGq8f5gNFPD op4FalHqE66S8XgUsd256x148ZD34quQE/zWACNyPD57wxmKTsZiMRIPTN7VCy4Nx3P3 faNGtH7egRVmuo87SnfKjUdEEx2jxefOKRs1L78S8asCK7TZNHogXpDsz0ms0pzk3mNv uC6rkehpeL7rqs5/Bj+sp3rHf4gZgb0naxc2Z2DTizt13SscweeIhDIwaoGOwJilXSHh oUlA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; t=1678126701; 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=/d/WjqCMEOnIt0TYycMwgW8xLzHmROVJwJuuv/G46Cw=; b=5miYq0Eyd/GD9cG88ZQSv7EKYTPrcLSz6OC35vy0uDMAUOhm1gWdVgsMYBa1WW242y 1ADJX1yKZbzZRkcn9uokH6XB6ZCoPucLx94Og7u3UbtL3NoiA1SNXjyoqBDlol4twmKs 7Jyzr4Uzjb2rmThGxmf5Ll7jTrWP4Qr/ucVNVsSAon+yAvaqhHyOR8E7sTlAnIOhVjt6 dBRbHM388UaKhO05YmSyeB8KuAA2rBjPOmhB3veQZJ076fq3+1d76ZKyuaynfLcP6GXn EaSDdXivwUEk3zmxEqn/uOyNSJ980iWY7DlU+FPHAbA21Fu43p83YaLjnmSgTbBOVLsv AnXQ== X-Gm-Message-State: AO0yUKV33d5UBVJ5+gLuOFGz4zBkOnMYEEyR3x5L3eJ1Nhj2BAm2PGmT SB/AbUqrDwr+crOXWvTPexiaZmqu75+pgPngOBmpTA== X-Google-Smtp-Source: AK7set+/aGiLltNk3RpQt4DuZCmj4OtyTiGChQDlWkyzz18HaW1RuZ+9lf4p5oGCUZZHJ8FGKGZWiQ== X-Received: by 2002:a17:902:b70e:b0:19c:a9bc:ce57 with SMTP id d14-20020a170902b70e00b0019ca9bcce57mr10746595pls.64.1678126701011; Mon, 06 Mar 2023 10:18:21 -0800 (PST) Received: from hermes.local (204-195-120-218.wavecable.com. [204.195.120.218]) by smtp.gmail.com with ESMTPSA id e7-20020a170902cf4700b0019adfb96084sm7039155plg.36.2023.03.06.10.18.20 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 06 Mar 2023 10:18:20 -0800 (PST) From: Stephen Hemminger To: dev@dpdk.org Cc: Stephen Hemminger Subject: [PATCH v2 2/2] eal: add option to put timestamp on console output Date: Mon, 6 Mar 2023 10:18:16 -0800 Message-Id: <20230306181816.97243-3-stephen@networkplumber.org> X-Mailer: git-send-email 2.39.2 In-Reply-To: <20230306181816.97243-1-stephen@networkplumber.org> References: <20200814173441.23086-1-stephen@networkplumber.org> <20230306181816.97243-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 was chosen to be the same as the default Linux dmesg timestamp. The messages are written using writev() which avoids unnecessary buffering and ensures that if multiple threads are logging at the same time that timestamp and message buffer don't get interleaved. Example: [ 0.000040] EAL: Probing VFIO support... Signed-off-by: Stephen Hemminger --- .../freebsd_gsg/freebsd_eal_parameters.rst | 32 ++++++++++++++ doc/guides/linux_gsg/linux_eal_parameters.rst | 5 +++ lib/eal/common/eal_common_options.c | 5 +++ lib/eal/common/eal_internal_cfg.h | 1 + lib/eal/common/eal_options.h | 2 + lib/eal/unix/eal_log.c | 42 +++++++++++++++++-- 6 files changed, 84 insertions(+), 3 deletions(-) diff --git a/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst b/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst index fba467a2ce92..99cff10e963c 100644 --- a/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst +++ b/doc/guides/freebsd_gsg/freebsd_eal_parameters.rst @@ -18,3 +18,35 @@ FreeBSD-specific EAL parameters ------------------------------- There are currently no FreeBSD-specific EAL command-line parameters available. + +Other options +~~~~~~~~~~~~~ + +* ``--syslog `` + + Set syslog facility. Valid syslog facilities are:: + + auth + cron + daemon + ftp + kern + lpr + mail + news + syslog + user + uucp + local0 + local1 + local2 + local3 + local4 + 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..2d3d8e82f7f3 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 }, @@ -1833,6 +1834,9 @@ eal_parse_common_option(int opt, const char *optarg, } break; } + case OPT_LOG_TIMESTAMP_NUM: + conf->log_timestamp = 1; + break; #ifndef RTE_EXEC_ENV_WINDOWS case OPT_TRACE_NUM: { @@ -2194,6 +2198,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..33144c3619dd 100644 --- a/lib/eal/common/eal_internal_cfg.h +++ b/lib/eal/common/eal_internal_cfg.h @@ -85,6 +85,7 @@ struct internal_config { * per-node) non-legacy mode only. */ volatile int syslog_facility; /**< facility passed to openlog() */ + volatile uint8_t log_timestamp; /**< add timestamp to console output */ /** 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/unix/eal_log.c b/lib/eal/unix/eal_log.c index d44416fd6570..d8a900efedea 100644 --- a/lib/eal/unix/eal_log.c +++ b/lib/eal/unix/eal_log.c @@ -4,11 +4,17 @@ #include #include +#include #include +#include +#include #include #include "eal_log.h" +#include "eal_private.h" + +static struct timespec log_start_time; /* * default log function @@ -16,11 +22,39 @@ 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 = fwrite(buf, 1, size, stderr); - fflush(stderr); + /* 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 -= log_start_time.tv_sec; + ts.tv_nsec -= 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 same 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 { + /* write on stderr */ + ret = fwrite(buf, 1, size, stderr); + fflush(stderr); + } /* Syslog error levels are from 0 to 7, so subtract 1 to convert */ syslog(rte_log_cur_msg_loglevel() - 1, "%.*s", (int)size, buf); @@ -49,6 +83,8 @@ eal_log_init(const char *id, int facility) { FILE *log_stream; + clock_gettime(CLOCK_MONOTONIC, &log_start_time); + log_stream = fopencookie(NULL, "w+", console_log_func); if (log_stream == NULL) return -1; -- 2.39.2