[v3,2/2] eal: add option to put timestamp on console output
Checks
Commit Message
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(-)
Comments
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;
>
On Tue, 7 Mar 2023 17:35:32 +0800
fengchengwen <fengchengwen@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@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?
On Tue, 7 Mar 2023 17:35:32 +0800
fengchengwen <fengchengwen@huawei.com> wrote:
> 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).
Are you using systemd?
Never, never configure a DPDK application with real-time process priority.
Polling model and RT don't mix.
On 2023/3/8 0:06, Stephen Hemminger wrote:
> On Tue, 7 Mar 2023 17:35:32 +0800
> fengchengwen <fengchengwen@huawei.com> wrote:
>
>> 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).
>
>
> Are you using systemd?
Yes
>
> Never, never configure a DPDK application with real-time process priority.
> Polling model and RT don't mix.
Maybe we should document them ?
> .
>
On Wed, 8 Mar 2023 08:36:48 +0800
fengchengwen <fengchengwen@huawei.com> wrote:
> On 2023/3/8 0:06, Stephen Hemminger wrote:
> > On Tue, 7 Mar 2023 17:35:32 +0800
> > fengchengwen <fengchengwen@huawei.com> wrote:
> >
> >> 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).
> >
> >
> > Are you using systemd?
>
> Yes
There is redhat bug about this:
https://bugzilla.redhat.com/show_bug.cgi?id=991678
> > Never, never configure a DPDK application with real-time process priority.
> > Polling model and RT don't mix.
>
> Maybe we should document them ?
Part of previous discussion here:
https://mails.dpdk.org/archives/dev/2021-April/203778.html
In my experience running DPDK on isolated threads (cgroup or scheduler isolation)
combined with remapping interrupts gives best response without lockup.
I.e don't depend on scheduler to do the right thing. Instead ensure that
each thread runs on dedicated CPU.
On Wed, 8 Mar 2023 08:36:48 +0800
fengchengwen <fengchengwen@huawei.com> wrote:
> > Never, never configure a DPDK application with real-time process priority.
> > Polling model and RT don't mix.
>
> Maybe we should document them ?
LOL - ChatGPT is amusing if you ask it. The answer is pro grammatically
correct, but will not work. The caveat at the end is much bigger than it
understands.
Question:
Is Dataplane Development Kit (DPDK) compatible with Linux Real Time thread priority like SCH_FIFO?
Yes, Dataplane Development Kit (DPDK) is compatible with Linux Real-Time thread priority scheduling policies, such as SCHED_FIFO.
Answer:
DPDK supports setting the thread priority using the standard Linux pthread APIs, including pthread_setschedparam() and pthread_attr_setschedpolicy(). This allows the application to configure the thread scheduling policy and priority for DPDK worker threads.
To set the real-time priority of DPDK threads, you can use the pthread_setschedparam() function to set the scheduling policy to SCHED_FIFO or SCHED_RR and the priority value to a value between 1 and 99. Here is an example of how to set the real-time priority of a DPDK thread:
> pthread_t tid;
> struct sched_param sched_param;
> pthread_attr_t attr;
>
> pthread_attr_init(&attr);
> pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_DETACHED);
>
> sched_param.sched_priority = 50;
> pthread_attr_setschedparam(&attr, &sched_param);
> pthread_attr_setschedpolicy(&attr, SCHED_FIFO);
>
> pthread_create(&tid, &attr, thread_func, arg);
In this example, the SCHED_FIFO scheduling policy is used, and the priority value is set to 50. You can adjust the priority value according to your needs.
Note that using real-time scheduling policies like SCHED_FIFO or SCHED_RR requires careful consideration of system resources and may impact system performance if not used properly. It is recommended to consult the Linux documentation and to test the system thoroughly before deploying any application using real-time scheduling policies.
On 2023/3/8 10:03, Stephen Hemminger wrote:
> On Wed, 8 Mar 2023 08:36:48 +0800
> fengchengwen <fengchengwen@huawei.com> wrote:
>
>> On 2023/3/8 0:06, Stephen Hemminger wrote:
>>> On Tue, 7 Mar 2023 17:35:32 +0800
>>> fengchengwen <fengchengwen@huawei.com> wrote:
>>>
>>>> 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).
>>>
>>>
>>> Are you using systemd?
>>
>> Yes
>
> There is redhat bug about this:
> https://bugzilla.redhat.com/show_bug.cgi?id=991678
>
>>> Never, never configure a DPDK application with real-time process priority.
>>> Polling model and RT don't mix.
>>
>> Maybe we should document them ?
>
> Part of previous discussion here:
> https://mails.dpdk.org/archives/dev/2021-April/203778.html
>
> In my experience running DPDK on isolated threads (cgroup or scheduler isolation)
> combined with remapping interrupts gives best response without lockup.
>
> I.e don't depend on scheduler to do the right thing. Instead ensure that
> each thread runs on dedicated CPU.
Got it, thanks.
>
>
>
> .
>
@@ -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
+
+* ``--log-timestamp``
+
+ Add a timestamp of seconds and microseconds to each log message
+ written to standard output.
@@ -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.
@@ -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"
@@ -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 */
@@ -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"
@@ -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;
/*
* 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);
@@ -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;