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

[Stephen Hemminger]

On Tue, 7 Mar 2023 17:35:32 +0800
fengchengwen <fengchengwen at huawei.com> wrote:

> 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 at 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?


If using primary/secondary, then the secondary's output would have time zero
of when secondary started.  Not sure if that is good or bad?