From mboxrd@z Thu Jan 1 00:00:00 1970
Return-Path: <dev-bounces@dpdk.org>
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 <dev@dpdk.org>; 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 <stephen@networkplumber.org>, <dev@dpdk.org>
CC: Bruce Richardson <bruce.richardson@intel.com>
References: <20200814173441.23086-1-stephen@networkplumber.org>
<20230306192810.106154-1-stephen@networkplumber.org>
<20230306192810.106154-3-stephen@networkplumber.org>
From: fengchengwen <fengchengwen@huawei.com>
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 <dev.dpdk.org>
List-Unsubscribe: <https://mails.dpdk.org/options/dev>,
<mailto:dev-request@dpdk.org?subject=unsubscribe>
List-Archive: <http://mails.dpdk.org/archives/dev/>
List-Post: <mailto:dev@dpdk.org>
List-Help: <mailto:dev-request@dpdk.org?subject=help>
List-Subscribe: <https://mails.dpdk.org/listinfo/dev>,
<mailto:dev-request@dpdk.org?subject=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 <stephen@networkplumber.org>
> ---
> .../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 <syslog facility>``
> +
> + 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"=<level> Set global log level\n"
> " --"OPT_LOG_LEVEL"=<type-match>:<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 <stdio.h>
> #include <sys/types.h>
> +#include <sys/uio.h>
> #include <syslog.h>
> +#include <time.h>
> +#include <unistd.h>
>
> #include <rte_log.h>
>
> #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;
>