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 2D69241DFF; Tue, 7 Mar 2023 10:35:36 +0100 (CET) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id D181D40E03; Tue, 7 Mar 2023 10:35:35 +0100 (CET) Received: from szxga01-in.huawei.com (szxga01-in.huawei.com [45.249.212.187]) by mails.dpdk.org (Postfix) with ESMTP id CAC4B4067E for ; Tue, 7 Mar 2023 10:35:34 +0100 (CET) Received: from dggpeml500024.china.huawei.com (unknown [172.30.72.55]) by szxga01-in.huawei.com (SkyGuard) with ESMTP id 4PW9Jl1GzTzrSNL; Tue, 7 Mar 2023 17:34:47 +0800 (CST) Received: from [10.67.100.224] (10.67.100.224) by dggpeml500024.china.huawei.com (7.185.36.10) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2507.21; Tue, 7 Mar 2023 17:35:32 +0800 Subject: Re: [PATCH v3 2/2] eal: add option to put timestamp on console output To: Stephen Hemminger , CC: Bruce Richardson References: <20200814173441.23086-1-stephen@networkplumber.org> <20230306192810.106154-1-stephen@networkplumber.org> <20230306192810.106154-3-stephen@networkplumber.org> From: fengchengwen Message-ID: <216dfffb-2a50-3288-27a5-5078ea9eb22d@huawei.com> Date: Tue, 7 Mar 2023 17:35:32 +0800 User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:68.0) Gecko/20100101 Thunderbird/68.11.0 MIME-Version: 1.0 In-Reply-To: <20230306192810.106154-3-stephen@networkplumber.org> Content-Type: text/plain; charset="utf-8" Content-Language: en-US Content-Transfer-Encoding: 7bit X-Originating-IP: [10.67.100.224] X-ClientProxiedBy: dggems704-chm.china.huawei.com (10.3.19.181) To dggpeml500024.china.huawei.com (7.185.36.10) X-CFilter-Loop: Reflected 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 On 2023/3/7 3:28, Stephen Hemminger wrote: > 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 This should add to commit 1/2 [PATCH v3 1/2] eal: unify logging code for FreeBsd and Linux > + > +* ``--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; This is process's private, how about support multi-process ? so that all process has the same base? > > /* > * 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); The syslog will add timestamp, but the syslog backend will re-write timestamp, so in the last, you can't find the real-timestamp of this log print. sometimes it requires to get real log time. PS: we found it in our test environment because RR schedule hang too long (similar question also found: https://bugzilla.redhat.com/show_bug.cgi?id=1855447). So suggest add timestamp in syslog string also, and don't convert to monotonic and just print as normal format (just like syslog). > @@ -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; >