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 <step...@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;
>
