[lttng-dev] notrace missing in lttng-ust

[lttng-dev] notrace missing in lttng-ust

[Woegerer, Paul]

Hi Mathieu,

libust 0.x uses notrace (__attribute__((no_instrument_function)) for all 
functions that are involved in event emitting.

For example:
./libust/marker.c:122:notrace void __ust_marker_empty_function(const 
struct ust_marker *mdata,
./libust/marker.c:137:notrace void ust_marker_probe_cb(const struct 
ust_marker *mdata,
./libust/marker.c:197:static notrace void 
ust_marker_probe_cb_noarg(const struct ust_marker *mdata,

I just realized that this is no more the case for lttng-ust.
Was it a conscious decision not to use notrace for LTTng 2.0 lttng-ust, 
or is it just missing ?

I would like to have notrace also in lttng-ust, at least for the 
_DECLARE_TRACEPOINT macro in tracepoint.h.
Like this for example:

diff --git a/include/lttng/tracepoint.h b/include/lttng/tracepoint.h
index 5bab476..71665dc 100644
--- a/include/lttng/tracepoint.h
+++ b/include/lttng/tracepoint.h
@@ -137,6 +137,7 @@ extern "C" {

  #define _DECLARE_TRACEPOINT(_provider, _name, ...)     \
  extern struct tracepoint __tracepoint_##_provider##___##_name;         
     \
+static inline void 
__tracepoint_cb_##_provider##___##_name(_TP_ARGS_PROTO(__VA_ARGS__)) 
__attribute__ ((no_instrument_function));    \
  static inline void 
__tracepoint_cb_##_provider##___##_name(_TP_ARGS_PROTO(__VA_ARGS__)) \
  {                                            \
      struct tracepoint_probe *__tp_probe;                        \
@@ -158,12 +159,16 @@ end:     \
      tp_rcu_read_unlock_bp();                            \
  }                                            \
  static inline void __tracepoint_register_##_provider##___##_name(char 
*name,        \
+        void (*func)(void), void *data) __attribute__ 
((no_instrument_function));    \
+static inline void __tracepoint_register_##_provider##___##_name(char 
*name,        \
          void (*func)(void), void *data) \
  {                                            \
      __tracepoint_probe_register(name, func, data,     \
          __tracepoint_##_provider##___##_name.signature); \
  }                                            \
  static inline void 
__tracepoint_unregister_##_provider##___##_name(char *name,        \
+        void (*func)(void), void *data) __attribute__ 
((no_instrument_function));    \
+static inline void __tracepoint_unregister_##_provider##___##_name(char 
*name,        \
          void (*func)(void), void *data) \
  {                                            \
      __tracepoint_probe_unregister(name, func, data); \

Greetings,
Paul

-- 
Paul Woegerer | SW Development Engineer
Mentor Embedded(tm) | Prinz Eugen Stra?e 72/2/4, Vienna, 1040 Austria
P 43.1.535991320
Nucleus? | Linux? | Android(tm) | Services | UI | Multi-OS

Android is a trademark of Google Inc. Use of this trademark is subject to Google Permissions.
Linux is the registered trademark of Linus Torvalds in the U.S. and other countries.

[lttng-dev] notrace missing in lttng-ust

[Mathieu Desnoyers]

* Woegerer, Paul (Paul_Woegerer at mentor.com) wrote:
> Hi Mathieu,
>
> libust 0.x uses notrace (__attribute__((no_instrument_function)) for all  
> functions that are involved in event emitting.
>
> For example:
> ./libust/marker.c:122:notrace void __ust_marker_empty_function(const  
> struct ust_marker *mdata,
> ./libust/marker.c:137:notrace void ust_marker_probe_cb(const struct  
> ust_marker *mdata,
> ./libust/marker.c:197:static notrace void  
> ust_marker_probe_cb_noarg(const struct ust_marker *mdata,
>
> I just realized that this is no more the case for lttng-ust.
> Was it a conscious decision not to use notrace for LTTng 2.0 lttng-ust,  
> or is it just missing ?

just missing. only needed for -finstrument-functions.

>
> I would like to have notrace also in lttng-ust, at least for the  
> _DECLARE_TRACEPOINT macro in tracepoint.h.

I guess the probes generated by ust-tracepoint-event.h would need that
too. A patch that adds those noinline everywhere where it's needed
(hint: all functions called on the tracing patch within public headers
of lttng-ust 2.0 would be a good start). Please test the patch by
tracing a program automatically instrumented by -finstrument-functions
and see if things blow up.

Thanks,

Mathieu

> Like this for example:
>
> diff --git a/include/lttng/tracepoint.h b/include/lttng/tracepoint.h
> index 5bab476..71665dc 100644
> --- a/include/lttng/tracepoint.h
> +++ b/include/lttng/tracepoint.h
> @@ -137,6 +137,7 @@ extern "C" {
>
>  #define _DECLARE_TRACEPOINT(_provider, _name, ...)     \
>  extern struct tracepoint __tracepoint_##_provider##___##_name;           
>   \
> +static inline void  
> __tracepoint_cb_##_provider##___##_name(_TP_ARGS_PROTO(__VA_ARGS__))  
> __attribute__ ((no_instrument_function));    \
>  static inline void  
> __tracepoint_cb_##_provider##___##_name(_TP_ARGS_PROTO(__VA_ARGS__)) \
>  {                                            \
>      struct tracepoint_probe *__tp_probe;                        \
> @@ -158,12 +159,16 @@ end:     \
>      tp_rcu_read_unlock_bp();                            \
>  }                                            \
>  static inline void __tracepoint_register_##_provider##___##_name(char  
> *name,        \
> +        void (*func)(void), void *data) __attribute__  
> ((no_instrument_function));    \
> +static inline void __tracepoint_register_##_provider##___##_name(char  
> *name,        \
>          void (*func)(void), void *data) \
>  {                                            \
>      __tracepoint_probe_register(name, func, data,     \
>          __tracepoint_##_provider##___##_name.signature); \
>  }                                            \
>  static inline void __tracepoint_unregister_##_provider##___##_name(char 
> *name,        \
> +        void (*func)(void), void *data) __attribute__  
> ((no_instrument_function));    \
> +static inline void __tracepoint_unregister_##_provider##___##_name(char  
> *name,        \
>          void (*func)(void), void *data) \
>  {                                            \
>      __tracepoint_probe_unregister(name, func, data); \
>
> Greetings,
> Paul
>
> -- 
> Paul Woegerer | SW Development Engineer
> Mentor Embedded(tm) | Prinz Eugen Stra?e 72/2/4, Vienna, 1040 Austria
> P 43.1.535991320
> Nucleus? | Linux? | Android(tm) | Services | UI | Multi-OS
>
> Android is a trademark of Google Inc. Use of this trademark is subject to Google Permissions.
> Linux is the registered trademark of Linus Torvalds in the U.S. and other countries.
>
>
> _______________________________________________
> lttng-dev mailing list
> lttng-dev at lists.lttng.org
> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com

[lttng-dev] notrace missing in lttng-ust

[Francis Giraldeau]

Le 2012-07-17 10:13, Mathieu Desnoyers a ?crit :
> * Woegerer, Paul (Paul_Woegerer at mentor.com) wrote:
>> Hi Mathieu,
>>
>> here is the revised patch that makes tracepoint.h and  
>> ust-tracepoint-event.h robust against -finstrument-functions.
> 
> I think we want to make the notrace always active. I don't see the point
> in letting UST lib be compiled with those tracing stubs in place.

I just hit a case where it would have been useful to profile lttng-ust
itself.

When generating events in a tight loop, the average time to execute a
simple tracepoint is about 280ns on my machine. But the problem is that
once in a while (once out of a million execution) the latency bump to a
blazing 100us. I agree, it's still fast, but nonetheless the maximum is
~350 times more than the average, which is strange.

I tried many profiling tools (perf, valgrind, etc.) and none was
providing good results. It's no point to use lttng-ust itself (are
tracepoints reentrants?). So, I decided to try -finstrument-functions
stuff with a small pre-allocated ringbuffer to get the lowest latency
possible. Well, it turns out that I was getting no results for the
tracepoint, because function instrumentation is disabled.

I tried to re-enable it, but then the instrumented app fails with this
error message:

/usr/local/include/lttng/ust-tracepoint-event.h:646:
__lttng_events_init__npt: Assertion `!ret' failed.

I confess that I didn't look deeply into this problem, but it's quite
strange that the init fails in the case function instrumentation is
enabled. Could it be related to the dlopen() done at registration? Maybe
somebody has an idea, because I saw screenshots of similar profiling
previously on the ML ;) Here is the configuration options to lttng-ust
(the profiling library is miniprof[1]):

./configure CFLAGS="-finstrument-functions" LIBS="-lminiprof"
LDFLAGS="-L/usr/local/lib -Wl,-E"

Cheers,

Francis

[1] https://github.com/giraldeau/miniprof

-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 4489 bytes
Desc: Signature cryptographique S/MIME
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20121001/1e34e8dd/attachment.bin>

[lttng-dev] notrace missing in lttng-ust

[Mathieu Desnoyers]

* Francis Giraldeau (francis.giraldeau at gmail.com) wrote:
> Le 2012-07-17 10:13, Mathieu Desnoyers a ?crit :
> > * Woegerer, Paul (Paul_Woegerer at mentor.com) wrote:
> >> Hi Mathieu,
> >>
> >> here is the revised patch that makes tracepoint.h and  
> >> ust-tracepoint-event.h robust against -finstrument-functions.
> > 
> > I think we want to make the notrace always active. I don't see the point
> > in letting UST lib be compiled with those tracing stubs in place.
> 
> I just hit a case where it would have been useful to profile lttng-ust
> itself.
> 
> When generating events in a tight loop, the average time to execute a
> simple tracepoint is about 280ns on my machine. But the problem is that
> once in a while (once out of a million execution) the latency bump to a
> blazing 100us. I agree, it's still fast, but nonetheless the maximum is
> ~350 times more than the average, which is strange.

interesting indeed. I would expect this time might be spent in the
"write" to the fifo to wakeup the consumerd, but even then it is
surprising, as this is supposed to be a non-blocking fifo.

> I tried many profiling tools (perf, valgrind, etc.) and none was
> providing good results. It's no point to use lttng-ust itself (are
> tracepoints reentrants?).

that might not work indeed. Something about infinite recursion.

You might want to try kernel tracing, and see if this time is spent
anywhere in the kernel when doing UST tracing.

> So, I decided to try -finstrument-functions
> stuff with a small pre-allocated ringbuffer to get the lowest latency
> possible. Well, it turns out that I was getting no results for the
> tracepoint, because function instrumentation is disabled.

no, don't. you'll run into infinite recursion too.

> 
> I tried to re-enable it, but then the instrumented app fails with this
> error message:
> 
> /usr/local/include/lttng/ust-tracepoint-event.h:646:
> __lttng_events_init__npt: Assertion `!ret' failed.

Doing something like that might require that you LD_PRELOAD
liblttng-ust-tracepoint.so, so that its constructor runs before the
constructor registering the .so that contains the function callback.

Thanks,

Mathieu

> 
> I confess that I didn't look deeply into this problem, but it's quite
> strange that the init fails in the case function instrumentation is
> enabled. Could it be related to the dlopen() done at registration? Maybe
> somebody has an idea, because I saw screenshots of similar profiling
> previously on the ML ;) Here is the configuration options to lttng-ust
> (the profiling library is miniprof[1]):
> 
> ./configure CFLAGS="-finstrument-functions" LIBS="-lminiprof"
> LDFLAGS="-L/usr/local/lib -Wl,-E"
> 
> Cheers,
> 
> Francis
> 
> [1] https://github.com/giraldeau/miniprof
> 



-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com