* [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