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 663391ec01888f4817bd1c0b84cd70be0da97285..a93945c04f28c219fcdacb0280e80a7e6957c13a 100644 (file)
--- 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 e784b68bcc8b7f8d6809d3de0e901c53e1b0c88a..71be71aa11516a4699d93a19a4da23ba5fbff8a8 100644 (file)
--- 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 5b29cba852d3d9f1dea0445807852b0b67032b76..391f5d7f2049d034ffa4ca249aac29f3e98f1fe8 100644 (file)
--- 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 *