[lttng-dev] some troubles having lttgng-ust actually log something on a shared library
Mathieu Desnoyers
compudj at krystal.dyndns.org
Wed Dec 21 23:15:44 EST 2011
* Sébastien Barthélémy (barthelemy at crans.org) wrote:
> Hi Mathieu,
>
> thank you again for your enlightenments
>
> 2011/12/20 Mathieu Desnoyers <compudj at krystal.dyndns.org>:
> > * Sébastien Barthélémy (barthelemy at crans.org) wrote:
> >> 2011/12/20 Sébastien Barthélémy <barthelemy at crans.org>:
> >> > 011/12/19 Mathieu Desnoyers <compudj at krystal.dyndns.org>:
> >> >>
> >> >> Please try to reproduce this problem in a simple application that uses
> >> >> dlopen to load libs.
> >> >
> >> > I omitted to mention it, but I tried that yesterday. Without success: tracing
> >> > worked. I'll keep trying.
> >>
> >> There is still a question that bugs me though: the tracing only works if I link
> >> the executable (the one which dlopens the traced .so) against lttng-ust.
> >>
> >> So, while the attached example works out of the box, it won't with the following
> >> patch applied:
> >>
> >> diff --git a/Makefile b/Makefile
> >> index 4674579..6e25f08 100644
> >> --- a/Makefile
> >> +++ b/Makefile
> >> @@ -3,7 +3,7 @@
> >> all: run_motion libmotion.so.1.0.0
> >>
> >> run_motion:run_motion.cpp
> >> - ${CC} -o run_motion -lstdc++ -ldl -llttng-ust run_motion.cpp
> >> + ${CC} -o run_motion -lstdc++ -ldl run_motion.cpp
> >> libmotion.so.1.0.0:motion.o ust_motion.o
> >> ${CC} -shared -Wl,-soname,libmotion.so.1 -o libmotion.so.1.0.0
> >> -ldl -llttng-ust -lstdc++ motion.o ust_motion.o
> >
> > you could also try linking libmotion.so on liblttng-ust, I think it
> > should work too.
>
> It does not, I really do not understand why.
>
> > you can also just LD_PRELOAD libmotion if you don't want to always link
> > your executable to libmotion (and thus liblttng-ust). The "demo" program
> > in the lttng-ust source tree does that with a small shell script.
>
> In this example, libmotion contains
>
> - motion.o: features that I want to instrument
> - ust_motion.o: the probes.
>
> So I'll always need libmotion (though it is dlopened, not linked), but
> I might want to
> avoid loading the probes. I guess I would need two shared objects then.
>
> I'll have a look at these questions once I'll get tracing working ;).
>
> >> The program hangs, waiting for ltt-sessiond :
> >>
> >> libust[4114/4114]: just registered a tracepoints section from
> >> 0x7fab35640aa8 and having 1 tracepoints (in tracepoint_register_lib()
> >> at tracepoint.c:575)
> >> libust[4114/4114]: LTT : ltt ring buffer client init
> >> (in ltt_ring_buffer_metadata_client_init() at
> >> ltt-ring-buffer-metadata-client.h:318)
> >> libust[4114/4114]: LTT : ltt ring buffer client init
> >> (in ltt_ring_buffer_client_overwrite_init() at ltt-ring-buffer-client.h:557)
> >> libust[4114/4114]: LTT : ltt ring buffer client init
> >> (in ltt_ring_buffer_client_discard_init() at ltt-ring-buffer-client.h:557)
> >> libust[4114/4116]: Info: sessiond not accepting connections to global
> >> apps socket (in ust_listener_thread() at lttng-ust-comm.c:633)
> >> libust[4114/4116]: Waiting for global apps sessiond (in
> >> wait_for_sessiond() at lttng-ust-comm.c:556)
> >> libust[4114/4116]: Linux kernels 2.6.33 to 3.0 (with the exception of
> >> stable versions) do not support FUTEX_WAKE on read-only memory
> >> mappings correctly. Please upgrade your kernel (fix is commit
> >> 9ea71503a8ed9184d2d0b8ccc4d269d05f7940ae in Linux kernel mainline).
> >> LTTng-UST will use polling mode fallback. (in wait_for_sessiond() at
> >> lttng-ust-comm.c:569)
> >> libust[4114/4116]: Error: futex: Bad address (in wait_for_sessiond()
> >> at lttng-ust-comm.c:571)
> >> libust[4114/4116]: Info: sessiond not accepting connections to global
> >> apps socket (in ust_listener_thread() at lttng-ust-comm.c:633)
> >> libust[4114/4115]: message received
> >> (in ust_listener_thread() at lttng-ust-comm.c:700)
> >> libust[4114/4114]: Error: Timed out waiting for ltt-sessiond (in
> >> lttng_ust_init() at lttng-ust-comm.c:818)
> >>
> >> Any idea why this is so?
> >
> > The constructor of liblttng-ust always try to register to:
> >
> > 1) the per-user sessiond
> > 2) the system-wide sessiond
> >
> > So you can see that the program cannot register to one of the sessiond,
> > but it does not mean registration to the other has failed.
>
> Maybe, but the program really hangs in such a case, and not in the other.
Hrm, that's odd. It is never supposed to hang the program.
>
> I have attached the two log files if you want to have a look.
I'd bet this is caused by the work-around for "Linux kernels 2.6.33 to
3.0 (with the exception of stable versions) do not support FUTEX_WAKE
on read-only memory mappings correctly. Please upgrade your kernel (fix
is commit 9ea71503a8ed9184d2d0b8ccc4d269d05f7940ae in Linux kernel
mainline). LTTng-UST will use polling mode fallback. (in
wait_for_sessiond() at lttng-ust-comm.c:569)"
I'll try to reproduce your issue here.
>
> > Also, note that you should upgrade your Linux kernel. There is a bug in
> > the futex implementation that lttng-ust needs to work-around by polling
> > for a sessiond every 5 seconds.
>
> Yes, I'll do it too once I'll get the basic tracing working.
>
> >> But how do you get these symbols defined? Greping through the lttng-ust source
> >> code did not help me much.
> >
> > Those are defined in your instrumented application _and_ in
> > liblttng-ust.so (this is why they have a "hidden" visibility -- their
> > scope is either the application or the shared-object they are defined
> > in; there can be more than one of these symbols per process, thanks to
> > the hidden visibility).
>
> ok.
>
> > For information about these special symbols, I have to cite Ian Lance
> > Taylor's blog about this feature almost undocumented
> > (source: http://www.airs.com/blog/archives/56):
>
> Thank you for the link. It makes it all clear. It looks like I have much reading
> to do.
>
> By the way, you haven't answered the question about the single member
> union in struct tp_probes (in liblttng-ust/tracepoint.c).
I guess I missed your question, sorry,
The union also contains a struct rcu_head for call_rcu garbage
collection in the tracepoint.c implementation within the Linux kernel.
Given that I don't want to launch RCU worker threads as a side-effect of
liblttng-ust, I use synchronize_rcu() instead of deferring the reclaim
with call_rcu (it therefore makes the execution slower, but it's less
complex).
But I did not feel like removing the union. So it's an historical
artefact, nothing more.
Thanks,
Mathieu
>
> Yet another almost undocumented feature? Some alignment trickery? A
> mean to extend the struc in the future?
>
> Cheers
> -- Sebastian
> libust[6271/6271]: just registered a tracepoints section from 0x7f7d1de2caa8 and having 1 tracepoints (in tracepoint_register_lib() at tracepoint.c:575)
> libust[6271/6271]: LTT : ltt ring buffer client init
> (in ltt_ring_buffer_metadata_client_init() at ltt-ring-buffer-metadata-client.h:318)
> libust[6271/6271]: LTT : ltt ring buffer client init
> (in ltt_ring_buffer_client_overwrite_init() at ltt-ring-buffer-client.h:557)
> libust[6271/6271]: LTT : ltt ring buffer client init
> (in ltt_ring_buffer_client_discard_init() at ltt-ring-buffer-client.h:557)
> libust[6271/6272]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[6271/6273]: Info: sessiond not accepting connections to global apps socket (in ust_listener_thread() at lttng-ust-comm.c:633)
> libust[6271/6273]: Waiting for global apps sessiond (in wait_for_sessiond() at lttng-ust-comm.c:556)
> libust[6271/6273]: Linux kernels 2.6.33 to 3.0 (with the exception of stable versions) do not support FUTEX_WAKE on read-only memory mappings correctly. Please upgrade your kernel (fix is commit 9ea71503a8ed9184d2d0b8ccc4d269d05f7940ae in Linux kernel mainline). LTTng-UST will use polling mode fallback. (in wait_for_sessiond() at lttng-ust-comm.c:569)
> libust[6271/6273]: Error: futex: Bad address (in wait_for_sessiond() at lttng-ust-comm.c:571)
> libust[6271/6272]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
> libust[6271/6272]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[6271/6273]: Info: sessiond not accepting connections to global apps socket (in ust_listener_thread() at lttng-ust-comm.c:633)
> libust[6271/6272]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
> libust[6271/6272]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[6271/6272]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
> libust[6271/6272]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[6271/6272]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
> libust[6271/6272]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[6271/6272]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
> libust[6271/6272]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[6271/6272]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
> libust[6271/6272]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[6271/6272]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
> libust[6271/6272]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[6271/6272]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
> libust[6271/6272]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[6271/6272]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
> libust[6271/6272]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[6271/6272]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
> libust[6271/6272]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[6271/6272]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
> libust[6271/6271]: just registered a tracepoints section from 0x7f7d1b9940f8 and having 2 tracepoints (in tracepoint_register_lib() at tracepoint.c:575)
> 0
> 100
> 200
> 300
> 400
> 500
> 600
> 700
> 800
> 900
> libust[6271/6271]: just unregistered a tracepoints section from 0x7f7d1b9940f8 (in tracepoint_unregister_lib() at tracepoint.c:608)
> libust[5961/5961]: just registered a tracepoints section from 0x7f0223d69aa8 and having 1 tracepoints (in tracepoint_register_lib() at tracepoint.c:575)
> libust[5961/5961]: LTT : ltt ring buffer client init
> (in ltt_ring_buffer_metadata_client_init() at ltt-ring-buffer-metadata-client.h:318)
> libust[5961/5961]: LTT : ltt ring buffer client init
> (in ltt_ring_buffer_client_overwrite_init() at ltt-ring-buffer-client.h:557)
> libust[5961/5961]: LTT : ltt ring buffer client init
> (in ltt_ring_buffer_client_discard_init() at ltt-ring-buffer-client.h:557)
> libust[5961/5963]: Info: sessiond not accepting connections to global apps socket (in ust_listener_thread() at lttng-ust-comm.c:633)
> libust[5961/5963]: Waiting for global apps sessiond (in wait_for_sessiond() at lttng-ust-comm.c:556)
> libust[5961/5963]: Linux kernels 2.6.33 to 3.0 (with the exception of stable versions) do not support FUTEX_WAKE on read-only memory mappings correctly. Please upgrade your kernel (fix is commit 9ea71503a8ed9184d2d0b8ccc4d269d05f7940ae in Linux kernel mainline). LTTng-UST will use polling mode fallback. (in wait_for_sessiond() at lttng-ust-comm.c:569)
> libust[5961/5963]: Error: futex: Bad address (in wait_for_sessiond() at lttng-ust-comm.c:571)
> libust[5961/5963]: Info: sessiond not accepting connections to global apps socket (in ust_listener_thread() at lttng-ust-comm.c:633)
> libust[5961/5962]: message received
> (in ust_listener_thread() at lttng-ust-comm.c:700)
> libust[5961/5961]: Error: Timed out waiting for ltt-sessiond (in lttng_ust_init() at lttng-ust-comm.c:818)
> _______________________________________________
> 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
More information about the lttng-dev
mailing list