From mboxrd@z Thu Jan 1 00:00:00 1970 From: compudj@krystal.dyndns.org (Mathieu Desnoyers) Date: Thu, 26 Jan 2012 15:30:32 -0500 Subject: [lttng-dev] traces omissions In-Reply-To: References: <20120125144357.GB3754@Krystal> Message-ID: <20120126203032.GA28714@Krystal> * S?bastien Barth?l?my (barthelemy at crans.org) wrote: > 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 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