[lttng-dev] [lttng-ust] [babeltrace] use case question - field names in event classes

[Philippe Proulx]

On Tue, Oct 11, 2016 at 4:46 PM, Staffan Tjernstrom
<staffan at eternaltraveller.com> wrote:
> We have a situation where we have a significant number (1000's) of
> log-style trace messages generated by a large group of (sometime
> offsite) developers.
>
> Unfortunately the tracepoint definitions are maintained by a small
> group of central developers.
>
> So we have a need for generic tracepoint definitions, without loosing
> the ability to tailor the output from individual log messages.
>
> One approach we've come up with involves including the labels as part
> of the parameter pack:
>
> TRACEPOINT_EVENT(
>     my_app,
>     two_ints_and_string,
>     TP_ARGS(
>         // some pre-amble fields removed for clarity
>         char const *, label1_arg,
>         int, value1_arg,
>         char const *, label2_arg,
>         int, value2_arg,
>         char const *, label3_arg,
>         char const *, value3_arg
>     ),
>     TP_FIELDS(
>         // pre-amble removed for clarity
>         ctf_string( label1, label1_arg )
>         ctf_integer(int, value1, value1_arg)
>         ctf_string( label2, label2_arg )
>         ctf_integer(int, value2, value2_arg)
>     )
> )
>
> and we can then call this from multiple locations in our general
> code-base using:
>
> tracepoint(my_app, two_ints_and_string, "widget_height", 19,
> "widget_width", 23, "widget_name", widget_name_as_cstring);
>
> tracepoint(my_app, two_ints_and_string, "x_coordinate", x,
> "y_coordinate", y, "point_type", "star");
>
>
> The issue with this is that the output obviously treats the field
> names and their values as individual items, so we get output like
>
> label1 = "widget_height", value1 = 19, label2 = "widget_width", value2
> =- 23, label3 = "widget_name", value3 = "topper"
> label1 = "x_coordinate", value1 = -23, label2 = "y_coordinate", value2
> = 25532, label3 = "point_type", value3 = "star"
>
> But of course we need to mechanically scrape / inspect the output, so
> what we'd really like would be output something more like:
>
> widget_height = 19, widget_width = 23, widget_name = "topper"
> x_coordinate = -23, y_coordinate = 25532, point_type = "star"
>
> Post-processing of the babeltrace output is of course one option
> (using -n none), but it feels like the wrong choice (adding more steps
> to the tracing chain).
>
> Does anyone out there have any better ideas how to achieve having our
> cake ( a small number of generic tracepoints ), and eating it (
> user-defined field names )?

Unfortunately I believe you can't escape the popular idiom here.

You know it already, but for the record I would like to emphasize that
choosing field names at the tracepoint definition site is always better
than using CTF strings to record them. This is one of the fundamental
purposes of CTF, not recording twice information that does not change.
On the one hand, you're adding to the trace data itself information that
could be stored once in the metadata file, and on the other hand, you
face this problem for which you're asking a solution.

This only applies if you can know all the field names at build time,
which seems to be the case with all those literal C strings passed as
label names in the examples above.

One solution is to use the Python bindings of Babeltrace to read the
trace and associate labels to fields and print only what you need, but:

* It still requires an additional step in the tracing chain.
* The Python bindings are quite slow to execute compared to the text
  output of the `babeltrace` command.

If your goal is really to avoid defining multiple tracepoints and keep
generic ones, and if you're going to use the Python bindings anyway,
you could record events which associate an integer to a set of field
names, and then use this integer when calling generic tracepoints. This
would at least avoid recording the field names in every event record.

For example (not tested);

    TRACEPOINT_EVENT(
        my_app,
        log_statement_field_names,
        TP_ARGS(
            int, id,
            char const *, arg1,
            char const *, arg2,
            char const *, arg3,
            char const *, arg4

            /* more if needed */
        ),
        TP_FIELDS(
            ctf_integer(int, id, id)
            ctf_string(arg1, arg1)
            ctf_string(arg2, arg2)
            ctf_string(arg3, arg3)
            ctf_string(arg4, arg4)

            /* more if needed */
        )
    )

    TRACEPOINT_EVENT(
        my_app,
        two_ints_and_string,
        TP_ARGS(
            int, id,
            int, value1,
            int, value2,
            char const *, value3
        ),
        TP_FIELDS(
            ctf_integer(int, id, id)
            ctf_integer(int, value1, value1)
            ctf_integer(int, value2, value2)
            ctf_string(value3, value3)
        )
    )

In the code, before calling the associated `two_ints_and_string`
tracepoint, and only once:

    tracepoint(my_app, log_statement_field_names, 1,
               "widget_height", "widget_width", "widget_name", "");

Then:

    tracepoint(my_app, two_ints_and_string, 1, height, width, name);

Then in your Python script you can register the dynamic field names when
you get a `log_statement_field_names` event and use them when you get a
"real" event (not tested):

    id_to_field_names = {}

    # open trace, etc.

    # some loop over the trace's events:
        if evt.name == 'log_statement_field_names':
            field_names = (evt['arg1'], evt['arg2'], evt['arg3'], evt['arg4'])
            id_to_field_names[evt['id']] = field_names
        elif evt.name == 'two_ints_and_string':
            field_names = id_to_field_names[evt['id']]
            print('{}: {}'.format(field_names[0], evt['value1']))
            print('{}: {}'.format(field_names[1], evt['value2']))
            print('{}: {}'.format(field_names[2], evt['value3']))
            print()

Now this is a great use case for future extensions of LTTng-UST and/or
the upcoming CTF 2.

Phil

>
> _______________________________________________
> lttng-dev mailing list
> lttng-dev at lists.lttng.org
> https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev