[lttng-dev] efficient use of LTTng in legacy codebase

Sun Dec 15 20:11:35 EST 2013

I agree that in the long term it would be nice if the trace reader could perform the formatting.

However, I am not sure how #2 would work if the format strings and argument lists are passed through a couple of function calls before calling the tracepoint API (which is the case in our code).

From: Amit Margalit [mailto:AMITM at il.ibm.com]
Sent: Sunday, December 15, 2013 4:56 AM
To: Máté Ferenczy
Cc: lttng-dev at lists.lttng.org; Mathieu Desnoyers
Subject: Re: [lttng-dev] efficient use of LTTng in legacy codebase

The macro is elegant and solves the problem nicely.

I find that it does not make the biggest issue go away - the entire formatted string gets stored in the trace file multiple times.

The best solution would be:

  1.  To modify CTF and define a type that indicates a printf-style format string.

  1.  To have a LTTng macro that provides this string to the tracer, so that it can record it only once in the metadata.

  1.  To have the tracepoint store all the arguments in binary form, possibly with the addition of some identifying value of the format string.

  1.  And to have babeltrace (the CTF trace reader) perform the formatting off-line.

I mean - consider a trace message that includes a long format string, with say - 5 integer arguments. Something like:
"Buffer vacancy threshold warning: curr_limit=%d, curr_threshold=%d, channel_num=%d, high_mark=%d, hit_count=%d"

This stores > 105 bytes with every trace line. But the real information here is only 20 bytes (assuming the integers are 32-bits).

Storing the format string once in the metadata will effectively boost performance for a system trying to trace like this.

Amit Margalit
IBM XIV - Storage Reinvented
XIV-NAS Development Team
Tel. 03-689-7774
Fax. 03-689-7230

From:        Máté Ferenczy <mate.ferenczy at ericsson.com<mailto:mate.ferenczy at ericsson.com>>
To:        Mathieu Desnoyers <mathieu.desnoyers at efficios.com<mailto:mathieu.desnoyers at efficios.com>>
Cc:        "lttng-dev at lists.lttng.org<mailto:lttng-dev at lists.lttng.org>" <lttng-dev at lists.lttng.org<mailto:lttng-dev at lists.lttng.org>>
Date:        12/12/2013 07:39 PM
Subject:        Re: [lttng-dev] efficient use of LTTng in legacy codebase
________________________________

That's even better, as far as I see we do not even have to touch the liblttng code itself.
Will get back with comments if any after testing.

Thanks so much!
mate

From: Mathieu Desnoyers [mailto:mathieu.desnoyers at efficios.com]
Sent: Thursday, December 12, 2013 4:35 AM
To: Máté Ferenczy
Cc: lttng-dev at lists.lttng.org<mailto:lttng-dev at lists.lttng.org>
Subject: Re: efficient use of LTTng in legacy codebase

Just to speed things up, please have a look at the proposed UST patch. (it's not in mainline yet)

This is specifically for a demo program example so far.

Comments are welcome,

Thanks,

Mathieu

________________________________

From: "Máté Ferenczy" <mate.ferenczy at ericsson.com<mailto:mate.ferenczy at ericsson.com>>
To: "Mathieu Desnoyers" <mathieu.desnoyers at efficios.com<mailto:mathieu.desnoyers at efficios.com>>
Cc: lttng-dev at lists.lttng.org<mailto:lttng-dev at lists.lttng.org>
Sent: Wednesday, December 11, 2013 8:52:30 PM
Subject: RE: efficient use of LTTng in legacy codebase

It sounds great, I like the idea. Just to make sure I understand your suggestion, are we talking about converting the variable argument list to string in include/lttng/ust-tracepoint-event-write.h?

For example:
#define ctf_format_string(_item, ...)                               \
        do {                                                      \
            char _buf[BUF_MAXLEN];                               \
            snprintf(buf, sizeof(_buf), __VA_ARGS__);            \
            _ctf_string(_item, _buf, 0);                         \
       } while(0)

Or do you have some better place to put this logic?

Thanks,
Mate

From: Mathieu Desnoyers [mailto:mathieu.desnoyers at efficios.com]
Sent: Wednesday, December 11, 2013 4:48 PM
To: Máté Ferenczy
Cc: lttng-dev at lists.lttng.org<mailto:lttng-dev at lists.lttng.org>
Subject: Re: efficient use of LTTng in legacy codebase

________________________________

From: "Máté Ferenczy" <mate.ferenczy at ericsson.com<mailto:mate.ferenczy at ericsson.com>>
To: "mathieu desnoyers" <mathieu.desnoyers at efficios.com<mailto:mathieu.desnoyers at efficios.com>>
Cc: lttng-dev at lists.lttng.org<mailto:lttng-dev at lists.lttng.org>
Sent: Wednesday, December 11, 2013 6:52:22 PM
Subject: RE: efficient use of LTTng in legacy codebase

I found this email thread: https://www.mail-archive.com/lttng-dev@lists.lttng.org/msg02278.html
According to this I could just check caa_unlikely(__tracepoint_##provider##___##name.state). However, Dave claims that this state will stay true even if the tracepoint is disabled. Is there anything else I should check for?

I would recommend doing this in the UST probe provider instead. Within the TRACEPOINT_EVENT "TP_FIELD" section, when you declare your string field, you could parse the format string there in the last argument of a ctf_string() (a statement expression). The format string would be received as parameter by the tracepoint, along with a variable arg list (...). In the probe, it would be turned into a va_list (see stdarg(3)), and the parameters could be decoded into a string there. This has the benefit of moving the serialization call out-of-line into the probe provider rather than clobbering the tracepoint call site.

Thoughts ?

Thanks,

Mathieu

Thanks,
Mate

From: Máté Ferenczy
Sent: Wednesday, December 11, 2013 12:17 PM
To: 'mathieu.desnoyers at efficios.com'
Cc: 'lttng-dev at lists.lttng.org'
Subject: efficient use of LTTng in legacy codebase
Hello Mathieu,
Our team was asked to support LTTng UST solution in a legacy codebase. The existing codebase is fairly large, and the requirement is that we provide all the existing logs and debugs in the system as LTTng traces.
The planned solution so far was just to pass everything we have as text (strings) to LTTng. For that we obviously have to convert the printf-like format string and parameter list to a string by calling snprintf before giving the string to the LTTng API. That would however mean, that these snprintfs are getting called every time even if there is no listener/active trace session for the given trace. In this case, all those unnecessary snprintf calls may end up significantly impacting the performance of our applications.
In order to work around this, we were thinking that if there was a way to query the LTTng library from our application code whether there is an active tracing session for the given trace level, we could avoid calling those snprintfs in case they are not needed. Do you think it would be feasible to easily get this data from LTTng lib? If yes, can you provide us some pointers where to look at in order to do those changes ourselves?
Any suggestions are welcome.
Thank you,
Mate Ferenczy

--
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com<http://www.efficios.com/>

--
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com<http://www.efficios.com/>_______________________________________________
lttng-dev mailing list
lttng-dev at lists.lttng.org<mailto:lttng-dev at lists.lttng.org>
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20131216/27f8df61/attachment-0001.html>