From 3cb793a17806cf436f2ee052434319f90d4c78a3 Mon Sep 17 00:00:00 2001 From: Philippe Proulx Date: Sat, 19 Nov 2016 14:00:14 -0500 Subject: [PATCH] Add tracing activity and tracing section API The new barectf_is_tracing_enabled() function allows the instrumented program to enable or disable tracing for a specific barectf context. This is a thread-safe API, in that it only sets a member of the context to 0 or 1. Disabling the tracing activity does not guarantee, however, that the current packet or back-end is not currently being altered. See the next paragraph about this. The new barectf_is_in_tracing_section() function allows the instrumented program to know if its tracing thread is currently in a barectf section or not. barectf_is_in_tracing_section_ptr() returns a volatile pointer to this same information. Both functions can be used together to implement a snapshot action for a given platform, something like: 1. The instrumented thread calls the barectf tracing functions during its execution. When a packet is closed, the platform appends it to a ring buffer, overwriting the oldest recorded one if there's no space left. This is called a flight recorder mode. 2. The controller (another thread of the instrumented program, or an external host) recognizes a trigger where we would only need the latest data to analyze the situation. Therefore tracing must be stopped, because we don't want the current ring buffer packets to be overwritten anymore. 3. The controller disables tracing. It is safe to call barectf_is_tracing_enabled(ctx, 0) from another thread. 4. When barectf_is_tracing_enabled(ctx, 0) is called, the barectf tracing function currently being executed still needs to finish. At this point it could still alter the current packet. Therefore the controller waits until barectf_is_in_tracing_section() is 0. 5. Once barectf_is_in_tracing_section() returns 0, it won't return 1 until barectf_is_tracing_enabled(ctx, 1) is called again, so it is safe to read the ring buffer, and also to read the current packet. Signed-off-by: Philippe Proulx --- barectf/gen.py | 102 +++++++++++++++++++++++++------------- barectf/templates.py | 114 +++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 177 insertions(+), 39 deletions(-) diff --git a/barectf/gen.py b/barectf/gen.py index 55b8edb..694f3e7 100644 --- a/barectf/gen.py +++ b/barectf/gen.py @@ -559,7 +559,15 @@ 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 @@ -657,13 +665,14 @@ class CCodeGenerator: lines = tmpl.format(prefix=self._cfg.prefix) self._cg.add_lines(lines) self._cg.indent() + self._cg.add_empty_line() if stream.event_header_type is not None: t = stream.event_header_type 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, {evid}{params});' + tmpl = '_serialize_stream_event_header_{sname}(ctx, ts, {evid}{params});' self._cg.add_cc_line('stream event header') self._cg.add_line(tmpl.format(sname=stream.name, evid=event.id, params=params)) @@ -694,8 +703,16 @@ 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)) + sname=stream.name, + clock_ctype=clock_ctype)) if stream.event_header_type is not None: exclude_list = [ @@ -727,17 +744,6 @@ class CCodeGenerator: lines = tmpl.format(prefix=self._cfg.prefix) self._cg.add_lines(lines) self._cg.indent() - - if stream.event_header_type is not None: - if 'timestamp' in stream.event_header_type.fields: - timestamp = stream.event_header_type.fields['timestamp'] - ts_ctype = self._get_int_ctype(timestamp) - clock = timestamp.property_mappings[0].object - clock_name = clock.name - clock_ctype = clock.return_ctype - tmpl = '{} ts = ctx->cbs.{}_clock_get_value(ctx->data);' - self._cg.add_line(tmpl.format(clock_ctype, clock_name)) - self._cg.add_empty_line() func = self._generate_func_serialize_event_from_entity @@ -750,6 +756,8 @@ class CCodeGenerator: spec_src['id'] = '({}) event_id'.format(id_t_ctype) if 'timestamp' in stream.event_header_type.fields: + field = stream.event_header_type.fields['timestamp'] + ts_ctype = self._get_int_ctype(field) spec_src['timestamp'] = '({}) ts'.format(ts_ctype) func(_PREFIX_SEH, stream.event_header_type, spec_src) @@ -779,8 +787,18 @@ class CCodeGenerator: 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) + + if not ts_line: + ts_line = '\tconst int ts = 0; /* unused */' + self._cg.add_lines(tmpl.format(sname=stream.name, evname=event.name, - params=params)) + params=params, ts=ts_line)) def _generate_func_init(self): self._reset_per_func_state() @@ -800,6 +818,27 @@ class CCodeGenerator: def _reset_per_func_state(self): pass + 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 '' + + if not field.property_mappings: + return '' + + tmpl = '\tconst {} ts = ctx->parent.cbs.{}_clock_get_value(ctx->parent.data);' + clock = field.property_mappings[0].object + line = tmpl.format(clock.return_ctype, clock.name) + + return line + def _generate_func_open(self, stream): def generate_save_offset(name): tmpl = 'ctx->off_spc_{} = ctx->parent.at;'.format(name) @@ -809,28 +848,26 @@ class CCodeGenerator: self._reset_per_func_state() self._generate_func_open_proto(stream) tmpl = templates._FUNC_OPEN_BODY_BEGIN - self._cg.add_lines(tmpl) - self._cg.indent() - tph_type = self._cfg.metadata.trace.packet_header_type + 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'] - tmpl = '{} ts = ctx->parent.cbs.{}_clock_get_value(ctx->parent.data);' - clock = field.property_mappings[0].object - clock_ctype = clock.return_ctype - clock_name = clock.name - self._cg.add_line(tmpl.format(clock_ctype, clock_name)) - self._cg.add_empty_line() + ts_line = self._get_ts_line(field) + lines = tmpl.format(ts=ts_line) + self._cg.add_lines(lines) + self._cg.indent() self._cg.add_cc_line('do not open a packet that is already open') self._cg.add_line('if (ctx->parent.packet_is_open) {') self._cg.indent() + self._cg.add_line('ctx->parent.in_tracing_section = saved_in_tracing_section;') self._cg.add_line('return;') self._cg.unindent() self._cg.add_line('}') self._cg.add_empty_line() self._cg.add_line('ctx->parent.at = 0;') + tph_type = self._cfg.metadata.trace.packet_header_type if tph_type is not None: self._cg.add_empty_line() @@ -931,23 +968,20 @@ class CCodeGenerator: self._reset_per_func_state() self._generate_func_close_proto(stream) tmpl = templates._FUNC_CLOSE_BODY_BEGIN - self._cg.add_lines(tmpl) - self._cg.indent() + ts_line = '' spc_type = stream.packet_context_type - if spc_type is not None: - if 'timestamp_end' in spc_type.fields: - tmpl = '{} ts = ctx->parent.cbs.{}_clock_get_value(ctx->parent.data);' - field = spc_type.fields['timestamp_end'] - clock = field.property_mappings[0].object - clock_ctype = clock.return_ctype - clock_name = clock.name - self._cg.add_line(tmpl.format(clock_ctype, clock_name)) - self._cg.add_empty_line() + 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) + lines = tmpl.format(ts=ts_line) + self._cg.add_lines(lines) + self._cg.indent() self._cg.add_cc_line('do not close a packet that is not open') self._cg.add_line('if (!ctx->parent.packet_is_open) {') self._cg.indent() + self._cg.add_line('ctx->parent.in_tracing_section = saved_in_tracing_section;') self._cg.add_line('return;') self._cg.unindent() self._cg.add_line('}') diff --git a/barectf/templates.py b/barectf/templates.py index 6dc52ce..696a9dd 100644 --- a/barectf/templates.py +++ b/barectf/templates.py @@ -68,6 +68,12 @@ struct {prefix}ctx {{ /* current packet is opened */ int packet_is_open; + + /* in tracing code */ + volatile int in_tracing_section; + + /* tracing is enabled */ + volatile int is_tracing_enabled; }};''' @@ -101,6 +107,8 @@ _FUNC_INIT_BODY = '''{{ ctx->at = 0; ctx->events_discarded = 0; ctx->packet_is_open = 0; + ctx->in_tracing_section = 0; + ctx->is_tracing_enabled = 1; }}''' @@ -112,7 +120,33 @@ void {prefix}{sname}_open_packet( _FUNC_OPEN_PROTO_END = ')' -_FUNC_OPEN_BODY_BEGIN = '{' +_FUNC_OPEN_BODY_BEGIN = '''{{ +{ts} + const int saved_in_tracing_section = ctx->parent.in_tracing_section; + + /* + * This function is either called by a tracing function, or + * directly by the platform. + * + * If it's called by a tracing function, then + * ctx->parent.in_tracing_section is 1, so it's safe to open + * the packet here (alter the packet), even if tracing was + * disabled in the meantime because we're already in a tracing + * section (which finishes at the end of the tracing function + * call). + * + * If it's called directly by the platform, then if tracing is + * disabled, we don't want to alter the packet, and return + * immediately. + */ + if (!ctx->parent.is_tracing_enabled && !saved_in_tracing_section) {{ + ctx->parent.in_tracing_section = 0; + return; + }} + + /* we can modify the packet */ + ctx->parent.in_tracing_section = 1; +''' _FUNC_OPEN_BODY_END = ''' @@ -120,6 +154,9 @@ _FUNC_OPEN_BODY_END = ''' /* mark current packet as open */ ctx->parent.packet_is_open = 1; + + /* not tracing anymore */ + ctx->parent.in_tracing_section = saved_in_tracing_section; }''' @@ -127,7 +164,33 @@ _FUNC_CLOSE_PROTO = '''/* close packet for stream "{sname}" */ void {prefix}{sname}_close_packet(struct {prefix}{sname}_ctx *ctx)''' -_FUNC_CLOSE_BODY_BEGIN = '{' +_FUNC_CLOSE_BODY_BEGIN = '''{{ +{ts} + const int saved_in_tracing_section = ctx->parent.in_tracing_section; + + /* + * This function is either called by a tracing function, or + * directly by the platform. + * + * If it's called by a tracing function, then + * ctx->parent.in_tracing_section is 1, so it's safe to close + * the packet here (alter the packet), even if tracing was + * disabled in the meantime, because we're already in a tracing + * section (which finishes at the end of the tracing function + * call). + * + * If it's called directly by the platform, then if tracing is + * disabled, we don't want to alter the packet, and return + * immediately. + */ + if (!ctx->parent.is_tracing_enabled && !saved_in_tracing_section) {{ + ctx->parent.in_tracing_section = 0; + return; + }} + + /* we can modify the packet */ + ctx->parent.in_tracing_section = 1; +''' _FUNC_CLOSE_BODY_END = ''' @@ -136,6 +199,9 @@ _FUNC_CLOSE_BODY_END = ''' /* mark packet as closed */ ctx->parent.packet_is_open = 0; + + /* not tracing anymore */ + ctx->parent.in_tracing_section = saved_in_tracing_section; }''' @@ -151,22 +217,34 @@ _FUNC_TRACE_PROTO_END = ')' _FUNC_TRACE_BODY = '''{{ +{ts} uint32_t ev_size; + if (!ctx->parent.is_tracing_enabled) {{ + return; + }} + + /* we can modify the packet */ + ctx->parent.in_tracing_section = 1; + /* get event size */ ev_size = _get_event_size_{sname}_{evname}(TO_VOID_PTR(ctx){params}); /* do we have enough space to serialize? */ if (!_reserve_event_space(TO_VOID_PTR(ctx), ev_size)) {{ /* no: forget this */ + ctx->parent.in_tracing_section = 0; return; }} /* serialize event */ - _serialize_event_{sname}_{evname}(TO_VOID_PTR(ctx){params}); + _serialize_event_{sname}_{evname}(TO_VOID_PTR(ctx), ts{params}); /* commit event */ _commit_event(TO_VOID_PTR(ctx)); + + /* not tracing anymore */ + ctx->parent.in_tracing_section = 0; }}''' @@ -188,6 +266,7 @@ _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''' @@ -216,7 +295,8 @@ _FUNC_SERIALIZE_STREAM_EVENT_CONTEXT_BODY_END = '}' _FUNC_SERIALIZE_EVENT_PROTO_BEGIN = '''static void _serialize_event_{sname}_{evname}( - void *vctx''' + void *vctx, + {clock_ctype} ts''' _FUNC_SERIALIZE_EVENT_PROTO_END = ')' @@ -285,7 +365,11 @@ uint32_t {prefix}packet_events_discarded(void *ctx); uint8_t *{prefix}packet_buf(void *ctx); void {prefix}packet_set_buf(void *ctx, uint8_t *buf, uint32_t buf_size); uint32_t {prefix}packet_buf_size(void *ctx); -int {prefix}packet_is_open(void *ctx);''' +int {prefix}packet_is_open(void *ctx); +int {prefix}is_in_tracing_section(void *ctx); +volatile const int *{prefix}is_in_tracing_section_ptr(void *ctx); +int {prefix}is_tracing_enabled(void *ctx); +void {prefix}enable_tracing(void *ctx, int enable);''' _HEADER_END = '''#ifdef __cplusplus @@ -408,6 +492,26 @@ int {prefix}packet_is_open(void *ctx) return FROM_VOID_PTR(struct {prefix}ctx, ctx)->packet_is_open; }} +int {prefix}is_in_tracing_section(void *ctx) +{{ + return FROM_VOID_PTR(struct {prefix}ctx, ctx)->in_tracing_section; +}} + +volatile const int *{prefix}is_in_tracing_section_ptr(void *ctx) +{{ + return &FROM_VOID_PTR(struct {prefix}ctx, ctx)->in_tracing_section; +}} + +int {prefix}is_tracing_enabled(void *ctx) +{{ + return FROM_VOID_PTR(struct {prefix}ctx, ctx)->is_tracing_enabled; +}} + +void {prefix}enable_tracing(void *ctx, int enable) +{{ + FROM_VOID_PTR(struct {prefix}ctx, ctx)->is_tracing_enabled = enable; +}} + static void _write_cstring(struct {prefix}ctx *ctx, const char *src) {{ -- 2.34.1