Re: [PATCH v3 2/2] eal: add option to put timestamp on console output

[fengchengwen <fengchengwen@huawei.com>]

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;
>