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 <pproulx@efficios.com>
Signed-off-by: Philippe Proulx <eeppeliteloop@gmail.com>

diff --git a/barectf/gen.py b/barectf/gen.py
index 98f819fb672ae788fb8f727fdb683f50f8258b4e..819250c3cb10055f88427df3968009820711cbd4 100644 (file)
--- 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 1f2278bb767c2b65fa99ccf1bed22fbcfb48e21b..eec677ba86f85d84d5d61d186c9b6e656f1dd6ae 100644 (file)
--- 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));
        }}