All of lore.kernel.org
 help / color / mirror / Atom feed
* Re: Problem LD_PRELOADing multiple UST helpers
       [not found] <5627922E.9000808@techfak.uni-bielefeld.de>
@ 2015-10-21 15:38 ` Jonathan Rajotte Julien
       [not found] ` <5627B163.5060407@efficios.com>
  1 sibling, 0 replies; 3+ messages in thread
From: Jonathan Rajotte Julien @ 2015-10-21 15:38 UTC (permalink / raw)
  To: Christian Ascheberg; +Cc: lttng-dev

Hi Christian,

The more debug output the merrier !

Could you attach the file generated (ld_debug.out.xxxx) by this command:

LD_PRELOAD="liblttng-ust-libc-wrapper.so liblttng-ust-cyg-profile.so 
liblttng-ust-pthread-wrapper.so liblttng-ust-dl.so" LD_DEBUG=all 
LD_DEBUG_OUTPUT=ld_debug.out ls

Also is the output provided in your previous email all of the debug 
output from 'ls' ?

Cheers!

On 2015-10-21 09:25 AM, Christian Ascheberg wrote:
> Hello,
>
> I am having a strange problem with LTTng UST helpers on a Cyclone V 
> ARM development board. If I LD_PRELOAD multiple helpers, then only 
> data of the first loaded helper appears in the trace.
> Below I have some debug output that looks wrong:
>
> This is the command:
> root@cyclone5:~# LTTNG_UST_DEBUG=1 
> LD_PRELOAD="liblttng-ust-libc-wrapper.so liblttng-ust-cyg-profile.so 
> liblttng-ust-pthread-wrapper.so liblttng-ust-dl.so" ls
>
> - This is some output regarding the first registration:
> liblttng_ust_tracepoint[XXX/XXX]: just registered a tracepoints 
> section from 0x76e7b42c and having 2 tracepoints (in 
> tracepoint_register_lib() at tracepoint.c:767)
> liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
> ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
> tracepoint.c:772)
> liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
> lttng_ust_tracef:event (in tracepoint_register_lib() at tracepoint.c:772)
> libust[XXX/XXX]: Provider "ust_baddr_statedump" accepted, version 1.0 
> is compatible with LTTng UST provider version 1.0. (in 
> check_provider_version() at lttng-probes.c:174)
> libust[XXX/XXX]: adding probe ust_baddr_statedump containing 1 events 
> to lazy registration list (in lttng_probe_register() at 
> lttng-probes.c:216)
> libust[XXX/XXY]: just registered probe ust_baddr_statedump containing 
> 1 events (in lttng_lazy_probe_register() at lttng-probes.c:115)
> libust[XXX/XXY]: Sent register event notification for name 
> "ust_baddr_statedump:soinfo": ret_code 0, event_id 0
>  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
> liblttng_ust_tracepoint[XXX/XXY]: Registering probe to tracepoint 
> ust_baddr_statedump:soinfo (in __tracepoint_probe_register() at 
> tracepoint.c:563)
> liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
> lttng_ust_tracef:event (in __tracepoint_probe_register() at 
> tracepoint.c:563)
>
> - And here is some strange output regarding another registration:
> liblttng_ust_tracepoint[XXX/XXX]: just registered a tracepoints 
> section from 0x76e7b42c and having 2 tracepoints (in 
> tracepoint_register_lib() at tracepoint.c:767)
> liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
> ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
> tracepoint.c:772)
> liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
> lttng_ust_tracef:event (in tracepoint_register_lib() at tracepoint.c:772)
> libust[XXX/XXX]: Provider "ust_pthread" accepted, version 1.0 is 
> compatible with LTTng UST provider version 1.0. (in 
> check_provider_version() at lttng-probes.c:174)
> libust[XXX/XXX]: adding probe ust_pthread containing 4 events to lazy 
> registration list (in lttng_probe_register() at lttng-probes.c:216)
> libust[XXX/XXX]: just registered probe ust_pthread containing 4 events 
> (in lttng_lazy_probe_register() at lttng-probes.c:115)
> libust[XXX/XXX]: Sent register event notification for name 
> "ust_pthread:pthread_mutex_lock_req": ret_code 0, event_id 4
>  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
> libust[XXX/XXX]: Sent register event notification for name 
> "ust_pthread:pthread_mutex_lock_acq": ret_code 0, event_id 5
>  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
> libust[XXX/XXX]: Sent register event notification for name 
> "ust_pthread:pthread_mutex_trylock": ret_code 0, event_id 6
>  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
> libust[XXX/XXX]: Sent register event notification for name 
> "ust_pthread:pthread_mutex_unlock": ret_code 0, event_id 7
>  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
> liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
> ust_pthread:pthread_mutex_unlock (in __tracepoint_probe_register() at 
> tracepoint.c:563)
> liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
> ust_pthread:pthread_mutex_trylock (in __tracepoint_probe_register() at 
> tracepoint.c:563)
> liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
> ust_pthread:pthread_mutex_lock_acq (in __tracepoint_probe_register() 
> at tracepoint.c:563)
> liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
> ust_pthread:pthread_mutex_lock_req (in __tracepoint_probe_register() 
> at tracepoint.c:563)
>
> As with this one, the first three lines of all registrations are 
> always the same and do not match the following (in this case) 
> 'Provider "ust_pthread" accepted'.
> I subsequently only get tracepoint data from ust_baddr_statedump:soinfo.
>
> I followed these build instructions for my board using Yocto 1.7: 
> http://rocketboards.org/foswiki/view/Documentation/GSRD150CompilingLinux
> I also tried updating the recipes to use the latest version of LTTng. 
> The output above is from LTTng v2.6.2.
> I can provide more debug output if that helps. I do not see this 
> problem on my desktop computer.
>
> Can somebody confirm this problem?
>
> Thanks, Christian
>
> _______________________________________________
> lttng-dev mailing list
> lttng-dev@lists.lttng.org
> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Jonathan R. Julien
Efficios

