From: Aki Tuomi <aki.tuomi@dovecot.fi>
Date: Tue, 16 Oct 2018 05:52:49 +0000 (+0300)
Subject: lib: event - Record real duration
X-Git-Tag: 2.3.4~43
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=db2855a40ea8fd42febcc1f1a580ab5953c33cb2;p=thirdparty%2Fdovecot%2Fcore.git

lib: event - Record real duration

The old code only measured difference between successive
ioloop_time updates. The new code uses gettimeofday to
get current real time, making measurements accurate.
---

diff --git a/src/lib/lib-event-private.h b/src/lib/lib-event-private.h
index 663391ec01..a93945c04f 100644
--- a/src/lib/lib-event-private.h
+++ b/src/lib/lib-event-private.h
@@ -24,6 +24,7 @@ struct event {
 
 /* Fields that are exported & imported: */
 	struct timeval tv_created_ioloop;
+	struct timeval tv_created;
 	struct timeval tv_last_sent;
 
 	const char *source_filename;
diff --git a/src/lib/lib-event.c b/src/lib/lib-event.c
index e784b68bcc..71be71aa11 100644
--- a/src/lib/lib-event.c
+++ b/src/lib/lib-event.c
@@ -5,6 +5,7 @@
 #include "event-filter.h"
 #include "array.h"
 #include "llist.h"
+#include "time-util.h"
 #include "str.h"
 #include "strescape.h"
 #include "ioloop.h"
@@ -128,6 +129,8 @@ struct event *event_create(struct event *parent, const char *source_filename,
 	event->id = ++event_id_counter;
 	event->pool = pool;
 	event->tv_created_ioloop = ioloop_timeval;
+	if (gettimeofday(&event->tv_created, NULL) < 0)
+		i_panic("gettimeofday() failed: %m");
 	event->source_filename = p_strdup(pool, source_filename);
 	event->source_linenum = source_linenum;
 	if (parent != NULL) {
@@ -155,6 +158,7 @@ event_create_passthrough(struct event *parent, const char *source_filename,
 		/* This event only intends to extend the parent event.
 		   Use the parent's creation timestamp. */
 		event->tv_created_ioloop = parent->tv_created_ioloop;
+		event->tv_created = parent->tv_created;
 		event_last_passthrough = &event->event_passthrough;
 	} else {
 		event_last_passthrough = &parent->event_passthrough;
@@ -541,7 +545,7 @@ struct event *event_get_parent(struct event *event)
 
 void event_get_create_time(struct event *event, struct timeval *tv_r)
 {
-	*tv_r = event->tv_created_ioloop;
+	*tv_r = event->tv_created;
 }
 
 bool event_get_last_send_time(struct event *event, struct timeval *tv_r)
@@ -550,6 +554,15 @@ bool event_get_last_send_time(struct event *event, struct timeval *tv_r)
 	return tv_r->tv_sec != 0;
 }
 
+void event_get_last_duration(struct event *event, intmax_t *duration_r)
+{
+	if (event->tv_last_sent.tv_sec == 0) {
+		*duration_r = 0;
+		return;
+	}
+	*duration_r = timeval_diff_usecs(&event->tv_last_sent, &event->tv_created);
+}
+
 const struct event_field *
 event_get_fields(struct event *event, unsigned int *count_r)
 {
@@ -583,7 +596,8 @@ void event_send(struct event *event, struct failure_context *ctx,
 void event_vsend(struct event *event, struct failure_context *ctx,
 		 const char *fmt, va_list args)
 {
-	event->tv_last_sent = ioloop_timeval;
+	if (gettimeofday(&event->tv_last_sent, NULL) < 0)
+		i_panic("gettimeofday() failed: %m");
 	if (event_send_callbacks(event, EVENT_CALLBACK_TYPE_EVENT,
 				 ctx, fmt, args)) {
 		if (ctx->type != LOG_TYPE_DEBUG ||
@@ -629,9 +643,11 @@ event_export_field_value(string_t *dest, const struct event_field *field)
 void event_export(const struct event *event, string_t *dest)
 {
 	/* required fields: */
-	str_printfa(dest, "%"PRIdTIME_T"\t%u",
+	str_printfa(dest, "%"PRIdTIME_T"\t%u\t%"PRIdTIME_T"\t%u",
 		    event->tv_created_ioloop.tv_sec,
-		    (unsigned int)event->tv_created_ioloop.tv_usec);
+		    (unsigned int)event->tv_created_ioloop.tv_usec,
+		    event->tv_created.tv_sec,
+		    (unsigned int)event->tv_created.tv_usec);
 
 	/* optional fields: */
 	if (event->source_filename != NULL) {
@@ -716,6 +732,11 @@ bool event_import_unescaped(struct event *event, const char *const *args,
 		return FALSE;
 	}
 	args += 2;
+	if (!event_import_tv(args[0], args[1], &event->tv_created, &error)) {
+		*error_r = t_strdup_printf("Invalid tv_created: %s", error);
+		return FALSE;
+	}
+	args += 2;
 
 	/* optional fields: */
 	while (*args != NULL) {
diff --git a/src/lib/lib-event.h b/src/lib/lib-event.h
index 5b29cba852..391f5d7f20 100644
--- a/src/lib/lib-event.h
+++ b/src/lib/lib-event.h
@@ -213,6 +213,8 @@ void event_get_create_time(struct event *event, struct timeval *tv_r);
 /* Get the time when the event was last sent. Returns TRUE if time was
    returned, FALSE if event has never been sent. */
 bool event_get_last_send_time(struct event *event, struct timeval *tv_r);
+/* Get the event duration field, calculated after event has been sent. */
+void event_get_last_duration(struct event *event, intmax_t *duration_msec_r);
 /* Returns field for a given key, or NULL if it doesn't exist. If the key
    isn't found from the event itself, find it from parent events. */
 const struct event_field *