From 27bc6f1e6265a0da01d8f1cf2d669f1a1537c47e Mon Sep 17 00:00:00 2001 From: Philippe Proulx Date: Mon, 25 Mar 2019 16:05:13 -0400 Subject: [PATCH] Fix: do not sample clock when closing/opening a packet for an event not fitting This patch adds members to the generated barectf context to save the current (becomes last) event's timestamp and use it when closing and opening packets when the event does not fit the current packet instead of sampling the clock again. Without this patch, with this scenario: 1. Application calls a tracing function. 2. Tracing function samples the clock. 3. Event does not fit the current packet size: current packet is closed, sampling the clock, and new packet is opened, also sampling the clock. 4. Event is serialized to the new packet. The new packet's timestamp is greater than its first event's timestamp, because this event's timestamp is the result of sampling the clock before sampling it to close the current packet and open a new one. Babeltrace 1 accepts and reads the resulting stream, but Babeltrace 2's muxer is more strict and refuses a message which is in the past. Signed-off-by: Philippe Proulx Signed-off-by: Philippe Proulx --- barectf/gen.py | 109 +++++++++++++++++++++---------------------- barectf/templates.py | 21 +++++++-- 2 files changed, 70 insertions(+), 60 deletions(-) diff --git a/barectf/gen.py b/barectf/gen.py index 98f819f..819250c 100644 --- a/barectf/gen.py +++ b/barectf/gen.py @@ -195,6 +195,26 @@ class CCodeGenerator: } self._saved_serialization_actions = {} + def _get_stream_clock(self, stream): + field = None + + if stream.event_header_type is not None: + if 'timestamp' in stream.event_header_type.fields: + field = stream.event_header_type['timestamp'] + + if stream.packet_context_type is not None: + if field is None and 'timestamp_begin' in stream.packet_context_type.fields: + field = stream.packet_context_type['timestamp_begin'] + + if field is None and 'timestamp_end' in stream.packet_context_type.fields: + field = stream.packet_context_type['timestamp_end'] + + if field is None: + return + + if field.property_mappings: + return field.property_mappings[0].object + def _generate_ctx_parent(self): tmpl = templates._CTX_PARENT self._cg.add_lines(tmpl.format(prefix=self._cfg.prefix)) @@ -217,6 +237,12 @@ class CCodeGenerator: for field_name in stream.packet_context_type.fields: self._cg.add_lines(tmpl.format(fname=field_name)) + clock = self._get_stream_clock(stream) + + if clock is not None: + line = '{} cur_last_event_ts;'.format(clock.return_ctype) + self._cg.add_line(line) + self._cg.unindent() tmpl = templates._CTX_END self._cg.add_lines(tmpl) @@ -561,15 +587,7 @@ class CCodeGenerator: def _generate_func_serialize_event_proto(self, stream, event): tmpl = templates._FUNC_SERIALIZE_EVENT_PROTO_BEGIN - clock_ctype = 'const int' - - if stream.event_header_type is not None: - if 'timestamp' in stream.event_header_type.fields: - field = stream.event_header_type['timestamp'] - clock_ctype = self._get_first_clock_ctype(field) - self._cg.add_lines(tmpl.format(prefix=self._cfg.prefix, - clock_ctype=clock_ctype, sname=stream.name, evname=event.name)) self._generate_func_trace_proto_params(stream, event) tmpl = templates._FUNC_SERIALIZE_EVENT_PROTO_END @@ -683,7 +701,7 @@ class CCodeGenerator: exclude_list = ['timestamp', 'id'] params = self._get_call_event_param_list_from_struct(t, _PREFIX_SEH, exclude_list) - tmpl = '_serialize_stream_event_header_{sname}(ctx, ts, {evid}{params});' + tmpl = '_serialize_stream_event_header_{sname}(ctx, {evid}{params});' self._cg.add_cc_line('stream event header') self._cg.add_line(tmpl.format(sname=stream.name, evid=event.id, params=params)) @@ -724,15 +742,8 @@ class CCodeGenerator: def _generate_func_serialize_stream_event_header_proto(self, stream): tmpl = templates._FUNC_SERIALIZE_STREAM_EVENT_HEADER_PROTO_BEGIN clock_ctype = 'const int' - - if stream.event_header_type is not None: - if 'timestamp' in stream.event_header_type.fields: - field = stream.event_header_type['timestamp'] - clock_ctype = self._get_first_clock_ctype(field) - self._cg.add_lines(tmpl.format(prefix=self._cfg.prefix, - sname=stream.name, - clock_ctype=clock_ctype)) + sname=stream.name)) if stream.event_header_type is not None: exclude_list = [ @@ -761,9 +772,20 @@ class CCodeGenerator: ser_action_iter): self._generate_func_serialize_stream_event_header_proto(stream) tmpl = templates._FUNC_SERIALIZE_STREAM_EVENT_HEADER_BODY_BEGIN - lines = tmpl.format(prefix=self._cfg.prefix) + lines = tmpl.format(prefix=self._cfg.prefix, sname=stream.name) self._cg.add_lines(lines) self._cg.indent() + clock = self._get_stream_clock(stream) + + if clock is not None: + tmpl = 'struct {prefix}{sname}_ctx *s_ctx = FROM_VOID_PTR(struct {prefix}{sname}_ctx, vctx);' + line = tmpl.format(prefix=self._cfg.prefix, + sname=stream.name) + self._cg.add_line(line) + tmpl = 'const {} ts = s_ctx->cur_last_event_ts;' + line = tmpl.format(clock.return_ctype) + self._cg.add_line(line) + self._cg.add_empty_line() if stream.event_header_type is not None: @@ -806,19 +828,17 @@ class CCodeGenerator: def _generate_func_trace(self, stream, event): self._generate_func_trace_proto(stream, event) params = self._get_call_event_param_list(stream, event) - tmpl = templates._FUNC_TRACE_BODY - ts_line = '' - - if stream.event_header_type is not None: - if 'timestamp' in stream.event_header_type.fields: - field = stream.event_header_type.fields['timestamp'] - ts_line = self._get_ts_line(field) + clock = self._get_stream_clock(stream) - if not ts_line: - ts_line = '\tconst int ts = 0; /* unused */' + if clock is not None: + tmpl = 'ctx->cur_last_event_ts = ctx->parent.cbs.{}_clock_get_value(ctx->parent.data);' + save_ts_line = tmpl.format(clock.name) + else: + save_ts_line = '/* (no clock) */' + tmpl = templates._FUNC_TRACE_BODY self._cg.add_lines(tmpl.format(sname=stream.name, evname=event.name, - params=params, ts=ts_line)) + params=params, save_ts=save_ts_line)) def _generate_func_init(self): self._generate_func_init_proto() @@ -831,25 +851,14 @@ class CCodeGenerator: def _save_serialization_action(self, name, action): self._saved_serialization_actions[name] = action - def _get_first_clock_ctype(self, field, default='int'): - if not field.property_mappings: - return 'const {}'.format(default) - - clock = field.property_mappings[0].object - - return 'const {}'.format(clock.return_ctype) - - def _get_ts_line(self, field): - if field is None: - return '' + def _get_open_close_ts_line(self, stream): + clock = self._get_stream_clock(stream) - if not field.property_mappings: + if clock is None: return '' - tmpl = '\tconst {} ts = ctx->parent.cbs.{}_clock_get_value(ctx->parent.data);' - clock = field.property_mappings[0].object + tmpl = '\tconst {} ts = ctx->parent.use_cur_last_event_ts ? ctx->cur_last_event_ts : ctx->parent.cbs.{}_clock_get_value(ctx->parent.data);' line = tmpl.format(clock.return_ctype, clock.name) - return line def _generate_func_open(self, stream): @@ -860,13 +869,8 @@ class CCodeGenerator: self._generate_func_open_proto(stream) tmpl = templates._FUNC_OPEN_BODY_BEGIN - ts_line = '' spc_type = stream.packet_context_type - - if spc_type is not None and 'timestamp_begin' in spc_type.fields: - field = spc_type.fields['timestamp_begin'] - ts_line = self._get_ts_line(field) - + ts_line = self._get_open_close_ts_line(stream) lines = tmpl.format(ts=ts_line) self._cg.add_lines(lines) self._cg.indent() @@ -1006,13 +1010,8 @@ class CCodeGenerator: self._generate_func_close_proto(stream) tmpl = templates._FUNC_CLOSE_BODY_BEGIN - ts_line = '' spc_type = stream.packet_context_type - - if spc_type is not None and 'timestamp_end' in spc_type.fields: - field = spc_type.fields['timestamp_end'] - ts_line = self._get_ts_line(field) - + ts_line = self._get_open_close_ts_line(stream) lines = tmpl.format(ts=ts_line) self._cg.add_lines(lines) self._cg.indent() diff --git a/barectf/templates.py b/barectf/templates.py index 1f2278b..eec677b 100644 --- a/barectf/templates.py +++ b/barectf/templates.py @@ -74,6 +74,9 @@ struct {prefix}ctx {{ /* tracing is enabled */ volatile int is_tracing_enabled; + + /* use current/last event timestamp when opening/closing packets */ + int use_cur_last_event_ts; }};''' @@ -109,6 +112,7 @@ _FUNC_INIT_BODY = '''{{ ctx->packet_is_open = 0; ctx->in_tracing_section = 0; ctx->is_tracing_enabled = 1; + ctx->use_cur_last_event_ts = 0; }}''' @@ -150,6 +154,7 @@ _FUNC_OPEN_BODY_BEGIN = '''{{ _FUNC_OPEN_BODY_END = ''' + /* save content beginning's offset */ ctx->parent.off_content = ctx->parent.at; /* mark current packet as open */ @@ -217,9 +222,11 @@ _FUNC_TRACE_PROTO_END = ')' _FUNC_TRACE_BODY = '''{{ -{ts} uint32_t ev_size; + /* save timestamp */ + {save_ts} + if (!ctx->parent.is_tracing_enabled) {{ return; }} @@ -238,7 +245,7 @@ _FUNC_TRACE_BODY = '''{{ }} /* serialize event */ - _serialize_event_{sname}_{evname}(TO_VOID_PTR(ctx), ts{params}); + _serialize_event_{sname}_{evname}(TO_VOID_PTR(ctx){params}); /* commit event */ _commit_event(TO_VOID_PTR(ctx)); @@ -266,7 +273,6 @@ _FUNC_GET_EVENT_SIZE_BODY_END = ''' return at - ctx->at; _FUNC_SERIALIZE_STREAM_EVENT_HEADER_PROTO_BEGIN = '''static void _serialize_stream_event_header_{sname}( void *vctx, - {clock_ctype} ts, uint32_t event_id''' @@ -295,8 +301,7 @@ _FUNC_SERIALIZE_STREAM_EVENT_CONTEXT_BODY_END = '}' _FUNC_SERIALIZE_EVENT_PROTO_BEGIN = '''static void _serialize_event_{sname}_{evname}( - void *vctx, - {clock_ctype} ts''' + void *vctx''' _FUNC_SERIALIZE_EVENT_PROTO_END = ')' @@ -544,13 +549,17 @@ int _reserve_event_space(void *vctx, uint32_t ev_size) }} /* back-end is not full: open new packet */ + ctx->use_cur_last_event_ts = 1; ctx->cbs.open_packet(ctx->data); + ctx->use_cur_last_event_ts = 0; }} /* event fits the current packet? */ if (ev_size > (ctx->packet_size - ctx->at)) {{ /* no: close packet now */ + ctx->use_cur_last_event_ts = 1; ctx->cbs.close_packet(ctx->data); + ctx->use_cur_last_event_ts = 0; /* is back-end full? */ if (ctx->cbs.is_backend_full(ctx->data)) {{ @@ -561,7 +570,9 @@ int _reserve_event_space(void *vctx, uint32_t ev_size) }} /* back-end is not full: open new packet */ + ctx->use_cur_last_event_ts = 1; ctx->cbs.open_packet(ctx->data); + ctx->use_cur_last_event_ts = 0; assert(ev_size <= (ctx->packet_size - ctx->at)); }} -- 2.34.1