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

Tue Dec 17 02:35:31 EST 2013

You are absolutely right. However, looking at several existing code bases 
that I am working with (our internal code, and a couple of open-source 
projects I am adding LTTng support for), it is clear that the vast 
majority of existing debug log statements have the following general form:

DEBUG_MACRO ( some_args, "lliteral format string", more args )

Amit

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>
To:     Amit Margalit/Israel/IBM at IBMIL
Cc:     "lttng-dev at lists.lttng.org" <lttng-dev at lists.lttng.org>, Mathieu 
Desnoyers <mathieu.desnoyers at efficios.com>
Date:   12/16/2013 03:11 AM
Subject:        RE: [lttng-dev] efficient use of LTTng in legacy codebase

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. 
2.      To have a LTTng macro that provides this string to the tracer, so 
that it can record it only once in the metadata. 
3.      To have the tracepoint store all the arguments in binary form, 
possibly with the addition of some identifying value of the format string. 

4.      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> 
To:        Mathieu Desnoyers <mathieu.desnoyers at efficios.com> 
Cc:        "lttng-dev at lists.lttng.org" <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
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>
To: "Mathieu Desnoyers" <mathieu.desnoyers at efficios.com>
Cc: 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
Subject: Re: efficient use of LTTng in legacy codebase 

From: "Máté Ferenczy" <mate.ferenczy at ericsson.com>
To: "mathieu desnoyers" <mathieu.desnoyers at efficios.com>
Cc: 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 

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com_______________________________________________
lttng-dev mailing list
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/20131217/71337a16/attachment-0001.html>