Fix: events discarded timing inaccuracy

Introduce babeltrace_ctf_console_output too, to ensure we only print
discarded events when a text output is used.

Fixes #589

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>

diff --git a/formats/ctf-text/ctf-text.c b/formats/ctf-text/ctf-text.c
index 48ce31b8691081319e7ee35762d87c8a47b579be..9d5123a1fdb5a43c19c4ee0d425f07810eb07524 100644 (file)
--- a/formats/ctf-text/ctf-text.c
+++ b/formats/ctf-text/ctf-text.c
@@ -262,13 +262,6 @@ int ctf_text_write_event(struct bt_stream_pos *ppos, struct ctf_stream_definitio
                return -EINVAL;
        }
 
-       /* Print events discarded */
-       if (stream->events_discarded) {
-               fflush(pos->fp);
-               ctf_print_discarded(stderr, stream, 0);
-               stream->events_discarded = 0;
-       }
-
        if (stream->has_timestamp) {
                set_field_names_print(pos, ITEM_HEADER);
                if (pos->print_names)
@@ -563,6 +556,7 @@ struct bt_trace_descriptor *ctf_text_open_trace(const char *path, int flags,
                pos->parent.event_cb = ctf_text_write_event;
                pos->parent.trace = &pos->trace_descriptor;
                pos->print_names = 0;
+               babeltrace_ctf_console_output++;
                break;
        case O_RDONLY:
        default:
@@ -582,6 +576,8 @@ int ctf_text_close_trace(struct bt_trace_descriptor *td)
        int ret;
        struct ctf_text_stream_pos *pos =
                container_of(td, struct ctf_text_stream_pos, trace_descriptor);
+
+       babeltrace_ctf_console_output--;
        if (pos->fp != stdout) {
                ret = fclose(pos->fp);
                if (ret) {

diff --git a/formats/ctf/ctf.c b/formats/ctf/ctf.c
index 4c64c930da1a4e1e60ccc32642d26286e32d3e97..e31808c3843d27380a63b0d173a949aa027e336e 100644 (file)
--- a/formats/ctf/ctf.c
+++ b/formats/ctf/ctf.c
@@ -84,6 +84,13 @@ uint64_t opt_clock_offset_ns;
 
 extern int yydebug;
 
+/*
+ * TODO: babeltrace_ctf_console_output ensures that we only print
+ * discarded events when ctf-text plugin is used. Should be cleaned up
+ * with the plugin system redesign.
+ */
+int babeltrace_ctf_console_output;
+
 static
 struct bt_trace_descriptor *ctf_open_trace(const char *path, int flags,
                void (*packet_seek)(struct bt_stream_pos *pos, size_t index,
@@ -279,10 +286,7 @@ void ctf_update_timestamp(struct ctf_stream_definition *stream,
        uint64_t oldval, newval, updateval;
 
        if (unlikely(integer_declaration->len == 64)) {
-               stream->prev_cycles_timestamp = stream->cycles_timestamp;
                stream->cycles_timestamp = integer_definition->value._unsigned;
-               stream->prev_real_timestamp = ctf_get_real_timestamp(stream,
-                               stream->prev_cycles_timestamp);
                stream->real_timestamp = ctf_get_real_timestamp(stream,
                                stream->cycles_timestamp);
                return;
@@ -298,12 +302,9 @@ void ctf_update_timestamp(struct ctf_stream_definition *stream,
        updateval = stream->cycles_timestamp;
        updateval &= ~((1ULL << integer_declaration->len) - 1);
        updateval += newval;
-       stream->prev_cycles_timestamp = stream->cycles_timestamp;
        stream->cycles_timestamp = updateval;
 
        /* convert to real timestamp */
-       stream->prev_real_timestamp = ctf_get_real_timestamp(stream,
-                       stream->prev_cycles_timestamp);
        stream->real_timestamp = ctf_get_real_timestamp(stream,
                        stream->cycles_timestamp);
 }
@@ -408,24 +409,39 @@ void print_uuid(FILE *fp, unsigned char *uuid)
                fprintf(fp, "%x", (unsigned int) uuid[i]);
 }
 
-void ctf_print_discarded(FILE *fp, struct ctf_stream_definition *stream,
-               int end_stream)
+/*
+ * Discarded events can be either:
+ * - discarded after end of previous buffer due to buffer full:
+ *     happened within range: [ prev_timestamp_end, timestamp_begin ]
+ * - discarded within current buffer due to either event too large or
+ *   nested wrap-around:
+ *     happened within range: [ timestamp_begin, timestamp_end ]
+ *
+ * Given we have discarded counters of those two types merged into the
+ * events_discarded counter, we need to use the union of those ranges:
+ *   [ prev_timestamp_end, timestamp_end ]
+ */
+static
+void ctf_print_discarded(FILE *fp, struct ctf_stream_definition *stream)
 {
-       fprintf(fp, "[warning] Tracer discarded %" PRIu64 " events %sbetween [",
-               stream->events_discarded,
-               end_stream ? "at end of stream " : "");
+       if (!stream->events_discarded || !babeltrace_ctf_console_output) {
+               return;
+       }
+       fflush(stdout);
+       fprintf(fp, "[warning] Tracer discarded %" PRIu64 " events between [",
+               stream->events_discarded);
        if (opt_clock_cycles) {
                ctf_print_timestamp(fp, stream,
-                               stream->prev_cycles_timestamp);
+                               stream->prev.cycles.end);
                fprintf(fp, "] and [");
                ctf_print_timestamp(fp, stream,
-                               stream->prev_cycles_timestamp_end);
+                               stream->current.cycles.end);
        } else {
                ctf_print_timestamp(fp, stream,
-                               stream->prev_real_timestamp);
+                               stream->prev.real.end);
                fprintf(fp, "] and [");
                ctf_print_timestamp(fp, stream,
-                               stream->prev_real_timestamp_end);
+                               stream->current.real.end);
        }
        fprintf(fp, "] in trace UUID ");
        print_uuid(fp, stream->stream_class->trace->uuid);
@@ -788,23 +804,30 @@ void ctf_update_current_packet_index(struct ctf_stream_definition *stream,
        uint64_t events_discarded_diff;
 
        /* Update packet index time information */
-       stream->prev_cycles_timestamp_end =
-               cur_index->ts_cycles.timestamp_end;
-       stream->prev_cycles_timestamp =
+
+       /* Current packet begin/end */
+       stream->current.real.begin =
+               cur_index->ts_real.timestamp_begin;
+       stream->current.cycles.begin =
                cur_index->ts_cycles.timestamp_begin;
-       stream->prev_real_timestamp_end =
+       stream->current.real.end =
                cur_index->ts_real.timestamp_end;
-       stream->prev_real_timestamp =
-               cur_index->ts_real.timestamp_begin;
-
-       stream->prev_real_timestamp =
-               stream->real_timestamp;
-       stream->prev_cycles_timestamp =
-               stream->cycles_timestamp;
+       stream->current.cycles.end =
+               cur_index->ts_cycles.timestamp_end;
 
        /* Update packet index discarded event information */
        events_discarded_diff = cur_index->events_discarded;
        if (prev_index) {
+               /* Previous packet begin/end */
+               stream->prev.cycles.begin =
+                       prev_index->ts_cycles.timestamp_begin;
+               stream->prev.real.begin =
+                       prev_index->ts_real.timestamp_begin;
+               stream->prev.cycles.end =
+                       prev_index->ts_cycles.timestamp_end;
+               stream->prev.real.end =
+                       prev_index->ts_real.timestamp_end;
+
                events_discarded_diff -= prev_index->events_discarded;
                /*
                 * Deal with 32-bit wrap-around if the tracer provided a
@@ -813,6 +836,17 @@ void ctf_update_current_packet_index(struct ctf_stream_definition *stream,
                if (prev_index->events_discarded_len == 32) {
                        events_discarded_diff = (uint32_t) events_discarded_diff;
                }
+       } else {
+               /*
+                * First packet: use current packet info as limits for
+                * previous packet.
+                */
+               stream->prev.cycles.begin =
+                       stream->prev.cycles.end =
+                               stream->current.cycles.begin;
+               stream->prev.real.begin =
+                       stream->prev.real.end =
+                               stream->current.real.begin;
        }
        stream->events_discarded = events_discarded_diff;
 }
@@ -829,7 +863,7 @@ void ctf_packet_seek(struct bt_stream_pos *stream_pos, size_t index, int whence)
                container_of(pos, struct ctf_file_stream, pos);
        int ret;
        off_t off;
-       struct packet_index *packet_index;
+       struct packet_index *packet_index, *prev_index;
 
        switch (whence) {
        case SEEK_CUR:
@@ -881,22 +915,10 @@ void ctf_packet_seek(struct bt_stream_pos *stream_pos, size_t index, int whence)
                switch (whence) {
                case SEEK_CUR:
                {
-                       struct packet_index *prev_index = NULL;
-
                        if (pos->offset == EOF) {
                                return;
                        }
                        assert(pos->cur_index < pos->packet_index->len);
-                       packet_index = &g_array_index(pos->packet_index,
-                                       struct packet_index, pos->cur_index);
-                       if (pos->cur_index > 0) {
-                               prev_index = &g_array_index(pos->packet_index,
-                                               struct packet_index,
-                                               pos->cur_index - 1);
-                       }
-                       ctf_update_current_packet_index(&file_stream->parent,
-                                       prev_index, packet_index);
-
                        /* The reader will expect us to skip padding */
                        ++pos->cur_index;
                        break;
@@ -906,44 +928,39 @@ void ctf_packet_seek(struct bt_stream_pos *stream_pos, size_t index, int whence)
                                pos->offset = EOF;
                                return;
                        }
-                       packet_index = &g_array_index(pos->packet_index,
-                                       struct packet_index, index);
-                       pos->last_events_discarded = packet_index->events_discarded;
                        pos->cur_index = index;
-                       file_stream->parent.prev_real_timestamp = 0;
-                       file_stream->parent.prev_real_timestamp_end = 0;
-                       file_stream->parent.prev_cycles_timestamp = 0;
-                       file_stream->parent.prev_cycles_timestamp_end = 0;
                        break;
                default:
                        assert(0);
                }
+
+               packet_index = &g_array_index(pos->packet_index,
+                               struct packet_index, pos->cur_index);
+               if (pos->cur_index > 0) {
+                       prev_index = &g_array_index(pos->packet_index,
+                                       struct packet_index,
+                                       pos->cur_index - 1);
+               } else {
+                       prev_index = NULL;
+               }
+               ctf_update_current_packet_index(&file_stream->parent,
+                               prev_index, packet_index);
+
                if (pos->cur_index >= pos->packet_index->len) {
-                       /*
-                        * We need to check if we are in trace read or
-                        * called from packet indexing.  In this last
-                        * case, the collection is not there, so we
-                        * cannot print the timestamps.
-                        */
-                       if ((&file_stream->parent)->stream_class->trace->parent.collection) {
-                               /*
-                                * When a stream reaches the end of the
-                                * file, we need to show the number of
-                                * events discarded ourselves, because
-                                * there is no next event scheduled to
-                                * be printed in the output.
-                                */
-                               if (file_stream->parent.events_discarded) {
-                                       fflush(stdout);
-                                       ctf_print_discarded(stderr,
-                                               &file_stream->parent,
-                                               1);
-                                       file_stream->parent.events_discarded = 0;
-                               }
-                       }
                        pos->offset = EOF;
                        return;
                }
+
+               /*
+                * We need to check if we are in trace read or called
+                * from packet indexing.  In this last case, the
+                * collection is not there, so we cannot print the
+                * timestamps.
+                */
+               if ((&file_stream->parent)->stream_class->trace->parent.collection) {
+                       ctf_print_discarded(stderr, &file_stream->parent);
+               }
+
                packet_index = &g_array_index(pos->packet_index,
                                struct packet_index,
                                pos->cur_index);

diff --git a/include/babeltrace/babeltrace-internal.h b/include/babeltrace/babeltrace-internal.h
index 1f379ee7719d53de5c013c586783357f1f283d73..c9345509009d73eda04ab3df7ac4739980fa4d71 100644 (file)
--- a/include/babeltrace/babeltrace-internal.h
+++ b/include/babeltrace/babeltrace-internal.h
@@ -195,5 +195,6 @@ extern int opt_all_field_names,
 
 extern uint64_t opt_clock_offset;
 extern uint64_t opt_clock_offset_ns;
+extern int babeltrace_ctf_console_output;
 
 #endif

diff --git a/include/babeltrace/ctf-ir/metadata.h b/include/babeltrace/ctf-ir/metadata.h
index 93c7a586a3ecc985d55b84928b657ae9ad7a743a..675369584b9253e82ca16338d7fedf7ea3bbd873 100644 (file)
--- a/include/babeltrace/ctf-ir/metadata.h
+++ b/include/babeltrace/ctf-ir/metadata.h
@@ -44,6 +44,16 @@ struct ctf_clock;
 struct ctf_callsite;
 struct ctf_scanner;
 
+struct ctf_stream_packet_limits {
+       uint64_t begin;
+       uint64_t end;
+};
+
+struct ctf_stream_packet_timestamp {
+       struct ctf_stream_packet_limits cycles;
+       struct ctf_stream_packet_limits real;
+};
+
 struct ctf_stream_definition {
        struct ctf_stream_declaration *stream_class;
        uint64_t real_timestamp;                /* Current timestamp, in ns */
@@ -64,10 +74,8 @@ struct ctf_stream_definition {
 
        /* Event discarded information */
        uint64_t events_discarded;
-       uint64_t prev_real_timestamp;           /* Start-of-last-packet timestamp in ns */
-       uint64_t prev_real_timestamp_end;       /* End-of-last-packet timestamp in ns */
-       uint64_t prev_cycles_timestamp;         /* Start-of-last-packet timestamp in cycles */
-       uint64_t prev_cycles_timestamp_end;     /* End-of-last-packet timestamp in cycles */
+       struct ctf_stream_packet_timestamp prev;
+       struct ctf_stream_packet_timestamp current;
        char path[PATH_MAX];                    /* Path to stream. '\0' for mmap traces */
 };
 

diff --git a/include/babeltrace/ctf/events-internal.h b/include/babeltrace/ctf/events-internal.h
index 2e37693ab689afa089eebb4dc84ed60b8303df53..48caa54429fd70fe0f9299f82b0e1930f5ee03c5 100644 (file)
--- a/include/babeltrace/ctf/events-internal.h
+++ b/include/babeltrace/ctf/events-internal.h
@@ -79,8 +79,6 @@ struct bt_ctf_iter {
        uint64_t events_lost;
 };
 
-void ctf_print_discarded(FILE *fp, struct ctf_stream_definition *stream,
-                       int end_stream);
 void ctf_update_current_packet_index(struct ctf_stream_definition *stream,
                struct packet_index *prev_index,
                struct packet_index *cur_index);

diff --git a/lib/iterator.c b/lib/iterator.c
index 74942ac8948e19d9abbcc4910cd6685d9a9a9e48..d2464ab7c4f8274e2fadee6e70a6f8a51f76dcc4 100644 (file)
--- a/lib/iterator.c
+++ b/lib/iterator.c
@@ -399,10 +399,15 @@ int bt_iter_set_pos(struct bt_iter *iter, const struct bt_iter_pos *iter_pos)
                        stream_pos->offset = saved_pos->offset;
                        stream_pos->last_offset = LAST_OFFSET_POISON;
 
-                       stream->prev_real_timestamp = 0;
-                       stream->prev_real_timestamp_end = 0;
-                       stream->prev_cycles_timestamp = 0;
-                       stream->prev_cycles_timestamp_end = 0;
+                       stream->current.real.begin = 0;
+                       stream->current.real.end = 0;
+                       stream->current.cycles.begin = 0;
+                       stream->current.cycles.end = 0;
+
+                       stream->prev.real.begin = 0;
+                       stream->prev.real.end = 0;
+                       stream->prev.cycles.begin = 0;
+                       stream->prev.cycles.end = 0;
 
                        printf_debug("restored to cur_index = %" PRId64 " and "
                                "offset = %" PRId64 ", timestamp = %" PRIu64 "\n",