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 A00D641DF6; Mon, 6 Mar 2023 20:28:27 +0100 (CET) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id A085541149; Mon, 6 Mar 2023 20:28:17 +0100 (CET) Received: from mail-pl1-f177.google.com (mail-pl1-f177.google.com [209.85.214.177]) by mails.dpdk.org (Postfix) with ESMTP id E025740EE4 for ; Mon, 6 Mar 2023 20:28:15 +0100 (CET) Received: by mail-pl1-f177.google.com with SMTP id p6so11681895plf.0 for ; Mon, 06 Mar 2023 11:28:15 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=networkplumber-org.20210112.gappssmtp.com; s=20210112; t=1678130894; 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=Ph+Y2Nd74jC+4/aZeoy7D1JaTQZ7c8/sm3ECjwE575o=; b=4eI3pKjCXGJysqNpAqEJfhjUwQi2XN6A225JIgTT2LtJ0XkmcCDZO6xfHGv3R3hDCn 6iy+/uQ6vKYSYbe1KqZ9KQnFxO8HijeNpZcntDYcvFfZ0PS0QpLtB4OFrj2TXkcokJ4m mGe3wx7/wpnsc44tr9GE8MLGy1FsLEUoLGyFUIkgqK5vzGjrEKQl1MEPFwo++xS6vxpR YJV/es5ELqfqOrg2snuAohY4KNZ43A6ESZEe6wvT2MY/xapsM4qsRD67X/OzaQn29GOz NfKkctX02pVlaGXgD8AN29Y6wK4av1HA49oLV2iKRXQJHRjUSHyTPNxeZVxp+rp4zYDp kC1Q== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; t=1678130894; 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=Ph+Y2Nd74jC+4/aZeoy7D1JaTQZ7c8/sm3ECjwE575o=; b=CffSUusZ9flayH6gfpzQQWlW+cNr+JDGE+dTx3RYaRs8H4JvjvqDQ0uiYJwT7RUqL3 MM5bZ0lJvejkVjCYTkJRfJEKdxjgV8m3rColzVCRgmdtzZOePWKIzopB1eQvTj19vlHH f70IMhJ9tblbKIcd563CytaNXEkYqJMaz3Ql8KDGnDRCu6r3Igwrg8y29DkphRcgRUvI fBnC6UVGlrWBGA72QLNtTUHNyOk4qvnp/wu5RUURB/yXbweLCfBZJ+mxPK9/tvWLIUx0 yzPnbZRBBO5ie4Y9iiHoFd/lhhkboXSvaVDyKZ5NSL+PD2GGEcfLRbIKdji1I0vAzzyZ p+XQ== X-Gm-Message-State: AO0yUKXPM8FuHfICpwIuCswD7RYanASUuXJfPKPX+0qdbsC16zjQlPns OHY84JLRa7iJHrWfhopFMWXLHx3QfaI3Gk6wcibnPQ== X-Google-Smtp-Source: AK7set/vSAxNPddfObt942qRAjZjLAAAfF3Heu973Qj9TLBculW/lLHtdh7tbMtTVwWiXTX9hh92aQ== X-Received: by 2002:a17:903:41ca:b0:19c:be63:a9ce with SMTP id u10-20020a17090341ca00b0019cbe63a9cemr12205061ple.4.1678130894156; Mon, 06 Mar 2023 11:28:14 -0800 (PST) Received: from hermes.local (204-195-120-218.wavecable.com. [204.195.120.218]) by smtp.gmail.com with ESMTPSA id g22-20020a1709029f9600b001991d6c6c64sm5653476plq.185.2023.03.06.11.28.13 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 06 Mar 2023 11:28:13 -0800 (PST) From: Stephen Hemminger To: dev@dpdk.org Cc: Stephen Hemminger , Bruce Richardson Subject: [PATCH v3 2/2] eal: add option to put timestamp on console output Date: Mon, 6 Mar 2023 11:28:10 -0800 Message-Id: <20230306192810.106154-3-stephen@networkplumber.org> X-Mailer: git-send-email 2.39.2 In-Reply-To: <20230306192810.106154-1-stephen@networkplumber.org> References: <20200814173441.23086-1-stephen@networkplumber.org> <20230306192810.106154-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: [ 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