From mboxrd@z Thu Jan 1 00:00:00 1970 From: barthelemy@crans.org (=?ISO-8859-1?Q?S=E9bastien_Barth=E9l=E9my?=) Date: Thu, 26 Jan 2012 15:30:43 +0100 Subject: [lttng-dev] traces omissions In-Reply-To: <20120125144357.GB3754@Krystal> References: <20120125144357.GB3754@Krystal> Message-ID: Hello again, 2012/1/25 Mathieu Desnoyers : > * 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.