X-Git-Url: http://git.efficios.com/?a=blobdiff_plain;f=src%2Fplugins%2Fctf%2Fcommon%2Fmsg-iter%2Fmsg-iter.c;h=f941970db67c3fdbc92866c8889d4a78979efdc5;hb=977d6cc05226fb841d687e64fc4f101bac3c512e;hp=99c585980bf8db9b97f151c3921676613ab1b9be;hpb=ed6d5d5c386154fc0315a077bb38dacf32b63f7c;p=babeltrace.git diff --git a/src/plugins/ctf/common/msg-iter/msg-iter.c b/src/plugins/ctf/common/msg-iter/msg-iter.c index 99c58598..f941970d 100644 --- a/src/plugins/ctf/common/msg-iter/msg-iter.c +++ b/src/plugins/ctf/common/msg-iter/msg-iter.c @@ -23,8 +23,10 @@ * SOFTWARE. */ +#define BT_COMP_LOG_SELF_COMP (notit->self_comp) +#define BT_LOG_OUTPUT_LEVEL (notit->log_level) #define BT_LOG_TAG "PLUGIN/CTF/MSG-ITER" -#include "logging.h" +#include "logging/comp-logging.h" #include #include @@ -62,8 +64,12 @@ struct stack_entry { size_t index; }; +struct bt_msg_iter; + /* Visit stack */ struct stack { + struct bt_msg_iter *notit; + /* Entries (struct stack_entry) */ GArray *entries; @@ -74,6 +80,7 @@ struct stack { /* State */ enum state { STATE_INIT, + STATE_SWITCH_PACKET, STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN, STATE_DSCOPE_TRACE_PACKET_HEADER_CONTINUE, STATE_AFTER_TRACE_PACKET_HEADER, @@ -82,7 +89,6 @@ enum state { STATE_AFTER_STREAM_PACKET_CONTEXT, STATE_CHECK_EMIT_MSG_STREAM_BEGINNING, STATE_EMIT_MSG_STREAM_BEGINNING, - STATE_EMIT_MSG_STREAM_ACTIVITY_BEGINNING, STATE_CHECK_EMIT_MSG_DISCARDED_EVENTS, STATE_CHECK_EMIT_MSG_DISCARDED_PACKETS, STATE_EMIT_MSG_DISCARDED_EVENTS, @@ -98,11 +104,12 @@ enum state { STATE_DSCOPE_EVENT_PAYLOAD_BEGIN, STATE_DSCOPE_EVENT_PAYLOAD_CONTINUE, STATE_EMIT_MSG_EVENT, + STATE_EMIT_QUEUED_MSG_EVENT, STATE_SKIP_PACKET_PADDING, STATE_EMIT_MSG_PACKET_END_MULTI, STATE_EMIT_MSG_PACKET_END_SINGLE, - STATE_CHECK_EMIT_MSG_STREAM_ACTIVITY_END, - STATE_EMIT_MSG_STREAM_ACTIVITY_END, + STATE_CHECK_EMIT_MSG_STREAM_END, + STATE_EMIT_QUEUED_MSG_PACKET_END, STATE_EMIT_MSG_STREAM_END, STATE_DONE, }; @@ -122,15 +129,18 @@ struct bt_msg_iter { /* Current message iterator to create messages (weak) */ bt_self_message_iterator *msg_iter; - /* - * True to emit stream beginning and stream activity beginning - * messages. - */ + /* True to emit a stream beginning message. */ bool emit_stream_begin_msg; - /* True to emit stream end and stream activity end messages */ + /* True to emit a stream end message. */ bool emit_stream_end_msg; + /* + * True if library objects are unavailable during the decoding and + * should not be created/used. + */ + bool dry_run; + /* True to set the stream */ bool set_stream; @@ -173,6 +183,12 @@ struct bt_msg_iter { /* Current event message (NULL if not created yet) */ bt_message *event_msg; + /* + * True if we need to emit a packet beginning message before we emit + * the next event message or the packet end message. + */ + bool emit_delayed_packet_beginning_msg; + /* Database of current dynamic scopes */ struct { bt_field *stream_packet_context; @@ -244,6 +260,12 @@ struct bt_msg_iter { /* Stored values (for sequence lengths, variant tags) */ GArray *stored_values; + + /* Iterator's current log level */ + bt_logging_level log_level; + + /* Iterator's owning self component, or `NULL` if none (query) */ + bt_self_component *self_comp; }; static inline @@ -251,69 +273,68 @@ const char *state_string(enum state state) { switch (state) { case STATE_INIT: - return "STATE_INIT"; + return "INIT"; + case STATE_SWITCH_PACKET: + return "SWITCH_PACKET"; case STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN: - return "STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN"; + return "DSCOPE_TRACE_PACKET_HEADER_BEGIN"; case STATE_DSCOPE_TRACE_PACKET_HEADER_CONTINUE: - return "STATE_DSCOPE_TRACE_PACKET_HEADER_CONTINUE"; + return "DSCOPE_TRACE_PACKET_HEADER_CONTINUE"; case STATE_AFTER_TRACE_PACKET_HEADER: - return "STATE_AFTER_TRACE_PACKET_HEADER"; + return "AFTER_TRACE_PACKET_HEADER"; case STATE_DSCOPE_STREAM_PACKET_CONTEXT_BEGIN: - return "STATE_DSCOPE_STREAM_PACKET_CONTEXT_BEGIN"; + return "DSCOPE_STREAM_PACKET_CONTEXT_BEGIN"; case STATE_DSCOPE_STREAM_PACKET_CONTEXT_CONTINUE: - return "STATE_DSCOPE_STREAM_PACKET_CONTEXT_CONTINUE"; + return "DSCOPE_STREAM_PACKET_CONTEXT_CONTINUE"; case STATE_AFTER_STREAM_PACKET_CONTEXT: - return "STATE_AFTER_STREAM_PACKET_CONTEXT"; + return "AFTER_STREAM_PACKET_CONTEXT"; case STATE_EMIT_MSG_STREAM_BEGINNING: - return "STATE_EMIT_MSG_STREAM_BEGINNING"; - case STATE_EMIT_MSG_STREAM_ACTIVITY_BEGINNING: - return "STATE_EMIT_MSG_STREAM_ACTIVITY_BEGINNING"; + return "EMIT_MSG_STREAM_BEGINNING"; case STATE_EMIT_MSG_PACKET_BEGINNING: - return "STATE_EMIT_MSG_PACKET_BEGINNING"; + return "EMIT_MSG_PACKET_BEGINNING"; case STATE_EMIT_MSG_DISCARDED_EVENTS: - return "STATE_EMIT_MSG_DISCARDED_EVENTS"; + return "EMIT_MSG_DISCARDED_EVENTS"; case STATE_EMIT_MSG_DISCARDED_PACKETS: - return "STATE_EMIT_MSG_DISCARDED_PACKETS"; + return "EMIT_MSG_DISCARDED_PACKETS"; case STATE_DSCOPE_EVENT_HEADER_BEGIN: - return "STATE_DSCOPE_EVENT_HEADER_BEGIN"; + return "DSCOPE_EVENT_HEADER_BEGIN"; case STATE_DSCOPE_EVENT_HEADER_CONTINUE: - return "STATE_DSCOPE_EVENT_HEADER_CONTINUE"; + return "DSCOPE_EVENT_HEADER_CONTINUE"; case STATE_AFTER_EVENT_HEADER: - return "STATE_AFTER_EVENT_HEADER"; + return "AFTER_EVENT_HEADER"; case STATE_DSCOPE_EVENT_COMMON_CONTEXT_BEGIN: - return "STATE_DSCOPE_EVENT_COMMON_CONTEXT_BEGIN"; + return "DSCOPE_EVENT_COMMON_CONTEXT_BEGIN"; case STATE_DSCOPE_EVENT_COMMON_CONTEXT_CONTINUE: - return "STATE_DSCOPE_EVENT_COMMON_CONTEXT_CONTINUE"; + return "DSCOPE_EVENT_COMMON_CONTEXT_CONTINUE"; case STATE_DSCOPE_EVENT_SPEC_CONTEXT_BEGIN: - return "STATE_DSCOPE_EVENT_SPEC_CONTEXT_BEGIN"; + return "DSCOPE_EVENT_SPEC_CONTEXT_BEGIN"; case STATE_DSCOPE_EVENT_SPEC_CONTEXT_CONTINUE: - return "STATE_DSCOPE_EVENT_SPEC_CONTEXT_CONTINUE"; + return "DSCOPE_EVENT_SPEC_CONTEXT_CONTINUE"; case STATE_DSCOPE_EVENT_PAYLOAD_BEGIN: - return "STATE_DSCOPE_EVENT_PAYLOAD_BEGIN"; + return "DSCOPE_EVENT_PAYLOAD_BEGIN"; case STATE_DSCOPE_EVENT_PAYLOAD_CONTINUE: - return "STATE_DSCOPE_EVENT_PAYLOAD_CONTINUE"; + return "DSCOPE_EVENT_PAYLOAD_CONTINUE"; case STATE_EMIT_MSG_EVENT: - return "STATE_EMIT_MSG_EVENT"; + return "EMIT_MSG_EVENT"; + case STATE_EMIT_QUEUED_MSG_EVENT: + return "EMIT_QUEUED_MSG_EVENT"; case STATE_SKIP_PACKET_PADDING: - return "STATE_SKIP_PACKET_PADDING"; + return "SKIP_PACKET_PADDING"; case STATE_EMIT_MSG_PACKET_END_MULTI: - return "STATE_EMIT_MSG_PACKET_END_MULTI"; + return "EMIT_MSG_PACKET_END_MULTI"; case STATE_EMIT_MSG_PACKET_END_SINGLE: - return "STATE_EMIT_MSG_PACKET_END_SINGLE"; - case STATE_EMIT_MSG_STREAM_ACTIVITY_END: - return "STATE_EMIT_MSG_STREAM_ACTIVITY_END"; + return "EMIT_MSG_PACKET_END_SINGLE"; + case STATE_EMIT_QUEUED_MSG_PACKET_END: + return "EMIT_QUEUED_MSG_PACKET_END"; case STATE_EMIT_MSG_STREAM_END: - return "STATE_EMIT_MSG_STREAM_END"; + return "EMIT_MSG_STREAM_END"; case STATE_DONE: - return "STATE_DONE"; + return "DONE"; default: return "(unknown)"; } } -static -int bt_msg_iter_switch_packet(struct bt_msg_iter *notit); - static struct stack *stack_new(struct bt_msg_iter *notit) { @@ -321,17 +342,18 @@ struct stack *stack_new(struct bt_msg_iter *notit) stack = g_new0(struct stack, 1); if (!stack) { - BT_LOGE_STR("Failed to allocate one stack."); + BT_COMP_LOGE_STR("Failed to allocate one stack."); goto error; } + stack->notit = notit; stack->entries = g_array_new(FALSE, TRUE, sizeof(struct stack_entry)); if (!stack->entries) { - BT_LOGE_STR("Failed to allocate a GArray."); + BT_COMP_LOGE_STR("Failed to allocate a GArray."); goto error; } - BT_LOGD("Created stack: notit-addr=%p, stack-addr=%p", notit, stack); + BT_COMP_LOGD("Created stack: notit-addr=%p, stack-addr=%p", notit, stack); goto end; error: @@ -345,8 +367,11 @@ end: static void stack_destroy(struct stack *stack) { - BT_ASSERT(stack); - BT_LOGD("Destroying stack: addr=%p", stack); + struct bt_msg_iter *notit; + + BT_ASSERT_DBG(stack); + notit = stack->notit; + BT_COMP_LOGD("Destroying stack: addr=%p", stack); if (stack->entries) { g_array_free(stack->entries, TRUE); @@ -359,10 +384,12 @@ static void stack_push(struct stack *stack, bt_field *base) { struct stack_entry *entry; + struct bt_msg_iter *notit; - BT_ASSERT(stack); - BT_ASSERT(base); - BT_LOGV("Pushing base field on stack: stack-addr=%p, " + BT_ASSERT_DBG(stack); + notit = stack->notit; + BT_ASSERT_DBG(base); + BT_COMP_LOGT("Pushing base field on stack: stack-addr=%p, " "stack-size-before=%zu, stack-size-after=%zu", stack, stack->size, stack->size + 1); @@ -379,16 +406,19 @@ void stack_push(struct stack *stack, bt_field *base) static inline unsigned int stack_size(struct stack *stack) { - BT_ASSERT(stack); + BT_ASSERT_DBG(stack); return stack->size; } static void stack_pop(struct stack *stack) { - BT_ASSERT(stack); - BT_ASSERT(stack_size(stack)); - BT_LOGV("Popping from stack: " + struct bt_msg_iter *notit; + + BT_ASSERT_DBG(stack); + BT_ASSERT_DBG(stack_size(stack)); + notit = stack->notit; + BT_COMP_LOGT("Popping from stack: " "stack-addr=%p, stack-size-before=%zu, stack-size-after=%zu", stack, stack->size, stack->size - 1); stack->size--; @@ -397,8 +427,8 @@ void stack_pop(struct stack *stack) static inline struct stack_entry *stack_top(struct stack *stack) { - BT_ASSERT(stack); - BT_ASSERT(stack_size(stack)); + BT_ASSERT_DBG(stack); + BT_ASSERT_DBG(stack_size(stack)); return &g_array_index(stack->entries, struct stack_entry, stack->size - 1); } @@ -412,7 +442,7 @@ bool stack_empty(struct stack *stack) static void stack_clear(struct stack *stack) { - BT_ASSERT(stack); + BT_ASSERT_DBG(stack); stack->size = 0; } @@ -445,7 +475,7 @@ size_t packet_at(struct bt_msg_iter *notit) static inline void buf_consume_bits(struct bt_msg_iter *notit, size_t incr) { - BT_LOGV("Advancing cursor: notit-addr=%p, cur-before=%zu, cur-after=%zu", + BT_COMP_LOGT("Advancing cursor: notit-addr=%p, cur-before=%zu, cur-after=%zu", notit, notit->buf.at, notit->buf.at + incr); notit->buf.at += incr; } @@ -458,12 +488,12 @@ enum bt_msg_iter_status request_medium_bytes( size_t buffer_sz = 0; enum bt_msg_iter_medium_status m_status; - BT_LOGD("Calling user function (request bytes): notit-addr=%p, " + BT_COMP_LOGD("Calling user function (request bytes): notit-addr=%p, " "request-size=%zu", notit, notit->medium.max_request_sz); m_status = notit->medium.medops.request_bytes( notit->medium.max_request_sz, &buffer_addr, &buffer_sz, notit->medium.data); - BT_LOGD("User function returned: status=%s, buf-addr=%p, buf-size=%zu", + BT_COMP_LOGD("User function returned: status=%s, buf-addr=%p, buf-size=%zu", bt_msg_iter_medium_status_string(m_status), buffer_addr, buffer_sz); if (m_status == BT_MSG_ITER_MEDIUM_STATUS_OK) { @@ -482,11 +512,11 @@ enum bt_msg_iter_status request_medium_bytes( /* New medium buffer address */ notit->buf.addr = buffer_addr; - BT_LOGD("User function returned new bytes: " + BT_COMP_LOGD("User function returned new bytes: " "packet-offset=%zu, cur=%zu, size=%zu, addr=%p", notit->buf.packet_offset, notit->buf.at, notit->buf.sz, notit->buf.addr); - BT_LOGD_MEM(buffer_addr, buffer_sz, "Returned bytes at %p:", + BT_COMP_LOGD_MEM(buffer_addr, buffer_sz, "Returned bytes at %p:", buffer_addr); } else if (m_status == BT_MSG_ITER_MEDIUM_STATUS_EOF) { /* @@ -511,7 +541,7 @@ enum bt_msg_iter_status request_medium_bytes( } /* All other states are invalid */ - BT_LOGW("User function returned %s, but message iterator is in an unexpected state: " + BT_COMP_LOGW("User function returned %s, but message iterator is in an unexpected state: " "state=%s, cur-packet-size=%" PRId64 ", cur=%zu, " "packet-cur=%zu, last-eh-at=%zu", bt_msg_iter_medium_status_string(m_status), @@ -521,7 +551,7 @@ enum bt_msg_iter_status request_medium_bytes( notit->buf.last_eh_at); m_status = BT_MSG_ITER_MEDIUM_STATUS_ERROR; } else if (m_status < 0) { - BT_LOGW("User function failed: status=%s", + BT_COMP_LOGW("User function failed: status=%s", bt_msg_iter_medium_status_string(m_status)); } @@ -558,25 +588,25 @@ enum bt_msg_iter_status read_dscope_begin_state( size_t consumed_bits; notit->cur_dscope_field = dscope_field; - BT_LOGV("Starting BFCR: notit-addr=%p, bfcr-addr=%p, fc-addr=%p", + BT_COMP_LOGT("Starting BFCR: notit-addr=%p, bfcr-addr=%p, fc-addr=%p", notit, notit->bfcr, dscope_fc); consumed_bits = bt_bfcr_start(notit->bfcr, dscope_fc, notit->buf.addr, notit->buf.at, packet_at(notit), notit->buf.sz, &bfcr_status); - BT_LOGV("BFCR consumed bits: size=%zu", consumed_bits); + BT_COMP_LOGT("BFCR consumed bits: size=%zu", consumed_bits); switch (bfcr_status) { case BT_BFCR_STATUS_OK: /* Field class was read completely */ - BT_LOGV_STR("Field was completely decoded."); + BT_COMP_LOGT_STR("Field was completely decoded."); notit->state = done_state; break; case BT_BFCR_STATUS_EOF: - BT_LOGV_STR("BFCR needs more data to decode field completely."); + BT_COMP_LOGT_STR("BFCR needs more data to decode field completely."); notit->state = continue_state; break; default: - BT_LOGW("BFCR failed to start: notit-addr=%p, bfcr-addr=%p, " + BT_COMP_LOGW("BFCR failed to start: notit-addr=%p, bfcr-addr=%p, " "status=%s", notit, notit->bfcr, bt_bfcr_status_string(bfcr_status)); status = BT_MSG_ITER_STATUS_ERROR; @@ -598,17 +628,17 @@ enum bt_msg_iter_status read_dscope_continue_state( enum bt_bfcr_status bfcr_status; size_t consumed_bits; - BT_LOGV("Continuing BFCR: notit-addr=%p, bfcr-addr=%p", + BT_COMP_LOGT("Continuing BFCR: notit-addr=%p, bfcr-addr=%p", notit, notit->bfcr); status = buf_ensure_available_bits(notit); if (status != BT_MSG_ITER_STATUS_OK) { if (status < 0) { - BT_LOGW("Cannot ensure that buffer has at least one byte: " + BT_COMP_LOGW("Cannot ensure that buffer has at least one byte: " "msg-addr=%p, status=%s", notit, bt_msg_iter_status_string(status)); } else { - BT_LOGV("Cannot ensure that buffer has at least one byte: " + BT_COMP_LOGT("Cannot ensure that buffer has at least one byte: " "msg-addr=%p, status=%s", notit, bt_msg_iter_status_string(status)); } @@ -618,20 +648,20 @@ enum bt_msg_iter_status read_dscope_continue_state( consumed_bits = bt_bfcr_continue(notit->bfcr, notit->buf.addr, notit->buf.sz, &bfcr_status); - BT_LOGV("BFCR consumed bits: size=%zu", consumed_bits); + BT_COMP_LOGT("BFCR consumed bits: size=%zu", consumed_bits); switch (bfcr_status) { case BT_BFCR_STATUS_OK: /* Type was read completely. */ - BT_LOGV_STR("Field was completely decoded."); + BT_COMP_LOGT_STR("Field was completely decoded."); notit->state = done_state; break; case BT_BFCR_STATUS_EOF: /* Stay in this continue state. */ - BT_LOGV_STR("BFCR needs more data to decode field completely."); + BT_COMP_LOGT_STR("BFCR needs more data to decode field completely."); break; default: - BT_LOGW("BFCR failed to continue: notit-addr=%p, bfcr-addr=%p, " + BT_COMP_LOGW("BFCR failed to continue: notit-addr=%p, bfcr-addr=%p, " "status=%s", notit, notit->bfcr, bt_bfcr_status_string(bfcr_status)); status = BT_MSG_ITER_STATUS_ERROR; @@ -665,31 +695,90 @@ void release_all_dscopes(struct bt_msg_iter *notit) release_event_dscopes(notit); } +static +enum bt_msg_iter_status switch_packet_state(struct bt_msg_iter *notit) +{ + enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; + + /* + * We don't put the stream class here because we need to make + * sure that all the packets processed by the same message + * iterator refer to the same stream class (the first one). + */ + BT_ASSERT(notit); + + if (notit->cur_exp_packet_total_size != -1) { + notit->cur_packet_offset += notit->cur_exp_packet_total_size; + } + + BT_COMP_LOGD("Switching packet: notit-addr=%p, cur=%zu, " + "packet-offset=%" PRId64, notit, notit->buf.at, + notit->cur_packet_offset); + stack_clear(notit->stack); + notit->meta.ec = NULL; + BT_PACKET_PUT_REF_AND_RESET(notit->packet); + BT_MESSAGE_PUT_REF_AND_RESET(notit->event_msg); + release_all_dscopes(notit); + notit->cur_dscope_field = NULL; + + /* + * Adjust current buffer so that addr points to the beginning of the new + * packet. + */ + if (notit->buf.addr) { + size_t consumed_bytes = (size_t) (notit->buf.at / CHAR_BIT); + + /* Packets are assumed to start on a byte frontier. */ + if (notit->buf.at % CHAR_BIT) { + BT_COMP_LOGW("Cannot switch packet: current position is not a multiple of 8: " + "notit-addr=%p, cur=%zu", notit, notit->buf.at); + status = BT_MSG_ITER_STATUS_ERROR; + goto end; + } + + notit->buf.addr += consumed_bytes; + notit->buf.sz -= consumed_bytes; + notit->buf.at = 0; + notit->buf.packet_offset = 0; + BT_COMP_LOGD("Adjusted buffer: addr=%p, size=%zu", + notit->buf.addr, notit->buf.sz); + } + + notit->cur_exp_packet_content_size = -1; + notit->cur_exp_packet_total_size = -1; + notit->cur_stream_class_id = -1; + notit->cur_event_class_id = -1; + notit->cur_data_stream_id = -1; + notit->prev_packet_snapshots = notit->snapshots; + notit->snapshots.discarded_events = UINT64_C(-1); + notit->snapshots.packets = UINT64_C(-1); + notit->snapshots.beginning_clock = UINT64_C(-1); + notit->snapshots.end_clock = UINT64_C(-1); + notit->state = STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN; + +end: + return status; +} + static enum bt_msg_iter_status read_packet_header_begin_state( struct bt_msg_iter *notit) { struct ctf_field_class *packet_header_fc = NULL; - enum bt_msg_iter_status ret = BT_MSG_ITER_STATUS_OK; - - if (bt_msg_iter_switch_packet(notit)) { - BT_LOGW("Cannot switch packet: notit-addr=%p", notit); - ret = BT_MSG_ITER_STATUS_ERROR; - goto end; - } + enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; /* * Make sure at least one bit is available for this packet. An * empty packet is impossible. If we reach the end of the medium * at this point, then it's considered the end of the stream. */ - ret = buf_ensure_available_bits(notit); - switch (ret) { + status = buf_ensure_available_bits(notit); + switch (status) { case BT_MSG_ITER_STATUS_OK: break; case BT_MSG_ITER_STATUS_EOF: - ret = BT_MSG_ITER_STATUS_OK; - notit->state = STATE_CHECK_EMIT_MSG_STREAM_ACTIVITY_END; + status = BT_MSG_ITER_STATUS_OK; + notit->state = STATE_CHECK_EMIT_MSG_STREAM_END; goto end; default: goto end; @@ -705,21 +794,21 @@ enum bt_msg_iter_status read_packet_header_begin_state( notit->cur_stream_class_id = -1; notit->cur_event_class_id = -1; notit->cur_data_stream_id = -1; - BT_LOGD("Decoding packet header field:" + BT_COMP_LOGD("Decoding packet header field:" "notit-addr=%p, trace-class-addr=%p, fc-addr=%p", notit, notit->meta.tc, packet_header_fc); - ret = read_dscope_begin_state(notit, packet_header_fc, + status = read_dscope_begin_state(notit, packet_header_fc, STATE_AFTER_TRACE_PACKET_HEADER, STATE_DSCOPE_TRACE_PACKET_HEADER_CONTINUE, NULL); - if (ret < 0) { - BT_LOGW("Cannot decode packet header field: " + if (status < 0) { + BT_COMP_LOGW("Cannot decode packet header field: " "notit-addr=%p, trace-class-addr=%p, " "fc-addr=%p", notit, notit->meta.tc, packet_header_fc); } end: - return ret; + return status; } static @@ -742,7 +831,7 @@ enum bt_msg_iter_status set_current_stream_class(struct bt_msg_iter *notit) * stream class. */ if (notit->meta.tc->stream_classes->len != 1) { - BT_LOGW("Need exactly one stream class since there's " + BT_COMP_LOGW("Need exactly one stream class since there's " "no stream class ID field: " "notit-addr=%p", notit); status = BT_MSG_ITER_STATUS_ERROR; @@ -756,7 +845,7 @@ enum bt_msg_iter_status set_current_stream_class(struct bt_msg_iter *notit) new_stream_class = ctf_trace_class_borrow_stream_class_by_id( notit->meta.tc, notit->cur_stream_class_id); if (!new_stream_class) { - BT_LOGW("No stream class with ID of stream class ID to use in trace class: " + BT_COMP_LOGW("No stream class with ID of stream class ID to use in trace class: " "notit-addr=%p, stream-class-id=%" PRIu64 ", " "trace-class-addr=%p", notit, notit->cur_stream_class_id, notit->meta.tc); @@ -766,7 +855,7 @@ enum bt_msg_iter_status set_current_stream_class(struct bt_msg_iter *notit) if (notit->meta.sc) { if (new_stream_class != notit->meta.sc) { - BT_LOGW("Two packets refer to two different stream classes within the same packet sequence: " + BT_COMP_LOGW("Two packets refer to two different stream classes within the same packet sequence: " "notit-addr=%p, prev-stream-class-addr=%p, " "prev-stream-class-id=%" PRId64 ", " "next-stream-class-addr=%p, " @@ -784,7 +873,7 @@ enum bt_msg_iter_status set_current_stream_class(struct bt_msg_iter *notit) notit->meta.sc = new_stream_class; } - BT_LOGD("Set current stream class: " + BT_COMP_LOGD("Set current stream class: " "notit-addr=%p, stream-class-addr=%p, " "stream-class-id=%" PRId64, notit, notit->meta.sc, notit->meta.sc->id); @@ -799,7 +888,7 @@ enum bt_msg_iter_status set_current_stream(struct bt_msg_iter *notit) enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; bt_stream *stream = NULL; - BT_LOGD("Calling user function (get stream): notit-addr=%p, " + BT_COMP_LOGD("Calling user function (get stream): notit-addr=%p, " "stream-class-addr=%p, stream-class-id=%" PRId64, notit, notit->meta.sc, notit->meta.sc->id); @@ -807,16 +896,16 @@ enum bt_msg_iter_status set_current_stream(struct bt_msg_iter *notit) notit->meta.sc->ir_sc, notit->cur_data_stream_id, notit->medium.data); bt_stream_get_ref(stream); - BT_LOGD("User function returned: stream-addr=%p", stream); + BT_COMP_LOGD("User function returned: stream-addr=%p", stream); if (!stream) { - BT_LOGW_STR("User function failed to return a stream object " + BT_COMP_LOGW_STR("User function failed to return a stream object " "for the given stream class."); status = BT_MSG_ITER_STATUS_ERROR; goto end; } if (notit->stream && stream != notit->stream) { - BT_LOGW("User function returned a different stream than the " + BT_COMP_LOGW("User function returned a different stream than the " "previous one for the same sequence of packets."); status = BT_MSG_ITER_STATUS_ERROR; goto end; @@ -835,9 +924,7 @@ enum bt_msg_iter_status set_current_packet(struct bt_msg_iter *notit) enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; bt_packet *packet = NULL; - BT_LOGD("Creating packet for packet message: " - "notit-addr=%p", notit); - BT_LOGD("Creating packet from stream: " + BT_COMP_LOGD("Creating packet from stream: " "notit-addr=%p, stream-addr=%p, " "stream-class-addr=%p, " "stream-class-id=%" PRId64, @@ -848,7 +935,7 @@ enum bt_msg_iter_status set_current_packet(struct bt_msg_iter *notit) BT_ASSERT(notit->stream); packet = bt_packet_create(notit->stream); if (!packet) { - BT_LOGE("Cannot create packet from stream: " + BT_COMP_LOGE("Cannot create packet from stream: " "notit-addr=%p, stream-addr=%p, " "stream-class-addr=%p, " "stream-class-id=%" PRId64, @@ -895,7 +982,7 @@ enum bt_msg_iter_status read_packet_context_begin_state( BT_ASSERT(notit->meta.sc); packet_context_fc = notit->meta.sc->packet_context_fc; if (!packet_context_fc) { - BT_LOGD("No packet packet context field class in stream class: continuing: " + BT_COMP_LOGD("No packet packet context field class in stream class: continuing: " "notit-addr=%p, stream-class-addr=%p, " "stream-class-id=%" PRId64, notit, notit->meta.sc, @@ -906,7 +993,7 @@ enum bt_msg_iter_status read_packet_context_begin_state( BT_ASSERT(!notit->packet_context_field); - if (packet_context_fc->in_ir) { + if (packet_context_fc->in_ir && !notit->dry_run) { /* * Create free packet context field from stream class. * This field is going to be moved to the packet once we @@ -920,7 +1007,7 @@ enum bt_msg_iter_status read_packet_context_begin_state( bt_packet_context_field_create( notit->meta.sc->ir_sc); if (!notit->packet_context_field) { - BT_LOGE_STR("Cannot create packet context field wrapper from stream class."); + BT_COMP_LOGE_STR("Cannot create packet context field wrapper from stream class."); status = BT_MSG_ITER_STATUS_ERROR; goto end; } @@ -931,7 +1018,7 @@ enum bt_msg_iter_status read_packet_context_begin_state( BT_ASSERT(notit->dscopes.stream_packet_context); } - BT_LOGD("Decoding packet context field: " + BT_COMP_LOGD("Decoding packet context field: " "notit-addr=%p, stream-class-addr=%p, " "stream-class-id=%" PRId64 ", fc-addr=%p", notit, notit->meta.sc, @@ -941,7 +1028,7 @@ enum bt_msg_iter_status read_packet_context_begin_state( STATE_DSCOPE_STREAM_PACKET_CONTEXT_CONTINUE, notit->dscopes.stream_packet_context); if (status < 0) { - BT_LOGW("Cannot decode packet context field: " + BT_COMP_LOGW("Cannot decode packet context field: " "notit-addr=%p, stream-class-addr=%p, " "stream-class-id=%" PRId64 ", fc-addr=%p", notit, notit->meta.sc, @@ -986,7 +1073,7 @@ enum bt_msg_iter_status set_current_packet_content_sizes( if (notit->cur_exp_packet_content_size > notit->cur_exp_packet_total_size) { - BT_LOGW("Invalid packet or content size: " + BT_COMP_LOGW("Invalid packet or content size: " "content size is greater than packet size: " "notit-addr=%p, packet-context-field-addr=%p, " "packet-size=%" PRId64 ", content-size=%" PRId64, @@ -997,7 +1084,7 @@ enum bt_msg_iter_status set_current_packet_content_sizes( goto end; } - BT_LOGD("Set current packet and content sizes: " + BT_COMP_LOGD("Set current packet and content sizes: " "notit-addr=%p, packet-size=%" PRIu64 ", content-size=%" PRIu64, notit, notit->cur_exp_packet_total_size, notit->cur_exp_packet_content_size); @@ -1046,14 +1133,14 @@ enum bt_msg_iter_status read_event_header_begin_state(struct bt_msg_iter *notit) if (G_UNLIKELY(packet_at(notit) == notit->cur_exp_packet_content_size)) { /* No more events! */ - BT_LOGD("Reached end of packet: notit-addr=%p, " + BT_COMP_LOGD("Reached end of packet: notit-addr=%p, " "cur=%zu", notit, packet_at(notit)); notit->state = STATE_EMIT_MSG_PACKET_END_MULTI; goto end; } else if (G_UNLIKELY(packet_at(notit) > notit->cur_exp_packet_content_size)) { /* That's not supposed to happen */ - BT_LOGD("Before decoding event header field: cursor is passed the packet's content: " + BT_COMP_LOGD("Before decoding event header field: cursor is passed the packet's content: " "notit-addr=%p, content-size=%" PRId64 ", " "cur=%zu", notit, notit->cur_exp_packet_content_size, @@ -1087,7 +1174,7 @@ enum bt_msg_iter_status read_event_header_begin_state(struct bt_msg_iter *notit) goto end; } - BT_LOGD("Decoding event header field: " + BT_COMP_LOGD("Decoding event header field: " "notit-addr=%p, stream-class-addr=%p, " "stream-class-id=%" PRId64 ", " "fc-addr=%p", @@ -1098,7 +1185,7 @@ enum bt_msg_iter_status read_event_header_begin_state(struct bt_msg_iter *notit) STATE_AFTER_EVENT_HEADER, STATE_DSCOPE_EVENT_HEADER_CONTINUE, NULL); if (status < 0) { - BT_LOGW("Cannot decode event header field: " + BT_COMP_LOGW("Cannot decode event header field: " "notit-addr=%p, stream-class-addr=%p, " "stream-class-id=%" PRId64 ", fc-addr=%p", notit, notit->meta.sc, @@ -1131,7 +1218,7 @@ enum bt_msg_iter_status set_current_event_class(struct bt_msg_iter *notit) * event class. */ if (notit->meta.sc->event_classes->len != 1) { - BT_LOGW("Need exactly one event class since there's " + BT_COMP_LOGW("Need exactly one event class since there's " "no event class ID field: " "notit-addr=%p", notit); status = BT_MSG_ITER_STATUS_ERROR; @@ -1145,7 +1232,7 @@ enum bt_msg_iter_status set_current_event_class(struct bt_msg_iter *notit) new_event_class = ctf_stream_class_borrow_event_class_by_id( notit->meta.sc, notit->cur_event_class_id); if (!new_event_class) { - BT_LOGW("No event class with ID of event class ID to use in stream class: " + BT_COMP_LOGW("No event class with ID of event class ID to use in stream class: " "notit-addr=%p, stream-class-id=%" PRIu64 ", " "event-class-id=%" PRIu64 ", " "trace-class-addr=%p", @@ -1156,7 +1243,7 @@ enum bt_msg_iter_status set_current_event_class(struct bt_msg_iter *notit) } notit->meta.ec = new_event_class; - BT_LOGD("Set current event class: " + BT_COMP_LOGD("Set current event class: " "notit-addr=%p, event-class-addr=%p, " "event-class-id=%" PRId64 ", " "event-class-name=\"%s\"", @@ -1174,27 +1261,27 @@ enum bt_msg_iter_status set_current_event_message( enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; bt_message *msg = NULL; - BT_ASSERT(notit->meta.ec); - BT_ASSERT(notit->packet); - BT_LOGD("Creating event message from event class and packet: " + BT_ASSERT_DBG(notit->meta.ec); + BT_ASSERT_DBG(notit->packet); + BT_COMP_LOGD("Creating event message from event class and packet: " "notit-addr=%p, ec-addr=%p, ec-name=\"%s\", packet-addr=%p", notit, notit->meta.ec, notit->meta.ec->name->str, notit->packet); - BT_ASSERT(notit->msg_iter); - BT_ASSERT(notit->meta.sc); + BT_ASSERT_DBG(notit->msg_iter); + BT_ASSERT_DBG(notit->meta.sc); if (bt_stream_class_borrow_default_clock_class(notit->meta.sc->ir_sc)) { - msg = bt_message_event_create_with_default_clock_snapshot( + msg = bt_message_event_create_with_packet_and_default_clock_snapshot( notit->msg_iter, notit->meta.ec->ir_ec, notit->packet, notit->default_clock_snapshot); } else { - msg = bt_message_event_create(notit->msg_iter, + msg = bt_message_event_create_with_packet(notit->msg_iter, notit->meta.ec->ir_ec, notit->packet); } if (!msg) { - BT_LOGE("Cannot create event message: " + BT_COMP_LOGE("Cannot create event message: " "notit-addr=%p, ec-addr=%p, ec-name=\"%s\", " "packet-addr=%p", notit, notit->meta.ec, @@ -1225,6 +1312,10 @@ enum bt_msg_iter_status after_event_header_state( goto end; } + if (G_UNLIKELY(notit->dry_run)) { + goto next_state; + } + status = set_current_event_message(notit); if (status != BT_MSG_ITER_STATUS_OK) { goto end; @@ -1232,7 +1323,9 @@ enum bt_msg_iter_status after_event_header_state( notit->event = bt_message_event_borrow_event( notit->event_msg); - BT_ASSERT(notit->event); + BT_ASSERT_DBG(notit->event); + +next_state: notit->state = STATE_DSCOPE_EVENT_COMMON_CONTEXT_BEGIN; end: @@ -1252,15 +1345,15 @@ enum bt_msg_iter_status read_event_common_context_begin_state( goto end; } - if (event_common_context_fc->in_ir) { - BT_ASSERT(!notit->dscopes.event_common_context); + if (event_common_context_fc->in_ir && !notit->dry_run) { + BT_ASSERT_DBG(!notit->dscopes.event_common_context); notit->dscopes.event_common_context = bt_event_borrow_common_context_field( notit->event); - BT_ASSERT(notit->dscopes.event_common_context); + BT_ASSERT_DBG(notit->dscopes.event_common_context); } - BT_LOGV("Decoding event common context field: " + BT_COMP_LOGT("Decoding event common context field: " "notit-addr=%p, stream-class-addr=%p, " "stream-class-id=%" PRId64 ", " "fc-addr=%p", @@ -1272,7 +1365,7 @@ enum bt_msg_iter_status read_event_common_context_begin_state( STATE_DSCOPE_EVENT_COMMON_CONTEXT_CONTINUE, notit->dscopes.event_common_context); if (status < 0) { - BT_LOGW("Cannot decode event common context field: " + BT_COMP_LOGW("Cannot decode event common context field: " "notit-addr=%p, stream-class-addr=%p, " "stream-class-id=%" PRId64 ", fc-addr=%p", notit, notit->meta.sc, @@ -1305,15 +1398,15 @@ enum bt_msg_iter_status read_event_spec_context_begin_state( goto end; } - if (event_spec_context_fc->in_ir) { - BT_ASSERT(!notit->dscopes.event_spec_context); + if (event_spec_context_fc->in_ir && !notit->dry_run) { + BT_ASSERT_DBG(!notit->dscopes.event_spec_context); notit->dscopes.event_spec_context = bt_event_borrow_specific_context_field( notit->event); - BT_ASSERT(notit->dscopes.event_spec_context); + BT_ASSERT_DBG(notit->dscopes.event_spec_context); } - BT_LOGV("Decoding event specific context field: " + BT_COMP_LOGT("Decoding event specific context field: " "notit-addr=%p, event-class-addr=%p, " "event-class-name=\"%s\", event-class-id=%" PRId64 ", " "fc-addr=%p", @@ -1326,7 +1419,7 @@ enum bt_msg_iter_status read_event_spec_context_begin_state( STATE_DSCOPE_EVENT_SPEC_CONTEXT_CONTINUE, notit->dscopes.event_spec_context); if (status < 0) { - BT_LOGW("Cannot decode event specific context field: " + BT_COMP_LOGW("Cannot decode event specific context field: " "notit-addr=%p, event-class-addr=%p, " "event-class-name=\"%s\", " "event-class-id=%" PRId64 ", fc-addr=%p", @@ -1361,15 +1454,15 @@ enum bt_msg_iter_status read_event_payload_begin_state( goto end; } - if (event_payload_fc->in_ir) { - BT_ASSERT(!notit->dscopes.event_payload); + if (event_payload_fc->in_ir && !notit->dry_run) { + BT_ASSERT_DBG(!notit->dscopes.event_payload); notit->dscopes.event_payload = bt_event_borrow_payload_field( notit->event); - BT_ASSERT(notit->dscopes.event_payload); + BT_ASSERT_DBG(notit->dscopes.event_payload); } - BT_LOGV("Decoding event payload field: " + BT_COMP_LOGT("Decoding event payload field: " "notit-addr=%p, event-class-addr=%p, " "event-class-name=\"%s\", event-class-id=%" PRId64 ", " "fc-addr=%p", @@ -1382,7 +1475,7 @@ enum bt_msg_iter_status read_event_payload_begin_state( STATE_DSCOPE_EVENT_PAYLOAD_CONTINUE, notit->dscopes.event_payload); if (status < 0) { - BT_LOGW("Cannot decode event payload field: " + BT_COMP_LOGW("Cannot decode event payload field: " "notit-addr=%p, event-class-addr=%p, " "event-class-name=\"%s\", " "event-class-id=%" PRId64 ", fc-addr=%p", @@ -1408,16 +1501,17 @@ enum bt_msg_iter_status skip_packet_padding_state(struct bt_msg_iter *notit) { enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; size_t bits_to_skip; + const enum state next_state = STATE_SWITCH_PACKET; BT_ASSERT(notit->cur_exp_packet_total_size > 0); bits_to_skip = notit->cur_exp_packet_total_size - packet_at(notit); if (bits_to_skip == 0) { - notit->state = STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN; + notit->state = next_state; goto end; } else { size_t bits_to_consume; - BT_LOGD("Trying to skip %zu bits of padding: notit-addr=%p, size=%zu", + BT_COMP_LOGD("Trying to skip %zu bits of padding: notit-addr=%p, size=%zu", bits_to_skip, notit, bits_to_skip); status = buf_ensure_available_bits(notit); if (status != BT_MSG_ITER_STATUS_OK) { @@ -1425,13 +1519,13 @@ enum bt_msg_iter_status skip_packet_padding_state(struct bt_msg_iter *notit) } bits_to_consume = MIN(buf_available_bits(notit), bits_to_skip); - BT_LOGD("Skipping %zu bits of padding: notit-addr=%p, size=%zu", + BT_COMP_LOGD("Skipping %zu bits of padding: notit-addr=%p, size=%zu", bits_to_consume, notit, bits_to_consume); buf_consume_bits(notit, bits_to_consume); bits_to_skip = notit->cur_exp_packet_total_size - packet_at(notit); if (bits_to_skip == 0) { - notit->state = STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN; + notit->state = next_state; goto end; } } @@ -1549,11 +1643,11 @@ end: } static -enum bt_msg_iter_status check_emit_msg_stream_activity_end( +enum bt_msg_iter_status check_emit_msg_stream_end( struct bt_msg_iter *notit) { if (notit->emit_stream_end_msg) { - notit->state = STATE_EMIT_MSG_STREAM_ACTIVITY_END; + notit->state = STATE_EMIT_MSG_STREAM_END; } else { notit->state = STATE_DONE; } @@ -1567,13 +1661,16 @@ enum bt_msg_iter_status handle_state(struct bt_msg_iter *notit) enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; const enum state state = notit->state; - BT_LOGV("Handling state: notit-addr=%p, state=%s", + BT_COMP_LOGT("Handling state: notit-addr=%p, state=%s", notit, state_string(state)); // TODO: optimalize! switch (state) { case STATE_INIT: - notit->state = STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN; + notit->state = STATE_SWITCH_PACKET; + break; + case STATE_SWITCH_PACKET: + status = switch_packet_state(notit); break; case STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN: status = read_packet_header_begin_state(notit); @@ -1597,9 +1694,6 @@ enum bt_msg_iter_status handle_state(struct bt_msg_iter *notit) status = check_emit_msg_stream_beginning_state(notit); break; case STATE_EMIT_MSG_STREAM_BEGINNING: - notit->state = STATE_EMIT_MSG_STREAM_ACTIVITY_BEGINNING; - break; - case STATE_EMIT_MSG_STREAM_ACTIVITY_BEGINNING: notit->state = STATE_CHECK_EMIT_MSG_DISCARDED_EVENTS; break; case STATE_CHECK_EMIT_MSG_DISCARDED_EVENTS: @@ -1647,6 +1741,9 @@ enum bt_msg_iter_status handle_state(struct bt_msg_iter *notit) case STATE_EMIT_MSG_EVENT: notit->state = STATE_DSCOPE_EVENT_HEADER_BEGIN; break; + case STATE_EMIT_QUEUED_MSG_EVENT: + notit->state = STATE_EMIT_MSG_EVENT; + break; case STATE_SKIP_PACKET_PADDING: status = skip_packet_padding_state(notit); break; @@ -1654,13 +1751,13 @@ enum bt_msg_iter_status handle_state(struct bt_msg_iter *notit) notit->state = STATE_SKIP_PACKET_PADDING; break; case STATE_EMIT_MSG_PACKET_END_SINGLE: - notit->state = STATE_CHECK_EMIT_MSG_STREAM_ACTIVITY_END; + notit->state = STATE_CHECK_EMIT_MSG_STREAM_END; break; - case STATE_CHECK_EMIT_MSG_STREAM_ACTIVITY_END: - status = check_emit_msg_stream_activity_end(notit); + case STATE_CHECK_EMIT_MSG_STREAM_END: + status = check_emit_msg_stream_end(notit); break; - case STATE_EMIT_MSG_STREAM_ACTIVITY_END: - notit->state = STATE_EMIT_MSG_STREAM_END; + case STATE_EMIT_QUEUED_MSG_PACKET_END: + notit->state = STATE_EMIT_MSG_PACKET_END_SINGLE; break; case STATE_EMIT_MSG_STREAM_END: notit->state = STATE_DONE; @@ -1668,12 +1765,12 @@ enum bt_msg_iter_status handle_state(struct bt_msg_iter *notit) case STATE_DONE: break; default: - BT_LOGF("Unknown CTF plugin message iterator state: " + BT_COMP_LOGF("Unknown CTF plugin message iterator state: " "notit-addr=%p, state=%d", notit, notit->state); abort(); } - BT_LOGV("Handled state: notit-addr=%p, status=%s, " + BT_COMP_LOGT("Handled state: notit-addr=%p, status=%s, " "prev-state=%s, cur-state=%s", notit, bt_msg_iter_status_string(status), state_string(state), state_string(notit->state)); @@ -1684,7 +1781,7 @@ BT_HIDDEN void bt_msg_iter_reset_for_next_stream_file(struct bt_msg_iter *notit) { BT_ASSERT(notit); - BT_LOGD("Resetting message iterator: addr=%p", notit); + BT_COMP_LOGD("Resetting message iterator: addr=%p", notit); stack_clear(notit->stack); notit->meta.sc = NULL; notit->meta.ec = NULL; @@ -1722,8 +1819,6 @@ void bt_msg_iter_reset(struct bt_msg_iter *notit) bt_msg_iter_reset_for_next_stream_file(notit); notit->cur_stream_class_id = -1; notit->cur_data_stream_id = -1; - notit->emit_stream_begin_msg = true; - notit->emit_stream_end_msg = true; notit->snapshots.discarded_events = UINT64_C(-1); notit->snapshots.packets = UINT64_C(-1); notit->prev_packet_snapshots.discarded_events = UINT64_C(-1); @@ -1732,113 +1827,46 @@ void bt_msg_iter_reset(struct bt_msg_iter *notit) notit->prev_packet_snapshots.end_clock = UINT64_C(-1); } -static -int bt_msg_iter_switch_packet(struct bt_msg_iter *notit) -{ - int ret = 0; - - /* - * We don't put the stream class here because we need to make - * sure that all the packets processed by the same message - * iterator refer to the same stream class (the first one). - */ - BT_ASSERT(notit); - - if (notit->cur_exp_packet_total_size != -1) { - notit->cur_packet_offset += notit->cur_exp_packet_total_size; - } - - BT_LOGD("Switching packet: notit-addr=%p, cur=%zu, " - "packet-offset=%" PRId64, notit, notit->buf.at, - notit->cur_packet_offset); - stack_clear(notit->stack); - notit->meta.ec = NULL; - BT_PACKET_PUT_REF_AND_RESET(notit->packet); - BT_MESSAGE_PUT_REF_AND_RESET(notit->event_msg); - release_all_dscopes(notit); - notit->cur_dscope_field = NULL; - - /* - * Adjust current buffer so that addr points to the beginning of the new - * packet. - */ - if (notit->buf.addr) { - size_t consumed_bytes = (size_t) (notit->buf.at / CHAR_BIT); - - /* Packets are assumed to start on a byte frontier. */ - if (notit->buf.at % CHAR_BIT) { - BT_LOGW("Cannot switch packet: current position is not a multiple of 8: " - "notit-addr=%p, cur=%zu", notit, notit->buf.at); - ret = -1; - goto end; - } - - notit->buf.addr += consumed_bytes; - notit->buf.sz -= consumed_bytes; - notit->buf.at = 0; - notit->buf.packet_offset = 0; - BT_LOGD("Adjusted buffer: addr=%p, size=%zu", - notit->buf.addr, notit->buf.sz); - } - - notit->cur_exp_packet_content_size = -1; - notit->cur_exp_packet_total_size = -1; - notit->cur_stream_class_id = -1; - notit->cur_event_class_id = -1; - notit->cur_data_stream_id = -1; - notit->prev_packet_snapshots = notit->snapshots; - notit->snapshots.discarded_events = UINT64_C(-1); - notit->snapshots.packets = UINT64_C(-1); - notit->snapshots.beginning_clock = UINT64_C(-1); - notit->snapshots.end_clock = UINT64_C(-1); - -end: - return ret; -} - static bt_field *borrow_next_field(struct bt_msg_iter *notit) { bt_field *next_field = NULL; bt_field *base_field; const bt_field_class *base_fc; + bt_field_class_type base_fc_type; size_t index; - BT_ASSERT(!stack_empty(notit->stack)); + BT_ASSERT_DBG(!stack_empty(notit->stack)); index = stack_top(notit->stack)->index; base_field = stack_top(notit->stack)->base; - BT_ASSERT(base_field); + BT_ASSERT_DBG(base_field); base_fc = bt_field_borrow_class_const(base_field); - BT_ASSERT(base_fc); + BT_ASSERT_DBG(base_fc); + base_fc_type = bt_field_class_get_type(base_fc); - switch (bt_field_class_get_type(base_fc)) { - case BT_FIELD_CLASS_TYPE_STRUCTURE: - { - BT_ASSERT(index < + if (base_fc_type == BT_FIELD_CLASS_TYPE_STRUCTURE) { + BT_ASSERT_DBG(index < bt_field_class_structure_get_member_count( bt_field_borrow_class_const( base_field))); next_field = bt_field_structure_borrow_member_field_by_index( base_field, index); - break; - } - case BT_FIELD_CLASS_TYPE_STATIC_ARRAY: - case BT_FIELD_CLASS_TYPE_DYNAMIC_ARRAY: - BT_ASSERT(index < bt_field_array_get_length(base_field)); + } else if (bt_field_class_type_is(base_fc_type, + BT_FIELD_CLASS_TYPE_ARRAY)) { + BT_ASSERT_DBG(index < bt_field_array_get_length(base_field)); next_field = bt_field_array_borrow_element_field_by_index( base_field, index); - break; - case BT_FIELD_CLASS_TYPE_VARIANT: - BT_ASSERT(index == 0); + } else if (bt_field_class_type_is(base_fc_type, + BT_FIELD_CLASS_TYPE_VARIANT)) { + BT_ASSERT_DBG(index == 0); next_field = bt_field_variant_borrow_selected_option_field( base_field); - break; - default: + } else { abort(); } - BT_ASSERT(next_field); + BT_ASSERT_DBG(next_field); return next_field; } @@ -1849,7 +1877,7 @@ void update_default_clock(struct bt_msg_iter *notit, uint64_t new_val, uint64_t new_val_mask; uint64_t cur_value_masked; - BT_ASSERT(new_val_size > 0); + BT_ASSERT_DBG(new_val_size > 0); /* * Special case for a 64-bit new value, which is the limit @@ -1880,7 +1908,7 @@ void update_default_clock(struct bt_msg_iter *notit, uint64_t new_val, notit->default_clock_snapshot |= new_val; end: - BT_LOGV("Updated default clock's value from integer field's value: " + BT_COMP_LOGT("Updated default clock's value from integer field's value: " "value=%" PRIu64, notit->default_clock_snapshot); } @@ -1893,7 +1921,7 @@ enum bt_bfcr_status bfcr_unsigned_int_cb(uint64_t value, bt_field *field = NULL; struct ctf_field_class_int *int_fc = (void *) fc; - BT_LOGV("Unsigned integer function called from BFCR: " + BT_COMP_LOGT("Unsigned integer function called from BFCR: " "notit-addr=%p, bfcr-addr=%p, fc-addr=%p, " "fc-type=%d, fc-in-ir=%d, value=%" PRIu64, notit, notit->bfcr, fc, fc->type, fc->in_ir, value); @@ -1920,7 +1948,7 @@ enum bt_bfcr_status bfcr_unsigned_int_cb(uint64_t value, break; case CTF_FIELD_CLASS_MEANING_MAGIC: if (value != 0xc1fc1fc1) { - BT_LOGW("Invalid CTF magic number: notit-addr=%p, " + BT_COMP_LOGW("Invalid CTF magic number: notit-addr=%p, " "magic=%" PRIx64, notit, value); status = BT_BFCR_STATUS_ERROR; goto end; @@ -1953,18 +1981,16 @@ update_def_clock: (uint64_t) int_fc->storing_index) = value; } - if (G_UNLIKELY(!fc->in_ir)) { + if (G_UNLIKELY(!fc->in_ir || notit->dry_run)) { goto end; } field = borrow_next_field(notit); - BT_ASSERT(field); - BT_ASSERT(bt_field_borrow_class_const(field) == fc->ir_fc); - BT_ASSERT(bt_field_get_class_type(field) == - BT_FIELD_CLASS_TYPE_UNSIGNED_INTEGER || - bt_field_get_class_type(field) == - BT_FIELD_CLASS_TYPE_UNSIGNED_ENUMERATION); - bt_field_unsigned_integer_set_value(field, value); + BT_ASSERT_DBG(field); + BT_ASSERT_DBG(bt_field_borrow_class_const(field) == fc->ir_fc); + BT_ASSERT_DBG(bt_field_class_type_is(bt_field_get_class_type(field), + BT_FIELD_CLASS_TYPE_UNSIGNED_INTEGER)); + bt_field_integer_unsigned_set_value(field, value); stack_top(notit->stack)->index++; end: @@ -1982,15 +2008,15 @@ enum bt_bfcr_status bfcr_unsigned_int_char_cb(uint64_t value, struct ctf_field_class_int *int_fc = (void *) fc; char str[2] = {'\0', '\0'}; - BT_LOGV("Unsigned integer character function called from BFCR: " + BT_COMP_LOGT("Unsigned integer character function called from BFCR: " "notit-addr=%p, bfcr-addr=%p, fc-addr=%p, " "fc-type=%d, fc-in-ir=%d, value=%" PRIu64, notit, notit->bfcr, fc, fc->type, fc->in_ir, value); - BT_ASSERT(int_fc->meaning == CTF_FIELD_CLASS_MEANING_NONE); - BT_ASSERT(!int_fc->mapped_clock_class); - BT_ASSERT(int_fc->storing_index < 0); + BT_ASSERT_DBG(int_fc->meaning == CTF_FIELD_CLASS_MEANING_NONE); + BT_ASSERT_DBG(!int_fc->mapped_clock_class); + BT_ASSERT_DBG(int_fc->storing_index < 0); - if (G_UNLIKELY(!fc->in_ir)) { + if (G_UNLIKELY(!fc->in_ir || notit->dry_run)) { goto end; } @@ -2004,14 +2030,14 @@ enum bt_bfcr_status bfcr_unsigned_int_char_cb(uint64_t value, } string_field = stack_top(notit->stack)->base; - BT_ASSERT(bt_field_get_class_type(string_field) == - BT_FIELD_CLASS_TYPE_STRING); + BT_ASSERT_DBG(bt_field_get_class_type(string_field) == + BT_FIELD_CLASS_TYPE_STRING); /* Append character */ str[0] = (char) value; ret = bt_field_string_append_with_length(string_field, str, 1); if (ret) { - BT_LOGE("Cannot append character to string field's value: " + BT_COMP_LOGE("Cannot append character to string field's value: " "notit-addr=%p, field-addr=%p, ret=%d", notit, string_field, ret); status = BT_BFCR_STATUS_ERROR; @@ -2031,29 +2057,27 @@ enum bt_bfcr_status bfcr_signed_int_cb(int64_t value, struct bt_msg_iter *notit = data; struct ctf_field_class_int *int_fc = (void *) fc; - BT_LOGV("Signed integer function called from BFCR: " + BT_COMP_LOGT("Signed integer function called from BFCR: " "notit-addr=%p, bfcr-addr=%p, fc-addr=%p, " "fc-type=%d, fc-in-ir=%d, value=%" PRId64, notit, notit->bfcr, fc, fc->type, fc->in_ir, value); - BT_ASSERT(int_fc->meaning == CTF_FIELD_CLASS_MEANING_NONE); + BT_ASSERT_DBG(int_fc->meaning == CTF_FIELD_CLASS_MEANING_NONE); if (G_UNLIKELY(int_fc->storing_index >= 0)) { g_array_index(notit->stored_values, uint64_t, (uint64_t) int_fc->storing_index) = (uint64_t) value; } - if (G_UNLIKELY(!fc->in_ir)) { + if (G_UNLIKELY(!fc->in_ir || notit->dry_run)) { goto end; } field = borrow_next_field(notit); - BT_ASSERT(field); - BT_ASSERT(bt_field_borrow_class_const(field) == fc->ir_fc); - BT_ASSERT(bt_field_get_class_type(field) == - BT_FIELD_CLASS_TYPE_SIGNED_INTEGER || - bt_field_get_class_type(field) == - BT_FIELD_CLASS_TYPE_SIGNED_ENUMERATION); - bt_field_signed_integer_set_value(field, value); + BT_ASSERT_DBG(field); + BT_ASSERT_DBG(bt_field_borrow_class_const(field) == fc->ir_fc); + BT_ASSERT_DBG(bt_field_class_type_is(bt_field_get_class_type(field), + BT_FIELD_CLASS_TYPE_SIGNED_INTEGER)); + bt_field_integer_signed_set_value(field, value); stack_top(notit->stack)->index++; end: @@ -2067,22 +2091,28 @@ enum bt_bfcr_status bfcr_floating_point_cb(double value, enum bt_bfcr_status status = BT_BFCR_STATUS_OK; bt_field *field = NULL; struct bt_msg_iter *notit = data; + bt_field_class_type type; - BT_LOGV("Floating point number function called from BFCR: " + BT_COMP_LOGT("Floating point number function called from BFCR: " "notit-addr=%p, bfcr-addr=%p, fc-addr=%p, " "fc-type=%d, fc-in-ir=%d, value=%f", notit, notit->bfcr, fc, fc->type, fc->in_ir, value); - if (G_UNLIKELY(!fc->in_ir)) { + if (G_UNLIKELY(!fc->in_ir || notit->dry_run)) { goto end; } field = borrow_next_field(notit); - BT_ASSERT(field); - BT_ASSERT(bt_field_borrow_class_const(field) == fc->ir_fc); - BT_ASSERT(bt_field_get_class_type(field) == - BT_FIELD_CLASS_TYPE_REAL); - bt_field_real_set_value(field, value); + type = bt_field_get_class_type(field); + BT_ASSERT_DBG(field); + BT_ASSERT_DBG(bt_field_borrow_class_const(field) == fc->ir_fc); + BT_ASSERT_DBG(bt_field_class_type_is(type, BT_FIELD_CLASS_TYPE_REAL)); + + if (type == BT_FIELD_CLASS_TYPE_SINGLE_PRECISION_REAL) { + bt_field_real_single_precision_set_value(field, (float) value); + } else { + bt_field_real_double_precision_set_value(field, value); + } stack_top(notit->stack)->index++; end: @@ -2095,24 +2125,22 @@ enum bt_bfcr_status bfcr_string_begin_cb( { bt_field *field = NULL; struct bt_msg_iter *notit = data; - int ret; - BT_LOGV("String (beginning) function called from BFCR: " + BT_COMP_LOGT("String (beginning) function called from BFCR: " "notit-addr=%p, bfcr-addr=%p, fc-addr=%p, " "fc-type=%d, fc-in-ir=%d", notit, notit->bfcr, fc, fc->type, fc->in_ir); - if (G_UNLIKELY(!fc->in_ir)) { + if (G_UNLIKELY(!fc->in_ir || notit->dry_run)) { goto end; } field = borrow_next_field(notit); - BT_ASSERT(field); - BT_ASSERT(bt_field_borrow_class_const(field) == fc->ir_fc); - BT_ASSERT(bt_field_get_class_type(field) == + BT_ASSERT_DBG(field); + BT_ASSERT_DBG(bt_field_borrow_class_const(field) == fc->ir_fc); + BT_ASSERT_DBG(bt_field_get_class_type(field) == BT_FIELD_CLASS_TYPE_STRING); - ret = bt_field_string_clear(field); - BT_ASSERT(ret == 0); + bt_field_string_clear(field); /* * Push on stack. Not a compound class per se, but we know that @@ -2134,23 +2162,23 @@ enum bt_bfcr_status bfcr_string_cb(const char *value, struct bt_msg_iter *notit = data; int ret; - BT_LOGV("String (substring) function called from BFCR: " + BT_COMP_LOGT("String (substring) function called from BFCR: " "notit-addr=%p, bfcr-addr=%p, fc-addr=%p, " "fc-type=%d, fc-in-ir=%d, string-length=%zu", notit, notit->bfcr, fc, fc->type, fc->in_ir, len); - if (G_UNLIKELY(!fc->in_ir)) { + if (G_UNLIKELY(!fc->in_ir || notit->dry_run)) { goto end; } field = stack_top(notit->stack)->base; - BT_ASSERT(field); + BT_ASSERT_DBG(field); /* Append current substring */ ret = bt_field_string_append_with_length(field, value, len); if (ret) { - BT_LOGE("Cannot append substring to string field's value: " + BT_COMP_LOGE("Cannot append substring to string field's value: " "notit-addr=%p, field-addr=%p, string-length=%zu, " "ret=%d", notit, field, len, ret); status = BT_BFCR_STATUS_ERROR; @@ -2167,12 +2195,12 @@ enum bt_bfcr_status bfcr_string_end_cb( { struct bt_msg_iter *notit = data; - BT_LOGV("String (end) function called from BFCR: " + BT_COMP_LOGT("String (end) function called from BFCR: " "notit-addr=%p, bfcr-addr=%p, fc-addr=%p, " "fc-type=%d, fc-in-ir=%d", notit, notit->bfcr, fc, fc->type, fc->in_ir); - if (G_UNLIKELY(!fc->in_ir)) { + if (G_UNLIKELY(!fc->in_ir || notit->dry_run)) { goto end; } @@ -2186,18 +2214,19 @@ end: return BT_BFCR_STATUS_OK; } +static enum bt_bfcr_status bfcr_compound_begin_cb( struct ctf_field_class *fc, void *data) { struct bt_msg_iter *notit = data; bt_field *field; - BT_LOGV("Compound (beginning) function called from BFCR: " + BT_COMP_LOGT("Compound (beginning) function called from BFCR: " "notit-addr=%p, bfcr-addr=%p, fc-addr=%p, " "fc-type=%d, fc-in-ir=%d", notit, notit->bfcr, fc, fc->type, fc->in_ir); - if (!fc->in_ir) { + if (G_UNLIKELY(!fc->in_ir || notit->dry_run)) { goto end; } @@ -2207,12 +2236,12 @@ enum bt_bfcr_status bfcr_compound_begin_cb( field = notit->cur_dscope_field; } else { field = borrow_next_field(notit); - BT_ASSERT(field); + BT_ASSERT_DBG(field); } /* Push field */ - BT_ASSERT(field); - BT_ASSERT(bt_field_borrow_class_const(field) == fc->ir_fc); + BT_ASSERT_DBG(field); + BT_ASSERT_DBG(bt_field_borrow_class_const(field) == fc->ir_fc); stack_push(notit->stack, field); /* @@ -2224,13 +2253,10 @@ enum bt_bfcr_status bfcr_compound_begin_cb( struct ctf_field_class_array_base *array_fc = (void *) fc; if (array_fc->is_text) { - int ret; - - BT_ASSERT(bt_field_get_class_type(field) == + BT_ASSERT_DBG(bt_field_get_class_type(field) == BT_FIELD_CLASS_TYPE_STRING); notit->done_filling_string = false; - ret = bt_field_string_clear(field); - BT_ASSERT(ret == 0); + bt_field_string_clear(field); bt_bfcr_set_unsigned_int_cb(notit->bfcr, bfcr_unsigned_int_char_cb); } @@ -2240,22 +2266,23 @@ end: return BT_BFCR_STATUS_OK; } +static enum bt_bfcr_status bfcr_compound_end_cb( struct ctf_field_class *fc, void *data) { struct bt_msg_iter *notit = data; - BT_LOGV("Compound (end) function called from BFCR: " + BT_COMP_LOGT("Compound (end) function called from BFCR: " "notit-addr=%p, bfcr-addr=%p, fc-addr=%p, " "fc-type=%d, fc-in-ir=%d", notit, notit->bfcr, fc, fc->type, fc->in_ir); - if (!fc->in_ir) { + if (G_UNLIKELY(!fc->in_ir || notit->dry_run)) { goto end; } - BT_ASSERT(!stack_empty(notit->stack)); - BT_ASSERT(bt_field_borrow_class_const(stack_top(notit->stack)->base) == + BT_ASSERT_DBG(!stack_empty(notit->stack)); + BT_ASSERT_DBG(bt_field_borrow_class_const(stack_top(notit->stack)->base) == fc->ir_fc); /* @@ -2267,7 +2294,7 @@ enum bt_bfcr_status bfcr_compound_end_cb( struct ctf_field_class_array_base *array_fc = (void *) fc; if (array_fc->is_text) { - BT_ASSERT(bt_field_get_class_type( + BT_ASSERT_DBG(bt_field_get_class_type( stack_top(notit->stack)->base) == BT_FIELD_CLASS_TYPE_STRING); bt_bfcr_set_unsigned_int_cb(notit->bfcr, @@ -2298,8 +2325,13 @@ int64_t bfcr_get_sequence_length_cb(struct ctf_field_class *fc, void *data) length = (uint64_t) g_array_index(notit->stored_values, uint64_t, seq_fc->stored_length_index); + + if (G_UNLIKELY(notit->dry_run)){ + goto end; + } + seq_field = stack_top(notit->stack)->base; - BT_ASSERT(seq_field); + BT_ASSERT_DBG(seq_field); /* * bfcr_get_sequence_length_cb() also gets called back for a @@ -2308,17 +2340,19 @@ int64_t bfcr_get_sequence_length_cb(struct ctf_field_class *fc, void *data) * is a sequence field. */ if (!seq_fc->base.is_text) { - BT_ASSERT(bt_field_get_class_type(seq_field) == - BT_FIELD_CLASS_TYPE_DYNAMIC_ARRAY); - ret = bt_field_dynamic_array_set_length(seq_field, + BT_ASSERT_DBG(bt_field_class_type_is( + bt_field_get_class_type(seq_field), + BT_FIELD_CLASS_TYPE_DYNAMIC_ARRAY)); + ret = bt_field_array_dynamic_set_length(seq_field, (uint64_t) length); if (ret) { - BT_LOGE("Cannot set dynamic array field's length field: " + BT_COMP_LOGE("Cannot set dynamic array field's length field: " "notit-addr=%p, field-addr=%p, " "length=%" PRIu64, notit, seq_field, length); } } +end: return length; } @@ -2372,7 +2406,7 @@ struct ctf_field_class *bfcr_borrow_variant_selected_field_class_cb( } if (option_index < 0) { - BT_LOGW("Cannot find variant field class's option: " + BT_COMP_LOGW("Cannot find variant field class's option: " "notit-addr=%p, var-fc-addr=%p, u-tag=%" PRIu64 ", " "i-tag=%" PRId64, notit, var_fc, tag.u, tag.i); goto end; @@ -2381,13 +2415,13 @@ struct ctf_field_class *bfcr_borrow_variant_selected_field_class_cb( selected_option = ctf_field_class_variant_borrow_option_by_index( var_fc, (uint64_t) option_index); - if (selected_option->fc->in_ir) { + if (selected_option->fc->in_ir && !notit->dry_run) { bt_field *var_field = stack_top(notit->stack)->base; - ret = bt_field_variant_select_option_field( + ret = bt_field_variant_select_option_field_by_index( var_field, option_index); if (ret) { - BT_LOGW("Cannot select variant field's option field: " + BT_COMP_LOGW("Cannot select variant field's option field: " "notit-addr=%p, var-field-addr=%p, " "opt-index=%" PRId64, notit, var_field, option_index); @@ -2402,117 +2436,64 @@ end: } static -void create_msg_stream_beginning(struct bt_msg_iter *notit, - bt_message **message) -{ - bt_message *ret = NULL; - - BT_ASSERT(notit->stream); - BT_ASSERT(notit->msg_iter); - ret = bt_message_stream_beginning_create(notit->msg_iter, - notit->stream); - if (!ret) { - BT_LOGE("Cannot create stream beginning message: " - "notit-addr=%p, stream-addr=%p", - notit, notit->stream); - return; - } - - *message = ret; -} - -static -void create_msg_stream_activity_beginning(struct bt_msg_iter *notit, - bt_message **message) -{ - bt_message *ret = NULL; - - BT_ASSERT(notit->stream); - BT_ASSERT(notit->msg_iter); - ret = bt_message_stream_activity_beginning_create(notit->msg_iter, - notit->stream); - if (!ret) { - BT_LOGE("Cannot create stream activity beginning message: " - "notit-addr=%p, stream-addr=%p", - notit, notit->stream); - return; - } - - *message = ret; -} - -static -void create_msg_stream_activity_end(struct bt_msg_iter *notit, - bt_message **message) +bt_message *create_msg_stream_beginning(struct bt_msg_iter *notit) { - bt_message *ret = NULL; - - if (!notit->stream) { - BT_LOGE("Cannot create stream for stream message: " - "notit-addr=%p", notit); - return; - } + bt_message *msg; BT_ASSERT(notit->stream); BT_ASSERT(notit->msg_iter); - ret = bt_message_stream_activity_end_create(notit->msg_iter, + msg = bt_message_stream_beginning_create(notit->msg_iter, notit->stream); - if (!ret) { - BT_LOGE("Cannot create stream activity end message: " + if (!msg) { + BT_COMP_LOGE("Cannot create stream beginning message: " "notit-addr=%p, stream-addr=%p", notit, notit->stream); - return; } - *message = ret; + return msg; } static -void create_msg_stream_end(struct bt_msg_iter *notit, bt_message **message) +bt_message *create_msg_stream_end(struct bt_msg_iter *notit) { - bt_message *ret; + bt_message *msg; if (!notit->stream) { - BT_LOGE("Cannot create stream for stream message: " + BT_COMP_LOGE("Cannot create stream for stream message: " "notit-addr=%p", notit); - return; + msg = NULL; + goto end; } BT_ASSERT(notit->msg_iter); - ret = bt_message_stream_end_create(notit->msg_iter, + msg = bt_message_stream_end_create(notit->msg_iter, notit->stream); - if (!ret) { - BT_LOGE("Cannot create stream end message: " + if (!msg) { + BT_COMP_LOGE("Cannot create stream end message: " "notit-addr=%p, stream-addr=%p", notit, notit->stream); - return; } - *message = ret; +end: + return msg; } static -void create_msg_packet_beginning(struct bt_msg_iter *notit, - bt_message **message) +bt_message *create_msg_packet_beginning(struct bt_msg_iter *notit, + bool use_default_cs) { int ret; - enum bt_msg_iter_status status; - bt_message *msg = NULL; - const bt_stream_class *sc; - - status = set_current_packet(notit); - if (status != BT_MSG_ITER_STATUS_OK) { - goto end; - } + bt_message *msg; + const bt_stream_class *sc = notit->meta.sc->ir_sc; BT_ASSERT(notit->packet); - sc = notit->meta.sc->ir_sc; BT_ASSERT(sc); if (notit->packet_context_field) { ret = bt_packet_move_context_field( notit->packet, notit->packet_context_field); if (ret) { + msg = NULL; goto end; } @@ -2532,38 +2513,115 @@ void create_msg_packet_beginning(struct bt_msg_iter *notit, if (notit->meta.sc->packets_have_ts_begin) { BT_ASSERT(notit->snapshots.beginning_clock != UINT64_C(-1)); + uint64_t raw_cs_value; + + /* + * Either use the decoded packet `timestamp_begin` field or the + * current stream's default clock_snapshot. + */ + if (use_default_cs) { + raw_cs_value = notit->default_clock_snapshot; + } else { + raw_cs_value = notit->snapshots.beginning_clock; + } + msg = bt_message_packet_beginning_create_with_default_clock_snapshot( notit->msg_iter, notit->packet, - notit->snapshots.beginning_clock); + raw_cs_value); } else { msg = bt_message_packet_beginning_create(notit->msg_iter, notit->packet); } if (!msg) { - BT_LOGE("Cannot create packet beginning message: " + BT_COMP_LOGE("Cannot create packet beginning message: " "notit-addr=%p, packet-addr=%p", notit, notit->packet); goto end; } - *message = msg; - end: - return; + return msg; +} + +static +bt_message *emit_delayed_packet_beg_msg(struct bt_msg_iter *notit) +{ + bool packet_beg_ts_need_fix_up; + + notit->emit_delayed_packet_beginning_msg = false; + + /* + * Only fix the packet's timestamp_begin if it's larger than the first + * event of the packet. If there was no event in the packet, the + * `default_clock_snapshot` field will be either equal or greater than + * `snapshots.beginning_clock` so there is not fix needed. + */ + packet_beg_ts_need_fix_up = + notit->default_clock_snapshot < notit->snapshots.beginning_clock; + + /* create_msg_packet_beginning() logs errors */ + return create_msg_packet_beginning(notit, packet_beg_ts_need_fix_up); } + static -void create_msg_packet_end(struct bt_msg_iter *notit, bt_message **message) +bt_message *create_msg_packet_end(struct bt_msg_iter *notit) { bt_message *msg; + bool update_default_cs = true; if (!notit->packet) { - return; + msg = NULL; + goto end; + } + + /* + * Check if we need to emit the delayed packet + * beginning message instead of the packet end message. + */ + if (G_UNLIKELY(notit->emit_delayed_packet_beginning_msg)) { + msg = emit_delayed_packet_beg_msg(notit); + /* Don't forget to emit the packet end message. */ + notit->state = STATE_EMIT_QUEUED_MSG_PACKET_END; + goto end; + } + + /* Check if may be affected by lttng-crash timestamp_end quirk. */ + if (G_UNLIKELY(notit->meta.tc->quirks.lttng_crash)) { + /* + * Check if the `timestamp_begin` field is non-zero but + * `timestamp_end` is zero. It means the trace is affected by + * the lttng-crash packet `timestamp_end` quirk and must be + * fixed up by omitting to update the default clock snapshot to + * the `timestamp_end` as is typically done. + */ + if (notit->snapshots.beginning_clock != 0 && + notit->snapshots.end_clock == 0) { + update_default_cs = false; + } } - /* Update default clock from packet's end time */ - if (notit->snapshots.end_clock != UINT64_C(-1)) { + /* + * Check if may be affected by lttng event-after-packet `timestamp_end` + * quirk. + */ + if (notit->meta.tc->quirks.lttng_event_after_packet) { + /* + * Check if `timestamp_end` is smaller then the current + * default_clock_snapshot (which is set to the last event + * decoded). It means the trace is affected by the lttng + * `event-after-packet` packet `timestamp_end` quirk and must + * be fixed up by omitting to update the default clock snapshot + * to the `timestamp_end` as is typically done. + */ + if (notit->snapshots.end_clock < notit->default_clock_snapshot) { + update_default_cs = false; + } + } + + /* Update default clock from packet's end time. */ + if (notit->snapshots.end_clock != UINT64_C(-1) && update_default_cs) { notit->default_clock_snapshot = notit->snapshots.end_clock; } @@ -2573,27 +2631,28 @@ void create_msg_packet_end(struct bt_msg_iter *notit, bt_message **message) BT_ASSERT(notit->snapshots.end_clock != UINT64_C(-1)); msg = bt_message_packet_end_create_with_default_clock_snapshot( notit->msg_iter, notit->packet, - notit->snapshots.end_clock); + notit->default_clock_snapshot); } else { msg = bt_message_packet_end_create(notit->msg_iter, notit->packet); } if (!msg) { - BT_LOGE("Cannot create packet end message: " + BT_COMP_LOGE("Cannot create packet end message: " "notit-addr=%p, packet-addr=%p", notit, notit->packet); - return; + goto end; } BT_PACKET_PUT_REF_AND_RESET(notit->packet); - *message = msg; + +end: + return msg; } static -void create_msg_discarded_events(struct bt_msg_iter *notit, - bt_message **message) +bt_message *create_msg_discarded_events(struct bt_msg_iter *notit) { bt_message *msg; uint64_t beginning_raw_value = UINT64_C(-1); @@ -2628,10 +2687,10 @@ void create_msg_discarded_events(struct bt_msg_iter *notit, } if (!msg) { - BT_LOGE("Cannot create discarded events message: " + BT_COMP_LOGE("Cannot create discarded events message: " "notit-addr=%p, stream-addr=%p", notit, notit->stream); - return; + goto end; } if (notit->prev_packet_snapshots.discarded_events != UINT64_C(-1)) { @@ -2640,12 +2699,12 @@ void create_msg_discarded_events(struct bt_msg_iter *notit, notit->prev_packet_snapshots.discarded_events); } - *message = msg; +end: + return msg; } static -void create_msg_discarded_packets(struct bt_msg_iter *notit, - bt_message **message) +bt_message *create_msg_discarded_packets(struct bt_msg_iter *notit) { bt_message *msg; @@ -2668,22 +2727,25 @@ void create_msg_discarded_packets(struct bt_msg_iter *notit, } if (!msg) { - BT_LOGE("Cannot create discarded packets message: " + BT_COMP_LOGE("Cannot create discarded packets message: " "notit-addr=%p, stream-addr=%p", notit, notit->stream); - return; + goto end; } bt_message_discarded_packets_set_count(msg, notit->snapshots.packets - notit->prev_packet_snapshots.packets - 1); - *message = msg; + +end: + return msg; } BT_HIDDEN struct bt_msg_iter *bt_msg_iter_create(struct ctf_trace_class *tc, size_t max_request_sz, - struct bt_msg_iter_medium_ops medops, void *data) + struct bt_msg_iter_medium_ops medops, void *data, + bt_logging_level log_level, bt_self_component *self_comp) { struct bt_msg_iter *notit = NULL; struct bt_bfcr_cbs cbs = { @@ -2706,14 +2768,19 @@ struct bt_msg_iter *bt_msg_iter_create(struct ctf_trace_class *tc, BT_ASSERT(tc); BT_ASSERT(medops.request_bytes); BT_ASSERT(medops.borrow_stream); - BT_LOGD("Creating CTF plugin message iterator: " + BT_COMP_LOG_CUR_LVL(BT_LOG_DEBUG, log_level, self_comp, + "Creating CTF plugin message iterator: " "trace-addr=%p, max-request-size=%zu, " - "data=%p", tc, max_request_sz, data); + "data=%p, log-level=%s", tc, max_request_sz, data, + bt_common_logging_level_string(log_level)); notit = g_new0(struct bt_msg_iter, 1); if (!notit) { - BT_LOGE_STR("Failed to allocate one CTF plugin message iterator."); + BT_COMP_LOG_CUR_LVL(BT_LOG_ERROR, log_level, self_comp, + "Failed to allocate one CTF plugin message iterator."); goto end; } + notit->self_comp = self_comp; + notit->log_level = log_level; notit->meta.tc = tc; notit->medium.medops = medops; notit->medium.max_request_sz = max_request_sz; @@ -2723,21 +2790,22 @@ struct bt_msg_iter *bt_msg_iter_create(struct ctf_trace_class *tc, g_array_set_size(notit->stored_values, tc->stored_value_count); if (!notit->stack) { - BT_LOGE_STR("Failed to create field stack."); + BT_COMP_LOGE_STR("Failed to create field stack."); goto error; } - notit->bfcr = bt_bfcr_create(cbs, notit, BT_LOG_OUTPUT_LEVEL); + notit->bfcr = bt_bfcr_create(cbs, notit, log_level, NULL); if (!notit->bfcr) { - BT_LOGE_STR("Failed to create binary class reader (BFCR)."); + BT_COMP_LOGE_STR("Failed to create binary class reader (BFCR)."); goto error; } bt_msg_iter_reset(notit); - BT_LOGD("Created CTF plugin message iterator: " + BT_COMP_LOGD("Created CTF plugin message iterator: " "trace-addr=%p, max-request-size=%zu, " - "data=%p, notit-addr=%p", - tc, max_request_sz, data, notit); + "data=%p, notit-addr=%p, log-level=%s", + tc, max_request_sz, data, notit, + bt_common_logging_level_string(log_level)); notit->cur_packet_offset = 0; end: @@ -2755,15 +2823,15 @@ void bt_msg_iter_destroy(struct bt_msg_iter *notit) BT_STREAM_PUT_REF_AND_RESET(notit->stream); release_all_dscopes(notit); - BT_LOGD("Destroying CTF plugin message iterator: addr=%p", notit); + BT_COMP_LOGD("Destroying CTF plugin message iterator: addr=%p", notit); if (notit->stack) { - BT_LOGD_STR("Destroying field stack."); + BT_COMP_LOGD_STR("Destroying field stack."); stack_destroy(notit->stack); } if (notit->bfcr) { - BT_LOGD("Destroying BFCR: bfcr-addr=%p", notit->bfcr); + BT_COMP_LOGD("Destroying BFCR: bfcr-addr=%p", notit->bfcr); bt_bfcr_destroy(notit->bfcr); } @@ -2780,32 +2848,51 @@ enum bt_msg_iter_status bt_msg_iter_get_next_message( { enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; - BT_ASSERT(notit); - BT_ASSERT(message); + BT_ASSERT_DBG(notit); + BT_ASSERT_DBG(message); notit->msg_iter = msg_iter; notit->set_stream = true; - BT_LOGD("Getting next message: notit-addr=%p", notit); + BT_COMP_LOGD("Getting next message: notit-addr=%p", notit); while (true) { status = handle_state(notit); if (G_UNLIKELY(status == BT_MSG_ITER_STATUS_AGAIN)) { - BT_LOGD_STR("Medium returned BT_MSG_ITER_STATUS_AGAIN."); + BT_COMP_LOGD_STR("Medium returned BT_MSG_ITER_STATUS_AGAIN."); goto end; } else if (G_UNLIKELY(status != BT_MSG_ITER_STATUS_OK)) { - BT_LOGW("Cannot handle state: notit-addr=%p, state=%s", + BT_COMP_LOGW("Cannot handle state: notit-addr=%p, state=%s", notit, state_string(notit->state)); goto end; } switch (notit->state) { case STATE_EMIT_MSG_EVENT: - BT_ASSERT(notit->event_msg); - *message = notit->event_msg; - notit->event_msg = NULL; + BT_ASSERT_DBG(notit->event_msg); + + /* + * Check if we need to emit the delayed packet + * beginning message instead of the event message. + */ + if (G_UNLIKELY(notit->emit_delayed_packet_beginning_msg)) { + *message = emit_delayed_packet_beg_msg(notit); + if (!*message) { + status = BT_MSG_ITER_STATUS_ERROR; + } + + /* + * Don't forget to emit the event message of + * the event record that was just decoded. + */ + notit->state = STATE_EMIT_QUEUED_MSG_EVENT; + + } else { + *message = notit->event_msg; + notit->event_msg = NULL; + } goto end; case STATE_EMIT_MSG_DISCARDED_EVENTS: /* create_msg_discared_events() logs errors */ - create_msg_discarded_events(notit, message); + *message = create_msg_discarded_events(notit); if (!*message) { status = BT_MSG_ITER_STATUS_ERROR; @@ -2814,7 +2901,7 @@ enum bt_msg_iter_status bt_msg_iter_get_next_message( goto end; case STATE_EMIT_MSG_DISCARDED_PACKETS: /* create_msg_discared_packets() logs errors */ - create_msg_discarded_packets(notit, message); + *message = create_msg_discarded_packets(notit); if (!*message) { status = BT_MSG_ITER_STATUS_ERROR; @@ -2822,36 +2909,33 @@ enum bt_msg_iter_status bt_msg_iter_get_next_message( goto end; case STATE_EMIT_MSG_PACKET_BEGINNING: - /* create_msg_packet_beginning() logs errors */ - create_msg_packet_beginning(notit, message); + status = set_current_packet(notit); + if (status != BT_MSG_ITER_STATUS_OK) { + goto end; + } - if (!*message) { - status = BT_MSG_ITER_STATUS_ERROR; + if (G_UNLIKELY(notit->meta.tc->quirks.barectf_event_before_packet)) { + notit->emit_delayed_packet_beginning_msg = true; + /* + * There is no message to return yet as this + * packet beginning message is delayed until we + * decode the first event message of the + * packet. + */ + break; + } else { + /* create_msg_packet_beginning() logs errors */ + *message = create_msg_packet_beginning(notit, false); + if (!*message) { + status = BT_MSG_ITER_STATUS_ERROR; + } } goto end; case STATE_EMIT_MSG_PACKET_END_SINGLE: case STATE_EMIT_MSG_PACKET_END_MULTI: /* create_msg_packet_end() logs errors */ - create_msg_packet_end(notit, message); - - if (!*message) { - status = BT_MSG_ITER_STATUS_ERROR; - } - - goto end; - case STATE_EMIT_MSG_STREAM_ACTIVITY_BEGINNING: - /* create_msg_stream_activity_beginning() logs errors */ - create_msg_stream_activity_beginning(notit, message); - - if (!*message) { - status = BT_MSG_ITER_STATUS_ERROR; - } - - goto end; - case STATE_EMIT_MSG_STREAM_ACTIVITY_END: - /* create_msg_stream_activity_end() logs errors */ - create_msg_stream_activity_end(notit, message); + *message = create_msg_packet_end(notit); if (!*message) { status = BT_MSG_ITER_STATUS_ERROR; @@ -2860,7 +2944,7 @@ enum bt_msg_iter_status bt_msg_iter_get_next_message( goto end; case STATE_EMIT_MSG_STREAM_BEGINNING: /* create_msg_stream_beginning() logs errors */ - create_msg_stream_beginning(notit, message); + *message = create_msg_stream_beginning(notit); if (!*message) { status = BT_MSG_ITER_STATUS_ERROR; @@ -2869,7 +2953,7 @@ enum bt_msg_iter_status bt_msg_iter_get_next_message( goto end; case STATE_EMIT_MSG_STREAM_END: /* create_msg_stream_end() logs errors */ - create_msg_stream_end(notit, message); + *message = create_msg_stream_end(notit); if (!*message) { status = BT_MSG_ITER_STATUS_ERROR; @@ -2890,39 +2974,37 @@ end: } static -enum bt_msg_iter_status read_packet_header_context_fields( - struct bt_msg_iter *notit) +enum bt_msg_iter_status decode_until_state( struct bt_msg_iter *notit, + enum state target_state_1, enum state target_state_2) { - int ret; enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; - BT_ASSERT(notit); + BT_ASSERT_DBG(notit); notit->set_stream = false; - if (notit->state == STATE_EMIT_MSG_PACKET_BEGINNING) { - /* We're already there */ - goto end; - } + do { + /* + * Check if we reached the state at which we want to stop + * decoding. + */ + if (notit->state == target_state_1 || + notit->state == target_state_2) { + goto end; + } - while (true) { status = handle_state(notit); if (G_UNLIKELY(status == BT_MSG_ITER_STATUS_AGAIN)) { - BT_LOGD_STR("Medium returned BT_MSG_ITER_STATUS_AGAIN."); + BT_COMP_LOGD_STR("Medium returned BT_MSG_ITER_STATUS_AGAIN."); goto end; } else if (G_UNLIKELY(status != BT_MSG_ITER_STATUS_OK)) { - BT_LOGW("Cannot handle state: notit-addr=%p, state=%s", + BT_COMP_LOGW("Cannot handle state: notit-addr=%p, state=%s", notit, state_string(notit->state)); goto end; } switch (notit->state) { - case STATE_EMIT_MSG_PACKET_BEGINNING: - /* - * Packet header and context fields are - * potentially decoded (or they don't exist). - */ - goto end; case STATE_INIT: + case STATE_SWITCH_PACKET: case STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN: case STATE_DSCOPE_TRACE_PACKET_HEADER_CONTINUE: case STATE_AFTER_TRACE_PACKET_HEADER: @@ -2931,30 +3013,62 @@ enum bt_msg_iter_status read_packet_header_context_fields( case STATE_AFTER_STREAM_PACKET_CONTEXT: case STATE_CHECK_EMIT_MSG_STREAM_BEGINNING: case STATE_EMIT_MSG_STREAM_BEGINNING: - case STATE_EMIT_MSG_STREAM_ACTIVITY_BEGINNING: case STATE_CHECK_EMIT_MSG_DISCARDED_EVENTS: case STATE_EMIT_MSG_DISCARDED_EVENTS: case STATE_CHECK_EMIT_MSG_DISCARDED_PACKETS: case STATE_EMIT_MSG_DISCARDED_PACKETS: - /* Non-emitting state: continue */ + case STATE_EMIT_MSG_PACKET_BEGINNING: + case STATE_DSCOPE_EVENT_HEADER_BEGIN: + case STATE_DSCOPE_EVENT_HEADER_CONTINUE: + case STATE_AFTER_EVENT_HEADER: + case STATE_DSCOPE_EVENT_COMMON_CONTEXT_BEGIN: + case STATE_DSCOPE_EVENT_COMMON_CONTEXT_CONTINUE: + case STATE_DSCOPE_EVENT_SPEC_CONTEXT_BEGIN: + case STATE_DSCOPE_EVENT_SPEC_CONTEXT_CONTINUE: + case STATE_DSCOPE_EVENT_PAYLOAD_BEGIN: + case STATE_DSCOPE_EVENT_PAYLOAD_CONTINUE: + case STATE_EMIT_MSG_EVENT: + case STATE_EMIT_QUEUED_MSG_EVENT: + case STATE_SKIP_PACKET_PADDING: + case STATE_EMIT_MSG_PACKET_END_MULTI: + case STATE_EMIT_MSG_PACKET_END_SINGLE: + case STATE_EMIT_QUEUED_MSG_PACKET_END: + case STATE_CHECK_EMIT_MSG_STREAM_END: + case STATE_EMIT_MSG_STREAM_END: break; + case STATE_DONE: + /* fall-through */ default: - /* - * We should never get past the - * STATE_EMIT_MSG_PACKET_BEGINNING state. - */ - BT_LOGF("Unexpected state: notit-addr=%p, state=%s", + /* We should never get to the STATE_DONE state. */ + BT_COMP_LOGF("Unexpected state: notit-addr=%p, state=%s", notit, state_string(notit->state)); abort(); } - } + } while (true); end: + return status; +} + +static +enum bt_msg_iter_status read_packet_header_context_fields( + struct bt_msg_iter *notit) +{ + int ret; + enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; + + status = decode_until_state(notit, STATE_EMIT_MSG_PACKET_BEGINNING, -1); + if (status != BT_MSG_ITER_STATUS_OK) { + goto end; + } + ret = set_current_packet_content_sizes(notit); if (ret) { status = BT_MSG_ITER_STATUS_ERROR; + goto end; } +end: return status; } @@ -2970,19 +3084,19 @@ BT_HIDDEN enum bt_msg_iter_status bt_msg_iter_seek(struct bt_msg_iter *notit, off_t offset) { - enum bt_msg_iter_status ret = BT_MSG_ITER_STATUS_OK; + enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; enum bt_msg_iter_medium_status medium_status; BT_ASSERT(notit); if (offset < 0) { - BT_LOGE("Cannot seek to negative offset: offset=%jd", offset); - ret = BT_MSG_ITER_STATUS_INVAL; + BT_COMP_LOGE("Cannot seek to negative offset: offset=%jd", (intmax_t) offset); + status = BT_MSG_ITER_STATUS_INVAL; goto end; } if (!notit->medium.medops.seek) { - ret = BT_MSG_ITER_STATUS_UNSUPPORTED; - BT_LOGD("Aborting seek as the iterator's underlying media does not implement seek support."); + status = BT_MSG_ITER_STATUS_UNSUPPORTED; + BT_COMP_LOGD("Aborting seek as the iterator's underlying media does not implement seek support."); goto end; } @@ -2990,9 +3104,9 @@ enum bt_msg_iter_status bt_msg_iter_seek(struct bt_msg_iter *notit, BT_MSG_ITER_SEEK_WHENCE_SET, offset, notit->medium.data); if (medium_status != BT_MSG_ITER_MEDIUM_STATUS_OK) { if (medium_status == BT_MSG_ITER_MEDIUM_STATUS_EOF) { - ret = BT_MSG_ITER_STATUS_EOF; + status = BT_MSG_ITER_STATUS_EOF; } else { - ret = BT_MSG_ITER_STATUS_ERROR; + status = BT_MSG_ITER_STATUS_ERROR; goto end; } } @@ -3001,7 +3115,43 @@ enum bt_msg_iter_status bt_msg_iter_seek(struct bt_msg_iter *notit, notit->cur_packet_offset = offset; end: - return ret; + return status; +} + +static +enum bt_msg_iter_status clock_snapshot_at_msg_iter_state( + struct bt_msg_iter *notit, enum state target_state_1, + enum state target_state_2, uint64_t *clock_snapshot) +{ + enum bt_msg_iter_status status = BT_MSG_ITER_STATUS_OK; + + BT_ASSERT_DBG(notit); + BT_ASSERT_DBG(clock_snapshot); + status = decode_until_state(notit, target_state_1, target_state_2); + if (status != BT_MSG_ITER_STATUS_OK) { + goto end; + } + + *clock_snapshot = notit->default_clock_snapshot; +end: + return status; +} + +BT_HIDDEN +enum bt_msg_iter_status bt_msg_iter_curr_packet_first_event_clock_snapshot( + struct bt_msg_iter *notit, uint64_t *first_clock_snapshot) +{ + return clock_snapshot_at_msg_iter_state(notit, + STATE_AFTER_EVENT_HEADER, -1, first_clock_snapshot); +} + +BT_HIDDEN +enum bt_msg_iter_status bt_msg_iter_curr_packet_last_event_clock_snapshot( + struct bt_msg_iter *notit, uint64_t *last_clock_snapshot) +{ + return clock_snapshot_at_msg_iter_state(notit, + STATE_EMIT_MSG_PACKET_END_SINGLE, + STATE_EMIT_MSG_PACKET_END_MULTI, last_clock_snapshot); } BT_HIDDEN @@ -3011,8 +3161,8 @@ enum bt_msg_iter_status bt_msg_iter_get_packet_properties( { enum bt_msg_iter_status status; - BT_ASSERT(notit); - BT_ASSERT(props); + BT_ASSERT_DBG(notit); + BT_ASSERT_DBG(props); status = read_packet_header_context_fields(notit); if (status != BT_MSG_ITER_STATUS_OK) { goto end; @@ -3044,3 +3194,10 @@ void bt_msg_iter_set_emit_stream_end_message(struct bt_msg_iter *notit, { notit->emit_stream_end_msg = val; } + +BT_HIDDEN +void bt_msg_iter_set_dry_run(struct bt_msg_iter *notit, + bool val) +{ + notit->dry_run = val; +}