[PATCH v3] log: add timestamp for log

[PATCH v3] log: add timestamp for log

[luzhipeng]

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(-)

diff --git a/lib/eal/common/eal_common_log.c b/lib/eal/common/eal_common_log.c
index bd7b188ceb..46dbd4b7bf 100644
--- a/lib/eal/common/eal_common_log.c
+++ b/lib/eal/common/eal_common_log.c
@@ -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;
-- 
2.31.1

Re: [PATCH v3] log: add timestamp for log

[Stephen Hemminger]

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/

Re: [PATCH v3] log: add timestamp for log

[Tyler Retzlaff]

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/

Re: [PATCH v3] log: add timestamp for log

[Stephen Hemminger]

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.