[lttng-dev] traces omissions

[Mathieu Desnoyers]

* Sébastien Barthélémy (barthelemy at crans.org) wrote:
> Hello again,
> 
> 2012/1/25 Mathieu Desnoyers <compudj at krystal.dyndns.org>:
> > * Sébastien Barthélémy (barthelemy at crans.org) wrote:
> >> Hello all,
> >>
> >> I have yet another difficulty using LTTng.
> >>
> >> I run a program which dlopens a module (called DCM) which is
> >> instrumented with ust (provider == qi_dcm), and which calls functions
> >> from a processsyncclient library (PSC for short), also instrumented
> >> with ust (provider == qi_bn_ipc_psc).
> >>
> >> When I run the program, I ld_preload the two probes provider as in
> >>
> >> LD_PRELOAD="$PREFIX/lib/libtp_processsyncclient_pipe.so
> >> $PREFIX/lib/libtp_dcm.so" LD_LIBRARY_PATH=$PREFIX/lib
> >> $PREFIX/bin/naoqi-bin &
> >>
> >> This used to work, but when I run it now, I only get traces from the
> >> processsyncclient probes, not from the DCM ones. However, they are
> >> triggered by the same code paths, so I expect to get events from both
> >> of them.
> >>
> >> I checked that the probes are correctly registered:
> >>
> >> libust[3739/3739]: just registered probe qi_dcm containing 2 events
> >> (in ltt_probe_register() at ltt-probes.c:109)
> >> libust[3739/3739]: just registered probe qi_bn_ipc_psc containing 3
> >> events (in ltt_probe_register() at ltt-probes.c:109)
> >>
> >> and that I have symbols from both of them in the DCM module (so it not
> >> a simple #define error):
> >>
> >> $ nm libdcm_hal.so |grep _qi_
> >> 0005cab4 r _ZL26__tp_strtab_qi_dcm___state
> >> 0006c22c d _ZL31__tracepoint_ptr_qi_dcm___state
> >> 0005cad8 r _ZL35__tp_strtab_qi_bn_ipc_psc___waiting
> >> 0005cac1 r _ZL35__tp_strtab_qi_dcm___clock_realtime
> >> 0005cb0f r _ZL38__tp_strtab_qi_bn_ipc_psc___notify_end
> >> 0006c234 d _ZL40__tracepoint_ptr_qi_bn_ipc_psc___waiting
> >> 0006c230 d _ZL40__tracepoint_ptr_qi_dcm___clock_realtime
> >> 0006c23c d _ZL43__tracepoint_ptr_qi_bn_ipc_psc___notify_end
> >> 0005caf0 r _ZL44__tp_strtab_qi_bn_ipc_psc___finished_waiting
> >> 0006c238 d _ZL49__tracepoint_ptr_qi_bn_ipc_psc___finished_waiting
> >> 00040566 t __tracepoint_cb_qi_dcm___clock_realtime
> >> 000404c7 t __tracepoint_cb_qi_dcm___state
> >> 0006c214 D __tracepoint_qi_bn_ipc_psc___finished_waiting
> >> 0006c220 D __tracepoint_qi_bn_ipc_psc___notify_end
> >> 0006c208 D __tracepoint_qi_bn_ipc_psc___waiting
> >> 0006c1fc D __tracepoint_qi_dcm___clock_realtime
> >> 0006c1f0 D __tracepoint_qi_dcm___state
> >>
> >>
> >> I also get these messages (not sure what they mean):
> >>
> >> liblttng_ust_tracepoint[3739/3739]: just registered a tracepoints
> >> section from 0xb1fa1860 and having 1 tracepoints (in
> >> tracepoint_register_lib() at tracepoint.c:610)
> >> liblttng_ust_tracepoint[3739/3739]: just registered a tracepoints
> >> section from 0xb203822c and having 5 tracepoints (in
> >> tracepoint_register_lib() at tracepoint.c:610)
> >> liblttng_ust_tracepoint[3739/3739]: just registered a tracepoints
> >> section from 0xb04b06f4 and having 2 tracepoints (in
> >> tracepoint_register_lib() at tracepoint.c:610)
> >>
> >> Is this use case expected?
> >>
> >> I fear I'm running out of ideas, how could investigate the matter further?
> >
> > This rather sounds like an event name typo in create-event. Can you
> > provide the exact list of lttng commands you used ?
> 
> Sure, here is the script I run:
> 
> killall lttng-sessiond lttng-consumerd hal
> sleep 1
> rm -rf  ~/lttng-traces/*
> LTTNG_UST_DEBUG=1 lttng-sessiond -v&
> sleep 4
> lttng create
> lttng enable-channel mychan -u --subbuf-size 262144 --num-subbuf 8
> lttng enable-event -a -u -c mychan

In order to test the "-a -u" more thoroughly and see if it produces your
problem, you might want to add printf in:

ltt-events.c:pending_probe_fix_events()
in the loop that sits under the /* Wildcard */ comment.

and in

ltt-probes.c:add_wildcard()

I suspect that due to the way your librairies are loaded, the
"fix_events" might miss one.

Let me know how it goes,

Thanks!

Mathieu

> lttng start
> sleep 1
> PREFIX=~/naoqi
> P=$PREFIX/lib/probes/libtp_
> LTTNG_UST_DEBUG=1 LD_PRELOAD="${P}processsyncclient_pipe.so
> ${P}dcm.so" LD_LIBRARY_PATH=$PREFIX/lib $PREFIX/bin/naoqi-bin &
> sleep 20
> lttng -v stop
> killall naoqi-bin
> sleep 8
> lttng -v destroy
> sleep 4
> killall lttng-sessiond lttng-consumerd
> 
> 
> Here are the tracepoints too (found no typo)
> 
> $ grep tracepoint\( dcmthread.cpp
>       tracepoint(qi_dcm, state, 0);
>       tracepoint(qi_dcm, state, 1);
>       tracepoint(qi_dcm, clock_realtime, after.tv_sec, after.tv_nsec);
>       tracepoint(qi_dcm, state, 2);
>       tracepoint(qi_dcm, state, 3);
>       tracepoint(qi_dcm, state, 4);
>       tracepoint(qi_dcm, state, 5);
>       tracepoint(qi_dcm, state, 6);
>       tracepoint(qi_dcm, state, 7);
> 
> $ cat tp_dcm.in.h
> TRACEPOINT_EVENT(qi_dcm, state,
>         TP_ARGS(char, state),
>         TP_FIELDS(ctf_integer(char, state, state))
> )
> TRACEPOINT_EVENT(qi_dcm, clock_realtime,
>         TP_ARGS(unsigned long, tv_sec, unsigned long, tv_nsec),
>         TP_FIELDS(ctf_integer(unsigned long, tv_sec, tv_sec)
>                   ctf_integer(unsigned long, tv_nsec, tv_nsec))
> )
> 
> Cheers
> -- Sébastien
> 
> PS: I'm logged on IRC, feel free to ping me there if you prefer.
> 
> _______________________________________________
> 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