[lttng-dev] some troubles having lttgng-ust actually log something on a shared library

[Sébastien Barthélémy]

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.

I have attached the two log files if you want to have a look.

> 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).

Yet another almost undocumented feature? Some alignment trickery? A
mean to extend the struc in the future?

Cheers
-- Sebastian
-------------- next part --------------
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)
-------------- next part --------------
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)