* [lttng-dev] [BUG] lttng-sessiond
@ 2015-04-23 10:04 Hannes Weisbach
2015-04-23 19:26 ` Mathieu Desnoyers
0 siblings, 1 reply; 8+ messages in thread
From: Hannes Weisbach @ 2015-04-23 10:04 UTC (permalink / raw)
Hello,
I'm using LTTng with a kernel that has lock debugging enabled. I
familiarized myself with LTTng using the "Hello world" example, where
I encountered two bugs.
1) Using multiple probes for the lttng-sessiond arguments
--kmod-probes and --extra-kmod-probes does not work:
$ sudo lttng-sessiond --kmod-probes="hello,sched" -vvv
[...]
DEBUG1 - 11:54:22.413830 [17827/17827]: Modprobe successfully lttng-probe-sched (in modprobe_lttng() at modprobe.c:285)
sh: 1: Syntax error: "(" unexpected
DEBUG1 - 11:54:22.415273 [17827/17827]: Unable to load optional module (null); continuing (in modprobe_lttng() at modprobe.c:281)
[...]
$ sudo lttng-sessiond --kmod-probes="sched,hello" -vvv
[...]
DEBUG1 - 11:55:13.879976 [17896/17896]: Modprobe successfully lttng-probe-hello (in modprobe_lttng() at modprobe.c:285)
sh: 1: Syntax error: "(" unexpected
DEBUG1 - 11:55:13.881183 [17896/17896]: Unable to load optional module (null); continuing (in modprobe_lttng() at modprobe.c:281)
[...]
$ sudo lttng-sessiond --extra-kmod-probes="sched,hello" -vvv
[...]
DEBUG1 - 11:55:54.244515 [17966/17966]: Modprobe successfully lttng-probe-hello (in modprobe_lttng() at modprobe.c:285)
sh: 1: Syntax error: "(" unexpected
DEBUG1 - 11:55:54.245758 [17966/17966]: Unable to load optional module (null); continuing (in modprobe_lttng() at modprobe.c:281)
[...]
It seems, only the last argument (module) is loaded correctly.
2) Having lttng-sessiond started:
$ sudo lttng-sessiond --kmod-probes=hello
And the tracer configured:
lttng create
lttng enable-event hello_world -k
'lttng start' causes a locking failure to be reported:
[ 159.783420]
[ 159.783922] =====================================
[ 159.784067] [ BUG: bad unlock balance detected! ]
[ 159.784067] 4.0.0-rc4-atlas+ #200 Tainted: G O
[ 159.784067] -------------------------------------
[ 159.784067] lttng-sessiond/1441 is trying to release lock (sessions_mutex) at:
[ 159.784067] [<ffffffff81808c3e>] mutex_unlock+0xe/0x10
[ 159.784067] but there are no more locks to release!
[ 159.784067]
[ 159.784067] other info that might help us debug this:
[ 159.784067] no locks held by lttng-sessiond/1441.
[ 159.784067]
[ 159.784067] stack backtrace:
[ 159.784067] CPU: 0 PID: 1441 Comm: lttng-sessiond Tainted: G O 4.0.0-rc4-atlas+ #200
[ 159.784067] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[ 159.784067] ffffffff81808c3e ffff88005d24fa28 ffffffff818029e0 0000000000000007
[ 159.784067] ffff880057c9cd60 ffff88005d24fa58 ffffffff810c1924 ffff88005d24fad8
[ 159.784067] ffff880057c9cd60 ffffffffa01ce070 ffffffff81808c3e ffff88005d24fa98
[ 159.784067] Call Trace:
[ 159.784067] [<ffffffff81808c3e>] ? mutex_unlock+0xe/0x10
[ 159.784067] [<ffffffff818029e0>] dump_stack+0x4c/0x65
[ 159.784067] [<ffffffff810c1924>] print_unlock_imbalance_bug+0xf4/0x100
[ 159.784067] [<ffffffff81808c3e>] ? mutex_unlock+0xe/0x10
[ 159.784067] [<ffffffff810c6986>] lock_release+0x2e6/0x460
[ 159.784067] [<ffffffff81808b16>] __mutex_unlock_slowpath+0x76/0x190
[ 159.784067] [<ffffffff81808c3e>] mutex_unlock+0xe/0x10
[ 159.784067] [<ffffffffa00bcc98>] lttng_session_enable+0x208/0x5b0 [lttng_tracer]
[ 159.784067] [<ffffffffa00bdd75>] lttng_session_ioctl+0x155/0x300 [lttng_tracer]
[ 159.784067] [<ffffffff810c3a80>] ? __lock_acquire+0x570/0x1f60
[ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90
[ 159.784067] [<ffffffff811d41c7>] ? do_wp_page+0x3a7/0x900
[ 159.784067] [<ffffffff8109d2d8>] ? sched_clock_cpu+0x98/0xc0
[ 159.784067] [<ffffffff8109d355>] ? local_clock+0x15/0x30
[ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90
[ 159.784067] [<ffffffff811d41c7>] ? do_wp_page+0x3a7/0x900
[ 159.784067] [<ffffffff810c3a80>] ? __lock_acquire+0x570/0x1f60
[ 159.784067] [<ffffffff811d41c7>] ? do_wp_page+0x3a7/0x900
[ 159.784067] [<ffffffff811d5820>] ? handle_mm_fault+0x310/0x18b0
[ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90
[ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90
[ 159.784067] [<ffffffff81248e41>] ? __fget+0x111/0x260
[ 159.784067] [<ffffffff8109d2d8>] ? sched_clock_cpu+0x98/0xc0
[ 159.784067] [<ffffffff8109d355>] ? local_clock+0x15/0x30
[ 159.784067] [<ffffffff81248e41>] ? __fget+0x111/0x260
[ 159.784067] [<ffffffff8123c998>] do_vfs_ioctl+0x308/0x560
[ 159.784067] [<ffffffff81248d35>] ? __fget+0x5/0x260
[ 159.784067] [<ffffffff8104f201>] ? __do_page_fault+0x1f1/0x4c0
[ 159.784067] [<ffffffff8123cc71>] SyS_ioctl+0x81/0xa0
[ 159.784067] [<ffffffff8180cfb6>] system_call_fastpath+0x16/0x1b
I hope this helps.
--
Best regards,
Hannes
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 203 bytes
Desc: Message signed with OpenPGP using GPGMail
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150423/014701e3/attachment-0001.sig>
^ permalink raw reply [flat|nested] 8+ messages in thread* [lttng-dev] [BUG] lttng-sessiond 2015-04-23 10:04 [lttng-dev] [BUG] lttng-sessiond Hannes Weisbach @ 2015-04-23 19:26 ` Mathieu Desnoyers 2015-04-23 20:13 ` Mathieu Desnoyers 0 siblings, 1 reply; 8+ messages in thread From: Mathieu Desnoyers @ 2015-04-23 19:26 UTC (permalink / raw) ----- Original Message ----- > Hello, > > I'm using LTTng with a kernel that has lock debugging enabled. I > familiarized myself with LTTng using the "Hello world" example, where > I encountered two bugs. Hi Hannes, Can you share with us the code of your "hello" probe ? Which version or git commit of lttng-modules are you using ? Thanks, Mathieu > > 1) Using multiple probes for the lttng-sessiond arguments > --kmod-probes and --extra-kmod-probes does not work: > > $ sudo lttng-sessiond --kmod-probes="hello,sched" -vvv > [...] > DEBUG1 - 11:54:22.413830 [17827/17827]: Modprobe successfully > lttng-probe-sched (in modprobe_lttng() at modprobe.c:285) > sh: 1: Syntax error: "(" unexpected > DEBUG1 - 11:54:22.415273 [17827/17827]: Unable to load optional module > (null); continuing (in modprobe_lttng() at modprobe.c:281) > [...] > > $ sudo lttng-sessiond --kmod-probes="sched,hello" -vvv > [...] > DEBUG1 - 11:55:13.879976 [17896/17896]: Modprobe successfully > lttng-probe-hello (in modprobe_lttng() at modprobe.c:285) > sh: 1: Syntax error: "(" unexpected > DEBUG1 - 11:55:13.881183 [17896/17896]: Unable to load optional module > (null); continuing (in modprobe_lttng() at modprobe.c:281) > [...] > > $ sudo lttng-sessiond --extra-kmod-probes="sched,hello" -vvv > [...] > DEBUG1 - 11:55:54.244515 [17966/17966]: Modprobe successfully > lttng-probe-hello (in modprobe_lttng() at modprobe.c:285) > sh: 1: Syntax error: "(" unexpected > DEBUG1 - 11:55:54.245758 [17966/17966]: Unable to load optional module > (null); continuing (in modprobe_lttng() at modprobe.c:281) > [...] > > It seems, only the last argument (module) is loaded correctly. > > 2) Having lttng-sessiond started: > $ sudo lttng-sessiond --kmod-probes=hello > And the tracer configured: > lttng create > lttng enable-event hello_world -k > > 'lttng start' causes a locking failure to be reported: > [ 159.783420] > [ 159.783922] ===================================== > [ 159.784067] [ BUG: bad unlock balance detected! ] > [ 159.784067] 4.0.0-rc4-atlas+ #200 Tainted: G O > [ 159.784067] ------------------------------------- > [ 159.784067] lttng-sessiond/1441 is trying to release lock (sessions_mutex) > at: > [ 159.784067] [<ffffffff81808c3e>] mutex_unlock+0xe/0x10 > [ 159.784067] but there are no more locks to release! > [ 159.784067] > [ 159.784067] other info that might help us debug this: > [ 159.784067] no locks held by lttng-sessiond/1441. > [ 159.784067] > [ 159.784067] stack backtrace: > [ 159.784067] CPU: 0 PID: 1441 Comm: lttng-sessiond Tainted: G O > 4.0.0-rc4-atlas+ #200 > [ 159.784067] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS > Bochs 01/01/2011 > [ 159.784067] ffffffff81808c3e ffff88005d24fa28 ffffffff818029e0 > 0000000000000007 > [ 159.784067] ffff880057c9cd60 ffff88005d24fa58 ffffffff810c1924 > ffff88005d24fad8 > [ 159.784067] ffff880057c9cd60 ffffffffa01ce070 ffffffff81808c3e > ffff88005d24fa98 > [ 159.784067] Call Trace: > [ 159.784067] [<ffffffff81808c3e>] ? mutex_unlock+0xe/0x10 > [ 159.784067] [<ffffffff818029e0>] dump_stack+0x4c/0x65 > [ 159.784067] [<ffffffff810c1924>] print_unlock_imbalance_bug+0xf4/0x100 > [ 159.784067] [<ffffffff81808c3e>] ? mutex_unlock+0xe/0x10 > [ 159.784067] [<ffffffff810c6986>] lock_release+0x2e6/0x460 > [ 159.784067] [<ffffffff81808b16>] __mutex_unlock_slowpath+0x76/0x190 > [ 159.784067] [<ffffffff81808c3e>] mutex_unlock+0xe/0x10 > [ 159.784067] [<ffffffffa00bcc98>] lttng_session_enable+0x208/0x5b0 > [lttng_tracer] > [ 159.784067] [<ffffffffa00bdd75>] lttng_session_ioctl+0x155/0x300 > [lttng_tracer] > [ 159.784067] [<ffffffff810c3a80>] ? __lock_acquire+0x570/0x1f60 > [ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90 > [ 159.784067] [<ffffffff811d41c7>] ? do_wp_page+0x3a7/0x900 > [ 159.784067] [<ffffffff8109d2d8>] ? sched_clock_cpu+0x98/0xc0 > [ 159.784067] [<ffffffff8109d355>] ? local_clock+0x15/0x30 > [ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90 > [ 159.784067] [<ffffffff811d41c7>] ? do_wp_page+0x3a7/0x900 > [ 159.784067] [<ffffffff810c3a80>] ? __lock_acquire+0x570/0x1f60 > [ 159.784067] [<ffffffff811d41c7>] ? do_wp_page+0x3a7/0x900 > [ 159.784067] [<ffffffff811d5820>] ? handle_mm_fault+0x310/0x18b0 > [ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90 > [ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90 > [ 159.784067] [<ffffffff81248e41>] ? __fget+0x111/0x260 > [ 159.784067] [<ffffffff8109d2d8>] ? sched_clock_cpu+0x98/0xc0 > [ 159.784067] [<ffffffff8109d355>] ? local_clock+0x15/0x30 > [ 159.784067] [<ffffffff81248e41>] ? __fget+0x111/0x260 > [ 159.784067] [<ffffffff8123c998>] do_vfs_ioctl+0x308/0x560 > [ 159.784067] [<ffffffff81248d35>] ? __fget+0x5/0x260 > [ 159.784067] [<ffffffff8104f201>] ? __do_page_fault+0x1f1/0x4c0 > [ 159.784067] [<ffffffff8123cc71>] SyS_ioctl+0x81/0xa0 > [ 159.784067] [<ffffffff8180cfb6>] system_call_fastpath+0x16/0x1b > > I hope this helps. > > -- > Best regards, > Hannes > > _______________________________________________ > lttng-dev mailing list > lttng-dev at lists.lttng.org > http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev > -- Mathieu Desnoyers EfficiOS Inc. http://www.efficios.com ^ permalink raw reply [flat|nested] 8+ messages in thread
* [lttng-dev] [BUG] lttng-sessiond 2015-04-23 19:26 ` Mathieu Desnoyers @ 2015-04-23 20:13 ` Mathieu Desnoyers 2015-04-24 9:52 ` Hannes Weisbach 0 siblings, 1 reply; 8+ messages in thread From: Mathieu Desnoyers @ 2015-04-23 20:13 UTC (permalink / raw) ----- Original Message ----- > ----- Original Message ----- > > Hello, > > > > I'm using LTTng with a kernel that has lock debugging enabled. I > > familiarized myself with LTTng using the "Hello world" example, where > > I encountered two bugs. > > Hi Hannes, > > Can you share with us the code of your "hello" probe ? > > Which version or git commit of lttng-modules are you > using ? I think the two issues should be fixed by this new git commit in lttng-modules master branch: commit 66fd8d5e4a6080f1b2db0f525c26c07e5b723aab Author: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> Date: Thu Apr 23 16:11:15 2015 -0400 Fix: double-unlock of session mutex Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> Can you give it a try ? Thanks! Mathieu > > Thanks, > > Mathieu > > > > > 1) Using multiple probes for the lttng-sessiond arguments > > --kmod-probes and --extra-kmod-probes does not work: > > > > $ sudo lttng-sessiond --kmod-probes="hello,sched" -vvv > > [...] > > DEBUG1 - 11:54:22.413830 [17827/17827]: Modprobe successfully > > lttng-probe-sched (in modprobe_lttng() at modprobe.c:285) > > sh: 1: Syntax error: "(" unexpected > > DEBUG1 - 11:54:22.415273 [17827/17827]: Unable to load optional module > > (null); continuing (in modprobe_lttng() at modprobe.c:281) > > [...] > > > > $ sudo lttng-sessiond --kmod-probes="sched,hello" -vvv > > [...] > > DEBUG1 - 11:55:13.879976 [17896/17896]: Modprobe successfully > > lttng-probe-hello (in modprobe_lttng() at modprobe.c:285) > > sh: 1: Syntax error: "(" unexpected > > DEBUG1 - 11:55:13.881183 [17896/17896]: Unable to load optional module > > (null); continuing (in modprobe_lttng() at modprobe.c:281) > > [...] > > > > $ sudo lttng-sessiond --extra-kmod-probes="sched,hello" -vvv > > [...] > > DEBUG1 - 11:55:54.244515 [17966/17966]: Modprobe successfully > > lttng-probe-hello (in modprobe_lttng() at modprobe.c:285) > > sh: 1: Syntax error: "(" unexpected > > DEBUG1 - 11:55:54.245758 [17966/17966]: Unable to load optional module > > (null); continuing (in modprobe_lttng() at modprobe.c:281) > > [...] > > > > It seems, only the last argument (module) is loaded correctly. > > > > 2) Having lttng-sessiond started: > > $ sudo lttng-sessiond --kmod-probes=hello > > And the tracer configured: > > lttng create > > lttng enable-event hello_world -k > > > > 'lttng start' causes a locking failure to be reported: > > [ 159.783420] > > [ 159.783922] ===================================== > > [ 159.784067] [ BUG: bad unlock balance detected! ] > > [ 159.784067] 4.0.0-rc4-atlas+ #200 Tainted: G O > > [ 159.784067] ------------------------------------- > > [ 159.784067] lttng-sessiond/1441 is trying to release lock > > (sessions_mutex) > > at: > > [ 159.784067] [<ffffffff81808c3e>] mutex_unlock+0xe/0x10 > > [ 159.784067] but there are no more locks to release! > > [ 159.784067] > > [ 159.784067] other info that might help us debug this: > > [ 159.784067] no locks held by lttng-sessiond/1441. > > [ 159.784067] > > [ 159.784067] stack backtrace: > > [ 159.784067] CPU: 0 PID: 1441 Comm: lttng-sessiond Tainted: G O > > 4.0.0-rc4-atlas+ #200 > > [ 159.784067] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS > > Bochs 01/01/2011 > > [ 159.784067] ffffffff81808c3e ffff88005d24fa28 ffffffff818029e0 > > 0000000000000007 > > [ 159.784067] ffff880057c9cd60 ffff88005d24fa58 ffffffff810c1924 > > ffff88005d24fad8 > > [ 159.784067] ffff880057c9cd60 ffffffffa01ce070 ffffffff81808c3e > > ffff88005d24fa98 > > [ 159.784067] Call Trace: > > [ 159.784067] [<ffffffff81808c3e>] ? mutex_unlock+0xe/0x10 > > [ 159.784067] [<ffffffff818029e0>] dump_stack+0x4c/0x65 > > [ 159.784067] [<ffffffff810c1924>] print_unlock_imbalance_bug+0xf4/0x100 > > [ 159.784067] [<ffffffff81808c3e>] ? mutex_unlock+0xe/0x10 > > [ 159.784067] [<ffffffff810c6986>] lock_release+0x2e6/0x460 > > [ 159.784067] [<ffffffff81808b16>] __mutex_unlock_slowpath+0x76/0x190 > > [ 159.784067] [<ffffffff81808c3e>] mutex_unlock+0xe/0x10 > > [ 159.784067] [<ffffffffa00bcc98>] lttng_session_enable+0x208/0x5b0 > > [lttng_tracer] > > [ 159.784067] [<ffffffffa00bdd75>] lttng_session_ioctl+0x155/0x300 > > [lttng_tracer] > > [ 159.784067] [<ffffffff810c3a80>] ? __lock_acquire+0x570/0x1f60 > > [ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90 > > [ 159.784067] [<ffffffff811d41c7>] ? do_wp_page+0x3a7/0x900 > > [ 159.784067] [<ffffffff8109d2d8>] ? sched_clock_cpu+0x98/0xc0 > > [ 159.784067] [<ffffffff8109d355>] ? local_clock+0x15/0x30 > > [ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90 > > [ 159.784067] [<ffffffff811d41c7>] ? do_wp_page+0x3a7/0x900 > > [ 159.784067] [<ffffffff810c3a80>] ? __lock_acquire+0x570/0x1f60 > > [ 159.784067] [<ffffffff811d41c7>] ? do_wp_page+0x3a7/0x900 > > [ 159.784067] [<ffffffff811d5820>] ? handle_mm_fault+0x310/0x18b0 > > [ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90 > > [ 159.784067] [<ffffffff8109d095>] ? sched_clock_local+0x25/0x90 > > [ 159.784067] [<ffffffff81248e41>] ? __fget+0x111/0x260 > > [ 159.784067] [<ffffffff8109d2d8>] ? sched_clock_cpu+0x98/0xc0 > > [ 159.784067] [<ffffffff8109d355>] ? local_clock+0x15/0x30 > > [ 159.784067] [<ffffffff81248e41>] ? __fget+0x111/0x260 > > [ 159.784067] [<ffffffff8123c998>] do_vfs_ioctl+0x308/0x560 > > [ 159.784067] [<ffffffff81248d35>] ? __fget+0x5/0x260 > > [ 159.784067] [<ffffffff8104f201>] ? __do_page_fault+0x1f1/0x4c0 > > [ 159.784067] [<ffffffff8123cc71>] SyS_ioctl+0x81/0xa0 > > [ 159.784067] [<ffffffff8180cfb6>] system_call_fastpath+0x16/0x1b > > > > I hope this helps. > > > > -- > > Best regards, > > Hannes > > > > _______________________________________________ > > lttng-dev mailing list > > lttng-dev at lists.lttng.org > > http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev > > > > -- > Mathieu Desnoyers > EfficiOS Inc. > http://www.efficios.com > > _______________________________________________ > lttng-dev mailing list > lttng-dev at lists.lttng.org > http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev > -- Mathieu Desnoyers EfficiOS Inc. http://www.efficios.com ^ permalink raw reply [flat|nested] 8+ messages in thread
* [lttng-dev] [BUG] lttng-sessiond 2015-04-23 20:13 ` Mathieu Desnoyers @ 2015-04-24 9:52 ` Hannes Weisbach 2015-04-24 18:32 ` Mathieu Desnoyers 0 siblings, 1 reply; 8+ messages in thread From: Hannes Weisbach @ 2015-04-24 9:52 UTC (permalink / raw) Hello, >> Can you share with us the code of your "hello" probe ? I used the example code from http://lttng.org/docs/#doc-instrumenting-linux-kernel-itself . >> Which version or git commit of lttng-modules are you >> using ? I used the current master of the github mirrors, specifically: lttng-tools: 94ffb05d6777efc0c40394d3df44a04feed92953 lttng-modules: d0558de29ca516e83b388b8028651f8b69288e4e lttng-ust: 4bc1ccd721114691c6f0dbd65335b3c43c9f895f > I think the two issues should be fixed by this new > git commit in lttng-modules master branch: > > commit 66fd8d5e4a6080f1b2db0f525c26c07e5b723aab > Author: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> > Date: Thu Apr 23 16:11:15 2015 -0400 > > Fix: double-unlock of session mutex > > Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> > > Can you give it a try ? Yes, the mutex error goes away. However, loading multiple probes with either --kmod-probes or --extra-kmod-probes still does not work: $ sudo lttng-sessiond -vvv --extra-kmod-probes=sched,napi [...] DEBUG1 - 11:42:18.492870 [5358/5358]: Modprobe successfully lttng-probe-napi (in modprobe_lttng() at modprobe.c:285) sh: 1: Syntax error: "(" unexpected DEBUG1 - 11:42:18.495037 [5358/5358]: Unable to load optional module (null); continuing (in modprobe_lttng() at modprobe.c:281) [...] Also, lttng-probe-regmap does not compile, but that might have to do with my kernel version of 4.0.0-rc4 (commit b314acaccd7e0d55314d96be4a33b5f50d0b3344 from https://github.com/torvalds/linux): lttng-modules$ make KERNELDIR=/usr/src/linux-4.0.0-rc4-atlas+ make -C /usr/src/linux-4.0.0-rc4-atlas+ M=/home/hannesweisbach/atlas/lttng-modules modules make[1]: Entering directory '/usr/src/linux-4.0.0-rc4-atlas+' CC [M] /home/hannesweisbach/atlas/lttng-modules/probes/lttng-probe-regmap.o In file included from /home/hannesweisbach/atlas/lttng-modules/probes/../instrumentation/events/lttng-module/../../../probes/define_trace.h:100:0, from /home/hannesweisbach/atlas/lttng-modules/probes/../instrumentation/events/lttng-module/regmap.h:278, from /home/hannesweisbach/atlas/lttng-modules/probes/lttng-probe-regmap.c:41: /home/hannesweisbach/atlas/lttng-modules/probes/../instrumentation/events/lttng-module/../../../probes/lttng-events.h:134:6: error: conflicting types for ?trace_regmap_reg_write? void trace_##_name(_proto); ^ /home/hannesweisbach/atlas/lttng-modules/probes/../instrumentation/events/lttng-module/../../../probes/lttng-events.h:99:2: note: in expansion of macro ?LTTNG_TRACEPOINT_EVENT_INSTANCE_MAP? LTTNG_TRACEPOINT_EVENT_INSTANCE_MAP(template, name, name, PARAMS(proto), PARAMS(args)) ^ /home/hannesweisbach/atlas/lttng-modules/probes/../instrumentation/events/lttng-module/../../../probes/../instrumentation/events/lttng-module/regmap.h:34:1: note: in expansion of macro ?LTTNG_TRACEPOINT_EVENT_INSTANCE? LTTNG_TRACEPOINT_EVENT_INSTANCE(regmap_reg, regmap_reg_write, ^ In file included from include/trace/events/regmap.h:8:0, from /home/hannesweisbach/atlas/lttng-modules/probes/lttng-probe-regmap.c:32: include/linux/tracepoint.h:169:21: note: previous definition of ?trace_regmap_reg_write? was here static inline void trace_##name(proto) \ ^ include/linux/tracepoint.h:325:3: note: in expansion of macro ?__DECLARE_TRACE? __DECLARE_TRACE(name, PARAMS(proto), PARAMS(args), 1, \ ^ include/linux/tracepoint.h:448:2: note: in expansion of macro ?DECLARE_TRACE? DECLARE_TRACE(name, PARAMS(proto), PARAMS(args)) ^ include/trace/events/regmap.h:40:1: note: in expansion of macro ?DEFINE_EVENT? DEFINE_EVENT(regmap_reg, regmap_reg_write, ^ [ and so on, and so on ? ] Since I don't need the regmap probe I simply disabled it in probes/Makefile. Unfortunately, I don't have time to debug it myself. If you want me to try another version, let me know. Best regards, Hannes -------------- next part -------------- A non-text attachment was scrubbed... Name: signature.asc Type: application/pgp-signature Size: 203 bytes Desc: Message signed with OpenPGP using GPGMail URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150424/81859d2d/attachment.sig> ^ permalink raw reply [flat|nested] 8+ messages in thread
* [lttng-dev] [BUG] lttng-sessiond 2015-04-24 9:52 ` Hannes Weisbach @ 2015-04-24 18:32 ` Mathieu Desnoyers 2015-04-25 14:13 ` Hannes Weisbach 2015-04-25 14:37 ` Hannes Weisbach 0 siblings, 2 replies; 8+ messages in thread From: Mathieu Desnoyers @ 2015-04-24 18:32 UTC (permalink / raw) ----- Original Message ----- > Hello, > > >> Can you share with us the code of your "hello" probe ? > I used the example code from > http://lttng.org/docs/#doc-instrumenting-linux-kernel-itself . > > >> Which version or git commit of lttng-modules are you > >> using ? > I used the current master of the github mirrors, specifically: > lttng-tools: 94ffb05d6777efc0c40394d3df44a04feed92953 > lttng-modules: d0558de29ca516e83b388b8028651f8b69288e4e > lttng-ust: 4bc1ccd721114691c6f0dbd65335b3c43c9f895f > > > I think the two issues should be fixed by this new > > git commit in lttng-modules master branch: > > > > commit 66fd8d5e4a6080f1b2db0f525c26c07e5b723aab > > Author: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> > > Date: Thu Apr 23 16:11:15 2015 -0400 > > > > Fix: double-unlock of session mutex > > > > Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> > > > > Can you give it a try ? > Yes, the mutex error goes away. Good! > However, loading multiple probes with > either --kmod-probes or --extra-kmod-probes still does not work: > $ sudo lttng-sessiond -vvv --extra-kmod-probes=sched,napi > [...] > DEBUG1 - 11:42:18.492870 [5358/5358]: Modprobe successfully lttng-probe-napi > (in modprobe_lttng() at modprobe.c:285) > sh: 1: Syntax error: "(" unexpected > DEBUG1 - 11:42:18.495037 [5358/5358]: Unable to load optional module (null); > continuing (in modprobe_lttng() at modprobe.c:281) > [...] Why do you need to load those explicitly ? They should be already loaded by default. I don't get those errors here. Which shell are you using (sh symlink) ? Can you reproduce using bash ? > > Also, lttng-probe-regmap does not compile, but that might have to do > with my kernel version of 4.0.0-rc4 (commit > b314acaccd7e0d55314d96be4a33b5f50d0b3344 from > https://github.com/torvalds/linux): > > lttng-modules$ make KERNELDIR=/usr/src/linux-4.0.0-rc4-atlas+ > make -C /usr/src/linux-4.0.0-rc4-atlas+ > M=/home/hannesweisbach/atlas/lttng-modules modules > make[1]: Entering directory '/usr/src/linux-4.0.0-rc4-atlas+' > CC [M] > /home/hannesweisbach/atlas/lttng-modules/probes/lttng-probe-regmap.o > In file included from > /home/hannesweisbach/atlas/lttng-modules/probes/../instrumentation/events/lttng-module/../../../probes/define_trace.h:100:0, > from > /home/hannesweisbach/atlas/lttng-modules/probes/../instrumentation/events/lttng-module/regmap.h:278, > from > /home/hannesweisbach/atlas/lttng-modules/probes/lttng-probe-regmap.c:41: > /home/hannesweisbach/atlas/lttng-modules/probes/../instrumentation/events/lttng-module/../../../probes/lttng-events.h:134:6: > error: conflicting types for ?trace_regmap_reg_write? > void trace_##_name(_proto); > ^ > /home/hannesweisbach/atlas/lttng-modules/probes/../instrumentation/events/lttng-module/../../../probes/lttng-events.h:99:2: > note: in expansion of macro ?LTTNG_TRACEPOINT_EVENT_INSTANCE_MAP? > LTTNG_TRACEPOINT_EVENT_INSTANCE_MAP(template, name, name, PARAMS(proto), > PARAMS(args)) > ^ > /home/hannesweisbach/atlas/lttng-modules/probes/../instrumentation/events/lttng-module/../../../probes/../instrumentation/events/lttng-module/regmap.h:34:1: > note: in expansion of macro ?LTTNG_TRACEPOINT_EVENT_INSTANCE? > LTTNG_TRACEPOINT_EVENT_INSTANCE(regmap_reg, regmap_reg_write, > ^ > In file included from include/trace/events/regmap.h:8:0, > from > /home/hannesweisbach/atlas/lttng-modules/probes/lttng-probe-regmap.c:32: > include/linux/tracepoint.h:169:21: note: previous definition of > ?trace_regmap_reg_write? was here > static inline void trace_##name(proto) \ > ^ > include/linux/tracepoint.h:325:3: note: in expansion of macro > ?__DECLARE_TRACE? > __DECLARE_TRACE(name, PARAMS(proto), PARAMS(args), 1, \ > ^ > include/linux/tracepoint.h:448:2: note: in expansion of macro ?DECLARE_TRACE? > DECLARE_TRACE(name, PARAMS(proto), PARAMS(args)) > ^ > include/trace/events/regmap.h:40:1: note: in expansion of macro > ?DEFINE_EVENT? > DEFINE_EVENT(regmap_reg, regmap_reg_write, > ^ > > [ and so on, and so on ? ] > > Since I don't need the regmap probe I simply disabled it in > probes/Makefile. Unfortunately, I don't have time to debug it myself. > If you want me to try another version, let me know. For regmap, you'll have to try with Linux 4.0 final, it works here. Thanks, Mathieu > > Best regards, > Hannes > > -- Mathieu Desnoyers EfficiOS Inc. http://www.efficios.com ^ permalink raw reply [flat|nested] 8+ messages in thread
* [lttng-dev] [BUG] lttng-sessiond 2015-04-24 18:32 ` Mathieu Desnoyers @ 2015-04-25 14:13 ` Hannes Weisbach 2015-04-25 14:37 ` Hannes Weisbach 1 sibling, 0 replies; 8+ messages in thread From: Hannes Weisbach @ 2015-04-25 14:13 UTC (permalink / raw) >> However, loading multiple probes with >> either --kmod-probes or --extra-kmod-probes still does not work: >> $ sudo lttng-sessiond -vvv --extra-kmod-probes=sched,napi >> [...] >> DEBUG1 - 11:42:18.492870 [5358/5358]: Modprobe successfully lttng-probe-napi >> (in modprobe_lttng() at modprobe.c:285) >> sh: 1: Syntax error: "(" unexpected >> DEBUG1 - 11:42:18.495037 [5358/5358]: Unable to load optional module (null); >> continuing (in modprobe_lttng() at modprobe.c:281) >> [...] > > Why do you need to load those explicitly ? They should be > already loaded by default. I don't get those errors here. I don't need them. They're just examples. Albeit they are loaded by default, using --kmod-probes or --extra-kmod-probes should work, no? > Which shell are you using (sh symlink) ? Can you reproduce > using bash ? I added a bit of debug output, namely the string that gets passed to system(): DBG("system(%s)", modprobe); Result: $ sudo lttng-sessiond -vvv --kmod-probes="sched,napi" [?] DEBUG1 - 16:02:21.372257 [4227/4227]: system(/sbin/modprobe -q lttng-probe-napi) (in modprobe_lttng() at modprobe.c:263) DEBUG1 - 16:02:21.381980 [4227/4227]: Modprobe successfully lttng-probe-napi (in modprobe_lttng() at modprobe.c:286) DEBUG1 - 16:02:21.382306 [4227/4227]: system(/sbin/modprobe -q (null)) (in modprobe_lttng() at modprobe.c:263) sh: 1: Syntax error: "(" unexpected DEBUG1 - 16:02:21.384942 [4227/4227]: Unable to load optional module (null); continuing (in modprobe_lttng() at modprobe.c:282) The problem is not with sh. It is that a NULL pointer is passed to snprintf in modprobe.c:254. My guess is, that splitting the argument of --kmod-probes and --extra-kmod-probes (probably using strtok) is somehow broken. If you can tell where in the source of lttng-sessiond argument parsing happens I can step through the code to see what is going on. Best regards, Hannes -------------- next part -------------- A non-text attachment was scrubbed... Name: signature.asc Type: application/pgp-signature Size: 203 bytes Desc: Message signed with OpenPGP using GPGMail URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150425/6d8a7685/attachment.sig> ^ permalink raw reply [flat|nested] 8+ messages in thread
* [lttng-dev] [BUG] lttng-sessiond 2015-04-24 18:32 ` Mathieu Desnoyers 2015-04-25 14:13 ` Hannes Weisbach @ 2015-04-25 14:37 ` Hannes Weisbach 2015-04-25 15:37 ` Mathieu Desnoyers 1 sibling, 1 reply; 8+ messages in thread From: Hannes Weisbach @ 2015-04-25 14:37 UTC (permalink / raw) > > Why do you need to load those explicitly ? They should be > already loaded by default. I don't get those errors here. > Which shell are you using (sh symlink) ? Can you reproduce > using bash ? Ok. Found the bug. In append_list_to_probes() index is used to get the current index into the probes array. However in the loop, index is never incremented. Therefore, the first entry of probes is overwritten, but nr_probes is incremented, and later those "empty" entries are referenced. There is also a memory leak in append_list_to_probes(): tmp_list = strdup(list); // uses malloc() next = strtok(tmp_list, ","); // tmp_list needs to be NULL except in the first iteration tmp_list = NULL; // so set it NULL free(tmp_list); // good intention, does not work. Best regards, Hannes -------------- next part -------------- A non-text attachment was scrubbed... Name: signature.asc Type: application/pgp-signature Size: 203 bytes Desc: Message signed with OpenPGP using GPGMail URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150425/3a0dfd04/attachment.sig> ^ permalink raw reply [flat|nested] 8+ messages in thread
* [lttng-dev] [BUG] lttng-sessiond 2015-04-25 14:37 ` Hannes Weisbach @ 2015-04-25 15:37 ` Mathieu Desnoyers 0 siblings, 0 replies; 8+ messages in thread From: Mathieu Desnoyers @ 2015-04-25 15:37 UTC (permalink / raw) ----- Original Message ----- > > > > Why do you need to load those explicitly ? They should be > > already loaded by default. I don't get those errors here. > > Which shell are you using (sh symlink) ? Can you reproduce > > using bash ? > Ok. Found the bug. In append_list_to_probes() index is used to get > the current index into the probes array. However in the loop, index > is never incremented. Therefore, the first entry of probes is > overwritten, but nr_probes is incremented, and later those "empty" > entries are referenced. > > There is also a memory leak in append_list_to_probes(): > > tmp_list = strdup(list); // uses malloc() > next = strtok(tmp_list, ","); // tmp_list needs to be NULL except in the > first iteration > tmp_list = NULL; // so set it NULL > free(tmp_list); // good intention, does not work. Thanks for spotting those issues! I'm CCing the author of this code. Mathieu > > Best regards, > Hannes > -- Mathieu Desnoyers EfficiOS Inc. http://www.efficios.com ^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2015-04-25 15:37 UTC | newest] Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2015-04-23 10:04 [lttng-dev] [BUG] lttng-sessiond Hannes Weisbach 2015-04-23 19:26 ` Mathieu Desnoyers 2015-04-23 20:13 ` Mathieu Desnoyers 2015-04-24 9:52 ` Hannes Weisbach 2015-04-24 18:32 ` Mathieu Desnoyers 2015-04-25 14:13 ` Hannes Weisbach 2015-04-25 14:37 ` Hannes Weisbach 2015-04-25 15:37 ` Mathieu Desnoyers
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox