From 2654fe9bab8f0eaeb17264ef7abadfd14e245b23 Mon Sep 17 00:00:00 2001 From: Mathieu Desnoyers Date: Tue, 25 Feb 2014 17:36:11 -0500 Subject: [PATCH] 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 --- formats/ctf-text/ctf-text.c | 10 +- formats/ctf/ctf.c | 153 +++++++++++++---------- include/babeltrace/babeltrace-internal.h | 1 + include/babeltrace/ctf-ir/metadata.h | 16 ++- include/babeltrace/ctf/events-internal.h | 2 - lib/iterator.c | 13 +- 6 files changed, 110 insertions(+), 85 deletions(-) diff --git a/formats/ctf-text/ctf-text.c b/formats/ctf-text/ctf-text.c index 48ce31b8..9d5123a1 100644 --- 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 4c64c930..e31808c3 100644 --- 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 1f379ee7..c9345509 100644 --- 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 93c7a586..67536958 100644 --- 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 2e37693a..48caa544 100644 --- 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 74942ac8..d2464ab7 100644 --- 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", -- 2.34.1