[lttng-dev] traces omissions

[barthelemy@crans.org (Sébastien Barthélémy)]

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