[v3] log: add timestamp for log
Checks
Commit Message
From: Zhipeng Lu <luzhipeng@cestc.cn>
add timestamp for log
Signed-off-by: Zhipeng Lu <luzhipeng@cestc.cn>
---
lib/eal/common/eal_common_log.c | 25 ++++++++++++++++++++++++-
1 file changed, 24 insertions(+), 1 deletion(-)
Comments
On Sat, 4 Mar 2023 16:14:21 +0800
luzhipeng <luzhipeng@cestc.cn> wrote:
> From: Zhipeng Lu <luzhipeng@cestc.cn>
>
> add timestamp for log
>
> Signed-off-by: Zhipeng Lu <luzhipeng@cestc.cn>
Good idea but:
- it needs to be optional
- timestamp only makes sense on the terminal (stdout) log stream
syslog/journal already have timestamp
I did a similar patch that never made it in that did this.
https://patchwork.dpdk.org/project/dpdk/patch/20200814173441.23086-1-stephen@networkplumber.org/
On Sat, Mar 04, 2023 at 08:04:41AM -0800, Stephen Hemminger wrote:
> On Sat, 4 Mar 2023 16:14:21 +0800
> luzhipeng <luzhipeng@cestc.cn> wrote:
>
> > From: Zhipeng Lu <luzhipeng@cestc.cn>
> >
> > add timestamp for log
> >
> > Signed-off-by: Zhipeng Lu <luzhipeng@cestc.cn>
>
> Good idea but:
> - it needs to be optional
> - timestamp only makes sense on the terminal (stdout) log stream
> syslog/journal already have timestamp
+1
also, some people who may have written scripts to consume the log output
might get kind of irritated that you suddenly broke the format of the
output. while not strictly an "api" it's not super friendly to break it
unnecessarily.
>
>
> I did a similar patch that never made it in that did this.
> https://patchwork.dpdk.org/project/dpdk/patch/20200814173441.23086-1-stephen@networkplumber.org/
On Mon, 6 Mar 2023 13:00:17 -0800
Tyler Retzlaff <roretzla@linux.microsoft.com> wrote:
> On Sat, Mar 04, 2023 at 08:04:41AM -0800, Stephen Hemminger wrote:
> > On Sat, 4 Mar 2023 16:14:21 +0800
> > luzhipeng <luzhipeng@cestc.cn> wrote:
> >
> > > From: Zhipeng Lu <luzhipeng@cestc.cn>
> > >
> > > add timestamp for log
> > >
> > > Signed-off-by: Zhipeng Lu <luzhipeng@cestc.cn>
> >
> > Good idea but:
> > - it needs to be optional
> > - timestamp only makes sense on the terminal (stdout) log stream
> > syslog/journal already have timestamp
>
> +1
>
> also, some people who may have written scripts to consume the log output
> might get kind of irritated that you suddenly broke the format of the
> output. while not strictly an "api" it's not super friendly to break it
> unnecessarily.
Two additional comments.
- since stderr is unbuffered on most OS, the fprintf of the timestamp
and then the message is not thread safe. Writes of one thread and another might
intermix. Addressed that in my version by using writev
- Putting full date is unnecessary overhead better to use seconds since startup
(similar to kernel dmesg). Also simpler to calculate.
@@ -480,6 +480,27 @@ rte_log_dump(FILE *f)
}
}
+/* get timestamp*/
+static void
+rte_log_get_timestamp_prefix(char *buf, int buf_size)
+{
+ struct tm *info;
+ char date[24];
+ struct timespec ts;
+ long usec;
+
+ clock_gettime(CLOCK_REALTIME, &ts);
+ info = localtime(&ts.tv_sec);
+ usec = ts.tv_nsec / 1000;
+ if (info == NULL) {
+ snprintf(buf, buf_size, "[%s.%06ld] ", "unknown date", usec);
+ return;
+ }
+
+ strftime(date, sizeof(date), "%Y-%m-%d %H:%M:%S", info);
+ snprintf(buf, buf_size, "[%s.%06ld] ", date, usec);
+}
+
/*
* Generates a log message The message will be sent in the stream
* defined by the previous call to rte_openlog_stream().
@@ -489,6 +510,7 @@ rte_vlog(uint32_t level, uint32_t logtype, const char *format, va_list ap)
{
FILE *f = rte_log_get_stream();
int ret;
+ char timestamp[64];
if (logtype >= rte_logs.dynamic_types_len)
return -1;
@@ -498,7 +520,8 @@ rte_vlog(uint32_t level, uint32_t logtype, const char *format, va_list ap)
/* save loglevel and logtype in a global per-lcore variable */
RTE_PER_LCORE(log_cur_msg).loglevel = level;
RTE_PER_LCORE(log_cur_msg).logtype = logtype;
-
+ rte_log_get_timestamp_prefix(timestamp, sizeof(timestamp));
+ fprintf(f, "%s ", timestamp);
ret = vfprintf(f, format, ap);
fflush(f);
return ret;