^ permalink raw reply	[flat|nested] 3+ messages in thread

* Re: Problem LD_PRELOADing multiple UST helpers
       [not found] ` <5627B163.5060407@efficios.com>
@ 2015-10-23 17:09   ` Christian Ascheberg
  0 siblings, 0 replies; 3+ messages in thread
From: Christian Ascheberg @ 2015-10-23 17:09 UTC (permalink / raw)
  To: lttng-dev

The requested output that was generated by the stated command is in 
http://pastebin.com/zxuFQ8yV (part 1) and http://pastebin.com/GgR8d3pV 
(part 2).

The full LTTng debug output, split by executed commands, is in 
http://pastebin.com/NsCxaYGT

As I tried to say before, note that these three lines are occuring for 
every registration, but they should occur only once:
liblttng_ust_tracepoint[313/313]: just registered a tracepoints section 
from 0x76e7b42c and having 2 tracepoints (in tracepoint_register_lib() 
at tracepoint.c:767)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
tracepoint.c:772)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
lttng_ust_tracef:event (in tracepoint_register_lib() at tracepoint.c:772)

Corresponding lines for other tracepoint providers are missing instead.


This is the full UST part of the debug output. Part of that is what I 
had posted before.

root@cyclone5:~# LD_PRELOAD="liblttng-ust-libc-wrapper.so 
liblttng-ust-cyg-profile.so liblttng-ust-pthread-wrapper.so 
liblttng-ust-dl.so" ls
liblttng_ust_tracepoint[313/313]: just registered a tracepoints section 
from 0x76e7b42c and having 2 tracepoints (in tracepoint_register_lib() 
at tracepoint.c:767)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
tracepoint.c:772)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
lttng_ust_tracef:event (in tracepoint_register_lib() at tracepoint.c:772)
libust[313/313]: Provider "ust_baddr_statedump" accepted, version 1.0 is 
compatible with LTTng UST provider version 1.0. (in 
check_provider_version() at lttng-probes.c:174)
libust[313/313]: adding probe ust_baddr_statedump containing 1 events to 
lazy registration list (in lttng_probe_register() at lttng-probes.c:216)
libust[313/313]: LTT : ltt ring buffer client "relay-metadata-mmap" init
  (in lttng_ring_buffer_metadata_client_init() at 
lttng-ring-buffer-metadata-client.h:330)
libust[313/313]: LTT : ltt ring buffer client "relay-overwrite-mmap" init
  (in lttng_ring_buffer_client_overwrite_init() at 
lttng-ring-buffer-client.h:681)
libust[313/313]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" init
  (in lttng_ring_buffer_client_overwrite_rt_init() at 
lttng-ring-buffer-client.h:681)
libust[313/313]: LTT : ltt ring buffer client "relay-discard-mmap" init
  (in lttng_ring_buffer_client_discard_init() at 
lttng-ring-buffer-client.h:681)
libust[313/313]: LTT : ltt ring buffer client "relay-discard-rt-mmap" init
  (in lttng_ring_buffer_client_discard_rt_init() at 
lttng-ring-buffer-client.h:681)
libust[313/315]: Info: sessiond not accepting connections to local apps 
socket (in ust_listener_thread() at lttng-ust-comm.c:1224)
libust[313/315]: Waiting for local apps sessiond (in wait_for_sessiond() 
at lttng-ust-comm.c:1135)
libust[313/314]: Message Received "Get Tracer Version" (65), Handle 
"root" (0) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 0 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Create Session" (64), Handle "root" 
(0) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 1 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Create Channel" (81), Handle 
"session" (1) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: channel data received (in handle_message() at 
lttng-ust-comm.c:723)
libust[313/314]: Return value: 2 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Create Stream" (96), Handle "channel" 
(2) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 0 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Create Stream" (96), Handle "channel" 
(2) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 0 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Create Context" (112), Handle 
"channel" (2) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 0 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Create Context" (112), Handle 
"channel" (2) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 0 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Create Context" (112), Handle 
"channel" (2) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 0 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Create Context" (112), Handle 
"channel" (2) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 0 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Create Event" (97), Handle "channel" 
(2) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 3 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Enable" (128), Handle "enabler" (3) 
(in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 0 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Enable" (128), Handle "session" (1) 
(in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Sent register channel notification: chan_id 0, 
header_type 1
  (in ustcomm_register_channel() at lttng-ust-comm.c:1108)
libust[313/314]: just registered probe ust_baddr_statedump containing 1 
events (in lttng_lazy_probe_register() at lttng-probes.c:115)
libust[313/314]: Sent register event notification for name 
"ust_baddr_statedump:soinfo": ret_code 0, event_id 0
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
liblttng_ust_tracepoint[313/314]: Registering probe to tracepoint 
ust_baddr_statedump:soinfo (in __tracepoint_probe_register() at 
tracepoint.c:563)
libust[313/314]: Return value: 0 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Wait for Quiescent State" (67), 
Handle "root" (0) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 0 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/314]: Message Received "Registration Done" (68), Handle 
"root" (0) (in print_cmd() at lttng-ust-comm.c:367)
libust[313/314]: Return value: 0 (in handle_message() at 
lttng-ust-comm.c:827)
libust[313/314]: message successfully sent (in send_reply() at 
lttng-ust-comm.c:484)
libust[313/313]: adding probe lttng_ust_tracef containing 1 events to 
lazy registration list (in lttng_probe_register() at lttng-probes.c:216)
libust[313/313]: just registered probe lttng_ust_tracef containing 1 
events (in lttng_lazy_probe_register() at lttng-probes.c:115)
libust[313/313]: Sent register event notification for name 
"lttng_ust_tracef:event": ret_code 0, event_id 1
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
lttng_ust_tracef:event (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: just registered a tracepoints section 
from 0x76e7b42c and having 2 tracepoints (in tracepoint_register_lib() 
at tracepoint.c:767)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
tracepoint.c:772)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
lttng_ust_tracef:event (in tracepoint_register_lib() at tracepoint.c:772)
libust[313/313]: Provider "ust_baddr" accepted, version 1.0 is 
compatible with LTTng UST provider version 1.0. (in 
check_provider_version() at lttng-probes.c:174)
libust[313/313]: adding probe ust_baddr containing 2 events to lazy 
registration list (in lttng_probe_register() at lttng-probes.c:216)
libust[313/313]: just registered probe ust_baddr containing 2 events (in 
lttng_lazy_probe_register() at lttng-probes.c:115)
libust[313/313]: Sent register event notification for name 
"ust_baddr:push": ret_code 0, event_id 2
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[313/313]: Sent register event notification for name 
"ust_baddr:pop": ret_code 0, event_id 3
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_baddr:pop (in __tracepoint_probe_register() at tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_baddr:push (in __tracepoint_probe_register() at tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: just registered a tracepoints section 
from 0x76e7b42c and having 2 tracepoints (in tracepoint_register_lib() 
at tracepoint.c:767)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
tracepoint.c:772)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
lttng_ust_tracef:event (in tracepoint_register_lib() at tracepoint.c:772)
libust[313/313]: Provider "ust_pthread" accepted, version 1.0 is 
compatible with LTTng UST provider version 1.0. (in 
check_provider_version() at lttng-probes.c:174)
libust[313/313]: adding probe ust_pthread containing 4 events to lazy 
registration list (in lttng_probe_register() at lttng-probes.c:216)
libust[313/313]: just registered probe ust_pthread containing 4 events 
(in lttng_lazy_probe_register() at lttng-probes.c:115)
libust[313/313]: Sent register event notification for name 
"ust_pthread:pthread_mutex_lock_req": ret_code 0, event_id 4
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[313/313]: Sent register event notification for name 
"ust_pthread:pthread_mutex_lock_acq": ret_code 0, event_id 5
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[313/313]: Sent register event notification for name 
"ust_pthread:pthread_mutex_trylock": ret_code 0, event_id 6
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[313/313]: Sent register event notification for name 
"ust_pthread:pthread_mutex_unlock": ret_code 0, event_id 7
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_pthread:pthread_mutex_unlock (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_pthread:pthread_mutex_trylock (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_pthread:pthread_mutex_lock_acq (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_pthread:pthread_mutex_lock_req (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: just registered a tracepoints section 
from 0x76e7b42c and having 2 tracepoints (in tracepoint_register_lib() 
at tracepoint.c:767)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
tracepoint.c:772)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
lttng_ust_tracef:event (in tracepoint_register_lib() at tracepoint.c:772)
libust[313/313]: Provider "lttng_ust_cyg_profile" accepted, version 1.0 
is compatible with LTTng UST provider version 1.0. (in 
check_provider_version() at lttng-probes.c:174)
libust[313/313]: adding probe lttng_ust_cyg_profile containing 2 events 
to lazy registration list (in lttng_probe_register() at lttng-probes.c:216)
libust[313/313]: just registered probe lttng_ust_cyg_profile containing 
2 events (in lttng_lazy_probe_register() at lttng-probes.c:115)
libust[313/313]: Sent register event notification for name 
"lttng_ust_cyg_profile:func_entry": ret_code 0, event_id 8
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[313/313]: Sent register event notification for name 
"lttng_ust_cyg_profile:func_exit": ret_code 0, event_id 9
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
lttng_ust_cyg_profile:func_exit (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
lttng_ust_cyg_profile:func_entry (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: just registered a tracepoints section 
from 0x76e7b42c and having 2 tracepoints (in tracepoint_register_lib() 
at tracepoint.c:767)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
tracepoint.c:772)
liblttng_ust_tracepoint[313/313]: registered tracepoint: 
lttng_ust_tracef:event (in tracepoint_register_lib() at tracepoint.c:772)
libust[313/313]: Provider "ust_libc" accepted, version 1.0 is compatible 
with LTTng UST provider version 1.0. (in check_provider_version() at 
lttng-probes.c:174)
libust[313/313]: adding probe ust_libc containing 6 events to lazy 
registration list (in lttng_probe_register() at lttng-probes.c:216)
libust[313/313]: just registered probe ust_libc containing 6 events (in 
lttng_lazy_probe_register() at lttng-probes.c:115)
libust[313/313]: Sent register event notification for name 
"ust_libc:malloc": ret_code 0, event_id 10
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[313/313]: Sent register event notification for name 
"ust_libc:free": ret_code 0, event_id 11
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[313/313]: Sent register event notification for name 
"ust_libc:calloc": ret_code 0, event_id 12
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[313/313]: Sent register event notification for name 
"ust_libc:realloc": ret_code 0, event_id 13
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[313/313]: Sent register event notification for name 
"ust_libc:memalign": ret_code 0, event_id 14
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[313/313]: Sent register event notification for name 
"ust_libc:posix_memalign": ret_code 0, event_id 15
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_libc:posix_memalign (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_libc:memalign (in __tracepoint_probe_register() at tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_libc:realloc (in __tracepoint_probe_register() at tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_libc:calloc (in __tracepoint_probe_register() at tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_libc:free (in __tracepoint_probe_register() at tracepoint.c:563)
liblttng_ust_tracepoint[313/313]: Registering probe to tracepoint 
ust_libc:malloc (in __tracepoint_probe_register() at tracepoint.c:563)



Am 21.10.2015 um 17:38 schrieb Jonathan Rajotte Julien:
> Hi Christian,
>
> The more debug output the merrier !
>
> Could you attach the file generated (ld_debug.out.xxxx) by this command:
>
> LD_PRELOAD="liblttng-ust-libc-wrapper.so liblttng-ust-cyg-profile.so 
> liblttng-ust-pthread-wrapper.so liblttng-ust-dl.so" LD_DEBUG=all 
> LD_DEBUG_OUTPUT=ld_debug.out ls
>
> Also is the output provided in your previous email all of the debug 
> output from 'ls' ?
>
> Cheers!
>
> On 2015-10-21 09:25 AM, Christian Ascheberg wrote:
>> Hello,
>>
>> I am having a strange problem with LTTng UST helpers on a Cyclone V 
>> ARM development board. If I LD_PRELOAD multiple helpers, then only 
>> data of the first loaded helper appears in the trace.
>> Below I have some debug output that looks wrong:
>>
>> This is the command:
>> root@cyclone5:~# LTTNG_UST_DEBUG=1 
>> LD_PRELOAD="liblttng-ust-libc-wrapper.so liblttng-ust-cyg-profile.so 
>> liblttng-ust-pthread-wrapper.so liblttng-ust-dl.so" ls
>>
>> - This is some output regarding the first registration:
>> liblttng_ust_tracepoint[XXX/XXX]: just registered a tracepoints 
>> section from 0x76e7b42c and having 2 tracepoints (in 
>> tracepoint_register_lib() at tracepoint.c:767)
>> liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
>> ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
>> tracepoint.c:772)
>> liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
>> lttng_ust_tracef:event (in tracepoint_register_lib() at 
>> tracepoint.c:772)
>> libust[XXX/XXX]: Provider "ust_baddr_statedump" accepted, version 1.0 
>> is compatible with LTTng UST provider version 1.0. (in 
>> check_provider_version() at lttng-probes.c:174)
>> libust[XXX/XXX]: adding probe ust_baddr_statedump containing 1 events 
>> to lazy registration list (in lttng_probe_register() at 
>> lttng-probes.c:216)
>> libust[XXX/XXY]: just registered probe ust_baddr_statedump containing 
>> 1 events (in lttng_lazy_probe_register() at lttng-probes.c:115)
>> libust[XXX/XXY]: Sent register event notification for name 
>> "ust_baddr_statedump:soinfo": ret_code 0, event_id 0
>>  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
>> liblttng_ust_tracepoint[XXX/XXY]: Registering probe to tracepoint 
>> ust_baddr_statedump:soinfo (in __tracepoint_probe_register() at 
>> tracepoint.c:563)
>> liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
>> lttng_ust_tracef:event (in __tracepoint_probe_register() at 
>> tracepoint.c:563)
>>
>> - And here is some strange output regarding another registration:
>> liblttng_ust_tracepoint[XXX/XXX]: just registered a tracepoints 
>> section from 0x76e7b42c and having 2 tracepoints (in 
>> tracepoint_register_lib() at tracepoint.c:767)
>> liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
>> ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
>> tracepoint.c:772)
>> liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
>> lttng_ust_tracef:event (in tracepoint_register_lib() at 
>> tracepoint.c:772)
>> libust[XXX/XXX]: Provider "ust_pthread" accepted, version 1.0 is 
>> compatible with LTTng UST provider version 1.0. (in 
>> check_provider_version() at lttng-probes.c:174)
>> libust[XXX/XXX]: adding probe ust_pthread containing 4 events to lazy 
>> registration list (in lttng_probe_register() at lttng-probes.c:216)
>> libust[XXX/XXX]: just registered probe ust_pthread containing 4 
>> events (in lttng_lazy_probe_register() at lttng-probes.c:115)
>> libust[XXX/XXX]: Sent register event notification for name 
>> "ust_pthread:pthread_mutex_lock_req": ret_code 0, event_id 4
>>  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
>> libust[XXX/XXX]: Sent register event notification for name 
>> "ust_pthread:pthread_mutex_lock_acq": ret_code 0, event_id 5
>>  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
>> libust[XXX/XXX]: Sent register event notification for name 
>> "ust_pthread:pthread_mutex_trylock": ret_code 0, event_id 6
>>  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
>> libust[XXX/XXX]: Sent register event notification for name 
>> "ust_pthread:pthread_mutex_unlock": ret_code 0, event_id 7
>>  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
>> liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
>> ust_pthread:pthread_mutex_unlock (in __tracepoint_probe_register() at 
>> tracepoint.c:563)
>> liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
>> ust_pthread:pthread_mutex_trylock (in __tracepoint_probe_register() 
>> at tracepoint.c:563)
>> liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
>> ust_pthread:pthread_mutex_lock_acq (in __tracepoint_probe_register() 
>> at tracepoint.c:563)
>> liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
>> ust_pthread:pthread_mutex_lock_req (in __tracepoint_probe_register() 
>> at tracepoint.c:563)
>>
>> As with this one, the first three lines of all registrations are 
>> always the same and do not match the following (in this case) 
>> 'Provider "ust_pthread" accepted'.
>> I subsequently only get tracepoint data from ust_baddr_statedump:soinfo.
>>
>> I followed these build instructions for my board using Yocto 1.7: 
>> http://rocketboards.org/foswiki/view/Documentation/GSRD150CompilingLinux
>> I also tried updating the recipes to use the latest version of LTTng. 
>> The output above is from LTTng v2.6.2.
>> I can provide more debug output if that helps. I do not see this 
>> problem on my desktop computer.
>>
>> Can somebody confirm this problem?
>>
>> Thanks, Christian
>>
>> _______________________________________________
>> lttng-dev mailing list
>> lttng-dev@lists.lttng.org
>> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
>

^ permalink raw reply	[flat|nested] 3+ messages in thread

* Problem LD_PRELOADing multiple UST helpers
@ 2015-10-21 13:25 Christian Ascheberg
  0 siblings, 0 replies; 3+ messages in thread
From: Christian Ascheberg @ 2015-10-21 13:25 UTC (permalink / raw)
  To: lttng-dev

Hello,

I am having a strange problem with LTTng UST helpers on a Cyclone V ARM 
development board. If I LD_PRELOAD multiple helpers, then only data of 
the first loaded helper appears in the trace.
Below I have some debug output that looks wrong:

This is the command:
root@cyclone5:~# LTTNG_UST_DEBUG=1 
LD_PRELOAD="liblttng-ust-libc-wrapper.so liblttng-ust-cyg-profile.so 
liblttng-ust-pthread-wrapper.so liblttng-ust-dl.so" ls

- This is some output regarding the first registration:
liblttng_ust_tracepoint[XXX/XXX]: just registered a tracepoints section 
from 0x76e7b42c and having 2 tracepoints (in tracepoint_register_lib() 
at tracepoint.c:767)
liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
tracepoint.c:772)
liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
lttng_ust_tracef:event (in tracepoint_register_lib() at tracepoint.c:772)
libust[XXX/XXX]: Provider "ust_baddr_statedump" accepted, version 1.0 is 
compatible with LTTng UST provider version 1.0. (in 
check_provider_version() at lttng-probes.c:174)
libust[XXX/XXX]: adding probe ust_baddr_statedump containing 1 events to 
lazy registration list (in lttng_probe_register() at lttng-probes.c:216)
libust[XXX/XXY]: just registered probe ust_baddr_statedump containing 1 
events (in lttng_lazy_probe_register() at lttng-probes.c:115)
libust[XXX/XXY]: Sent register event notification for name 
"ust_baddr_statedump:soinfo": ret_code 0, event_id 0
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
liblttng_ust_tracepoint[XXX/XXY]: Registering probe to tracepoint 
ust_baddr_statedump:soinfo (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
lttng_ust_tracef:event (in __tracepoint_probe_register() at 
tracepoint.c:563)

- And here is some strange output regarding another registration:
liblttng_ust_tracepoint[XXX/XXX]: just registered a tracepoints section 
from 0x76e7b42c and having 2 tracepoints (in tracepoint_register_lib() 
at tracepoint.c:767)
liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
ust_baddr_statedump:soinfo (in tracepoint_register_lib() at 
tracepoint.c:772)
liblttng_ust_tracepoint[XXX/XXX]: registered tracepoint: 
lttng_ust_tracef:event (in tracepoint_register_lib() at tracepoint.c:772)
libust[XXX/XXX]: Provider "ust_pthread" accepted, version 1.0 is 
compatible with LTTng UST provider version 1.0. (in 
check_provider_version() at lttng-probes.c:174)
libust[XXX/XXX]: adding probe ust_pthread containing 4 events to lazy 
registration list (in lttng_probe_register() at lttng-probes.c:216)
libust[XXX/XXX]: just registered probe ust_pthread containing 4 events 
(in lttng_lazy_probe_register() at lttng-probes.c:115)
libust[XXX/XXX]: Sent register event notification for name 
"ust_pthread:pthread_mutex_lock_req": ret_code 0, event_id 4
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[XXX/XXX]: Sent register event notification for name 
"ust_pthread:pthread_mutex_lock_acq": ret_code 0, event_id 5
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[XXX/XXX]: Sent register event notification for name 
"ust_pthread:pthread_mutex_trylock": ret_code 0, event_id 6
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
libust[XXX/XXX]: Sent register event notification for name 
"ust_pthread:pthread_mutex_unlock": ret_code 0, event_id 7
  (in ustcomm_register_event() at lttng-ust-comm.c:1001)
liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
ust_pthread:pthread_mutex_unlock (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
ust_pthread:pthread_mutex_trylock (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
ust_pthread:pthread_mutex_lock_acq (in __tracepoint_probe_register() at 
tracepoint.c:563)
liblttng_ust_tracepoint[XXX/XXX]: Registering probe to tracepoint 
ust_pthread:pthread_mutex_lock_req (in __tracepoint_probe_register() at 
tracepoint.c:563)

As with this one, the first three lines of all registrations are always 
the same and do not match the following (in this case) 'Provider 
"ust_pthread" accepted'.
I subsequently only get tracepoint data from ust_baddr_statedump:soinfo.

I followed these build instructions for my board using Yocto 1.7: 
http://rocketboards.org/foswiki/view/Documentation/GSRD150CompilingLinux
I also tried updating the recipes to use the latest version of LTTng. 
The output above is from LTTng v2.6.2.
I can provide more debug output if that helps. I do not see this problem 
on my desktop computer.

Can somebody confirm this problem?

Thanks, Christian

^ permalink raw reply	[flat|nested] 3+ messages in thread

end of thread, other threads:[~2015-10-23 17:09 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
     [not found] <5627922E.9000808@techfak.uni-bielefeld.de>
2015-10-21 15:38 ` Problem LD_PRELOADing multiple UST helpers Jonathan Rajotte Julien
     [not found] ` <5627B163.5060407@efficios.com>
2015-10-23 17:09   ` Christian Ascheberg
2015-10-21 13:25 Christian Ascheberg

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.