WARNING: CPU: 0 PID: 8961 at kernel/trace/ftrace.c:1640 __ftrace_hash_rec_update.part.37+0x20a/0x240()
Modules linked in: bridge stp fuse hidp bnep rfcomm nfnetlink ipt_ULOG scsi_transport_iscsi can_bcm nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can_raw can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs libcrc32c snd_hda_codec_realtek snd_hda_intel snd_hda_codec pcspkr snd_hwdep usb_debug snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd e1000e ptp soundcore pps_core
CPU: 0 PID: 8961 Comm: trinity-child4 Not tainted 3.11.0-rc7+ #30
ffffffff81a21901 ffff880210039c60 ffffffff816f9e2f 0000000000000000
ffff880210039c98 ffffffff81052dcd 0000000000000000 0000000000000001
ffff8801cc5d2000 0000000000000000 ffff88022f357248 ffff880210039ca8
Call Trace:
[<ffffffff816f9e2f>] dump_stack+0x54/0x74
[<ffffffff81052dcd>] warn_slowpath_common+0x7d/0xa0
[<ffffffff81052eaa>] warn_slowpath_null+0x1a/0x20
[<ffffffff81115d1a>] __ftrace_hash_rec_update.part.37+0x20a/0x240
[<ffffffff81117e18>] ftrace_shutdown+0xb8/0x160
[<ffffffff811182a0>] unregister_ftrace_function+0x30/0x50
[<ffffffff81135e57>] perf_ftrace_event_register+0x87/0x130
[<ffffffff81135cdc>] perf_trace_destroy+0x2c/0x50
[<ffffffff8113df29>] tp_perf_event_destroy+0x9/0x10
[<ffffffff81140507>] free_event+0xa7/0x300
[<ffffffff811407c4>] perf_event_release_kernel+0x64/0x90
[<ffffffff811413c3>] put_event+0x133/0x1c0
[<ffffffff811412c0>] ? put_event+0x30/0x1c0
[<ffffffff81141460>] perf_release+0x10/0x20
[<ffffffff811b969a>] __fput+0xfa/0x2e0
[<ffffffff811b98ce>] ____fput+0xe/0x10
[<ffffffff8107a2fc>] task_work_run+0xac/0xe0
[<ffffffff8105469c>] do_exit+0x2cc/0xcd0
[<ffffffff8170cfc0>] ? ftrace_call+0x5/0x2f
[<ffffffff8105643c>] do_group_exit+0x4c/0xc0
[<ffffffff810564c4>] SyS_exit_group+0x14/0x20
[<ffffffff8170d594>] tracesys+0xdd/0xe2
---[ end trace e1bf4ddc241d086b ]---
1640 if (FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0))
1641 return;
On Tue, 27 Aug 2013 23:46:27 -0400
Dave Jones <[email protected]> wrote:
> WARNING: CPU: 0 PID: 8961 at kernel/trace/ftrace.c:1640 __ftrace_hash_rec_update.part.37+0x20a/0x240()
> Modules linked in: bridge stp fuse hidp bnep rfcomm nfnetlink ipt_ULOG scsi_transport_iscsi can_bcm nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can_raw can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs libcrc32c snd_hda_codec_realtek snd_hda_intel snd_hda_codec pcspkr snd_hwdep usb_debug snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd e1000e ptp soundcore pps_core
> CPU: 0 PID: 8961 Comm: trinity-child4 Not tainted 3.11.0-rc7+ #30
> ffffffff81a21901 ffff880210039c60 ffffffff816f9e2f 0000000000000000
> ffff880210039c98 ffffffff81052dcd 0000000000000000 0000000000000001
> ffff8801cc5d2000 0000000000000000 ffff88022f357248 ffff880210039ca8
> Call Trace:
> [<ffffffff816f9e2f>] dump_stack+0x54/0x74
> [<ffffffff81052dcd>] warn_slowpath_common+0x7d/0xa0
> [<ffffffff81052eaa>] warn_slowpath_null+0x1a/0x20
> [<ffffffff81115d1a>] __ftrace_hash_rec_update.part.37+0x20a/0x240
> [<ffffffff81117e18>] ftrace_shutdown+0xb8/0x160
OK, this is a hint. The __unregister_ftrace_function returned an error
code, and called ftrace_shutdown(). This is an error path that is not
tested much. So perhaps you did find another place that can cause the
accounting to get out of sync.
I'll investigate this.
Thanks!
-- Steve
> [<ffffffff811182a0>] unregister_ftrace_function+0x30/0x50
> [<ffffffff81135e57>] perf_ftrace_event_register+0x87/0x130
> [<ffffffff81135cdc>] perf_trace_destroy+0x2c/0x50
> [<ffffffff8113df29>] tp_perf_event_destroy+0x9/0x10
> [<ffffffff81140507>] free_event+0xa7/0x300
> [<ffffffff811407c4>] perf_event_release_kernel+0x64/0x90
> [<ffffffff811413c3>] put_event+0x133/0x1c0
> [<ffffffff811412c0>] ? put_event+0x30/0x1c0
> [<ffffffff81141460>] perf_release+0x10/0x20
> [<ffffffff811b969a>] __fput+0xfa/0x2e0
> [<ffffffff811b98ce>] ____fput+0xe/0x10
> [<ffffffff8107a2fc>] task_work_run+0xac/0xe0
> [<ffffffff8105469c>] do_exit+0x2cc/0xcd0
> [<ffffffff8170cfc0>] ? ftrace_call+0x5/0x2f
> [<ffffffff8105643c>] do_group_exit+0x4c/0xc0
> [<ffffffff810564c4>] SyS_exit_group+0x14/0x20
> [<ffffffff8170d594>] tracesys+0xdd/0xe2
> ---[ end trace e1bf4ddc241d086b ]---
>
>
> 1640 if (FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0))
> 1641 return;
>
On Wed, 28 Aug 2013 09:54:08 -0400
Steven Rostedt <[email protected]> wrote:
>
> OK, this is a hint. The __unregister_ftrace_function returned an error
> code, and called ftrace_shutdown(). This is an error path that is not
> tested much. So perhaps you did find another place that can cause the
> accounting to get out of sync.
I'll take that back. The ftrace_shutdown() is called on success, thus
this is a normal path. I have to find out what perf is doing. Do you
have any clue to what calls are being made to perf?
-- Steve
Dave,
BTW, is there a way to run trinity on a subset of syscalls. Basically,
I would like to run it on just the perf code, and nothing else. I have
a feeling that the bug you see is not caused by other operations
happening (although it could be), but from just out of order perf
calls. If I can reproduce it, I'll have a much better way of debugging
this.
Perhaps another thing you may think of adding to trinity (if it doesn't
already exist), is a log of what it is doing. That is, to log somewhere
the commands it writes, and that way, if something goes wrong, you have
a clue to how it got there. Because this is one of those bugs that
triggered before the code crashes, and the crash is just the symptom of
what went wrong and does not give you much clue to how it happened.
-- Steve
On Wed, 28 Aug 2013 09:58:33 -0400
Steven Rostedt <[email protected]> wrote:
> I'll take that back. The ftrace_shutdown() is called on success, thus
> this is a normal path. I have to find out what perf is doing. Do you
> have any clue to what calls are being made to perf?
This may be the error path that is taken that causes things to get off
whack.
Dave, can you add this patch to your kernels you test, and that way,
the next time you hit this error, I want to see if this warning was
triggered too.
If we did not unregister the ftrace ops but free the filters, it will
cause the accounting to get out of whack.
Thanks!
-- Steve
diff --git a/kernel/trace/trace_event_perf.c b/kernel/trace/trace_event_perf.c
index 80c36bc..05167bb 100644
--- a/kernel/trace/trace_event_perf.c
+++ b/kernel/trace/trace_event_perf.c
@@ -306,6 +306,7 @@ static int perf_ftrace_function_unregister(struct perf_event *event)
{
struct ftrace_ops *ops = &event->ftrace_ops;
int ret = unregister_ftrace_function(ops);
+ WARN_ON(ret);
ftrace_free_filter(ops);
return ret;
}
On Wed, Aug 28, 2013 at 10:31:01AM -0400, Steven Rostedt wrote:
> Dave,
>
> BTW, is there a way to run trinity on a subset of syscalls. Basically,
> I would like to run it on just the perf code, and nothing else. I have
> a feeling that the bug you see is not caused by other operations
> happening (although it could be), but from just out of order perf
> calls. If I can reproduce it, I'll have a much better way of debugging
> this.
indeed. -c perf_open_event for eg. (You can also specify multiple -c's
if you want to thow in some others)
There's a few other options in there for narrowing things down.
Say you think it's an interaction between perf and and unknown other syscall
for eg, you can do -c perf_open_event -r5. This will pick 5 random
syscalls, and fuzz those plus perf. See scripts/find.sh for an example of
how I've used this in the past.
> Perhaps another thing you may think of adding to trinity (if it doesn't
> already exist), is a log of what it is doing. That is, to log somewhere
> the commands it writes, and that way, if something goes wrong, you have
> a clue to how it got there. Because this is one of those bugs that
> triggered before the code crashes, and the crash is just the symptom of
> what went wrong and does not give you much clue to how it happened.
It does have logging already, though for a bug that takes hours, or days to
hit, they can grow to unmanagable sizes, and there's a problem if we have
a situation like..
syscall A
<24 hours of boring syscalls>
syscall B
oops as a result of B's interaction with A.
Quite often just rerunning that last syscall that caused the oops/warn
isn't sufficient to trigger an issue. (Though it may be for this specific
bug that may not be the case..)
Vince has a variant of trinity focussed just on perf which also has some
neat replay/bisecting capabilities to narrow down test cases.
I think I might need to add something like that at some point.
Dave
On Wed, 28 Aug 2013, Dave Jones wrote:
> Quite often just rerunning that last syscall that caused the oops/warn
> isn't sufficient to trigger an issue. (Though it may be for this specific
> bug that may not be the case..)
>
> Vince has a variant of trinity focussed just on perf which also has some
> neat replay/bisecting capabilities to narrow down test cases.
> I think I might need to add something like that at some point.
Yes, you can get the perf_fuzzer code here:
git clone https://github.com/deater/perf_event_tests.git
in the fuzzer directory
Bisecting down which perf_event_open() call causes problems is still very
labor intensive even with the other tools I've added to help. Even if the
bug is triggered right away (within the first 100,000 calls or so) it can
take hours to narrow things down to the two or three syscalls needed to
reproduce the problem. Especially if you need to reboot after triggering
the issue.
Vince
On Wed, 28 Aug 2013 12:50:36 -0400 (EDT)
Vince Weaver <[email protected]> wrote:
> On Wed, 28 Aug 2013, Dave Jones wrote:
> > Quite often just rerunning that last syscall that caused the oops/warn
> > isn't sufficient to trigger an issue. (Though it may be for this specific
> > bug that may not be the case..)
> >
> > Vince has a variant of trinity focussed just on perf which also has some
> > neat replay/bisecting capabilities to narrow down test cases.
> > I think I might need to add something like that at some point.
>
> Yes, you can get the perf_fuzzer code here:
> git clone https://github.com/deater/perf_event_tests.git
> in the fuzzer directory
>
> Bisecting down which perf_event_open() call causes problems is still very
> labor intensive even with the other tools I've added to help. Even if the
> bug is triggered right away (within the first 100,000 calls or so) it can
> take hours to narrow things down to the two or three syscalls needed to
> reproduce the problem. Especially if you need to reboot after triggering
> the issue.
Note, I have an idea that it's not even that many perf calls. I have a
good idea what perf syscalls with what options are the issue. I think
the issue is the calling order that is the problem.
Dave, I'm assuming that trinidy does things as threads, such that it
may be two threads calling perf with the same descriptor, and if we
don't have the proper locks, things can get bad, right?
-- Steve
On Wed, Aug 28, 2013 at 12:57:01PM -0400, Steven Rostedt wrote:
> Dave, I'm assuming that trinidy does things as threads, such that it
> may be two threads calling perf with the same descriptor, and if we
> don't have the proper locks, things can get bad, right?
>
close. It does use as many processes as there are cpus (unless you override with -C)
but the fd's created by perf_event_open were only being used within the thread
that created them. I just committed code to make it also reuse some shared ones
created from the parent process.
Dave
On Wed, Aug 28, 2013 at 11:17:46AM -0400, Steven Rostedt wrote:
> Dave, can you add this patch to your kernels you test, and that way,
> the next time you hit this error, I want to see if this warning was
> triggered too.
>
> If we did not unregister the ftrace ops but free the filters, it will
> cause the accounting to get out of whack.
>
> Thanks!
>
> -- Steve
>
> diff --git a/kernel/trace/trace_event_perf.c b/kernel/trace/trace_event_perf.c
> index 80c36bc..05167bb 100644
> --- a/kernel/trace/trace_event_perf.c
> +++ b/kernel/trace/trace_event_perf.c
> @@ -306,6 +306,7 @@ static int perf_ftrace_function_unregister(struct perf_event *event)
> {
> struct ftrace_ops *ops = &event->ftrace_ops;
> int ret = unregister_ftrace_function(ops);
> + WARN_ON(ret);
> ftrace_free_filter(ops);
> return ret;
> }
I hit the WARN in the subject, and then this new one immediately afterwards.
Dave.
On Wed, Aug 28, 2013 at 02:27:10PM -0400, Dave Jones wrote:
> On Wed, Aug 28, 2013 at 11:17:46AM -0400, Steven Rostedt wrote:
>
> > Dave, can you add this patch to your kernels you test, and that way,
> > the next time you hit this error, I want to see if this warning was
> > triggered too.
> >
> > If we did not unregister the ftrace ops but free the filters, it will
> > cause the accounting to get out of whack.
> >
> > Thanks!
> >
> > -- Steve
> >
> > diff --git a/kernel/trace/trace_event_perf.c b/kernel/trace/trace_event_perf.c
> > index 80c36bc..05167bb 100644
> > --- a/kernel/trace/trace_event_perf.c
> > +++ b/kernel/trace/trace_event_perf.c
> > @@ -306,6 +306,7 @@ static int perf_ftrace_function_unregister(struct perf_event *event)
> > {
> > struct ftrace_ops *ops = &event->ftrace_ops;
> > int ret = unregister_ftrace_function(ops);
> > + WARN_ON(ret);
> > ftrace_free_filter(ops);
> > return ret;
> > }
>
> I hit the WARN in the subject, and then this new one immediately afterwards.
actually looking closer..
[ 6619.050768] WARNING: CPU: 1 PID: 16351 at kernel/trace/ftrace.c:1640 __ftrace_hash_rec_update.part.37+0x20a/0x240()
[ 6619.053767] Modules linked in: lec snd_seq_dummy bridge stp fuse tun bnep hidp rfcomm nfnetlink ipt_ULOG scsi_transport_iscsi can_bcm can_raw nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs libcrc32c snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc e1000e ptp snd_timer pcspkr pps_core snd soundcore usb_debug
[ 6619.060523] CPU: 1 PID: 16351 Comm: trinity-child2 Not tainted 3.11.0-rc7+ #31
[ 6619.062161] ffffffff81a21901 ffff8802267b9ce0 ffffffff816f9e4f 0000000000000000
[ 6619.063733] ffff8802267b9d18 ffffffff81052dcd 0000000000000000 0000000000000001
[ 6619.065309] ffff8802203a3000 0000000000000000 ffff880225e962d0 ffff8802267b9d28
[ 6619.066895] Call Trace:
[ 6619.068437] [<ffffffff816f9e4f>] dump_stack+0x54/0x74
[ 6619.070046] [<ffffffff81052dcd>] warn_slowpath_common+0x7d/0xa0
[ 6619.071642] [<ffffffff81052eaa>] warn_slowpath_null+0x1a/0x20
[ 6619.073224] [<ffffffff81115d1a>] __ftrace_hash_rec_update.part.37+0x20a/0x240
[ 6619.074817] [<ffffffff81117e18>] ftrace_shutdown+0xb8/0x160
[ 6619.076399] [<ffffffff811182a0>] unregister_ftrace_function+0x30/0x50
[ 6619.077983] [<ffffffff81135e57>] perf_ftrace_event_register+0x87/0x150
[ 6619.079565] [<ffffffff81135cdc>] perf_trace_destroy+0x2c/0x50
[ 6619.081180] [<ffffffff8113df49>] tp_perf_event_destroy+0x9/0x10
[ 6619.082742] [<ffffffff81140527>] free_event+0xa7/0x300
[ 6619.084264] [<ffffffff81141620>] __perf_event_exit_task+0xe0/0x130
[ 6619.085792] [<ffffffff8114a491>] perf_event_exit_task+0x1f1/0x230
[ 6619.087329] [<ffffffff810546dd>] do_exit+0x30d/0xcd0
[ 6619.088860] [<ffffffff8170cfc0>] ? ftrace_call+0x5/0x2f
[ 6619.090460] [<ffffffff8105643c>] do_group_exit+0x4c/0xc0
[ 6619.092036] [<ffffffff810564c4>] SyS_exit_group+0x14/0x20
[ 6619.093614] [<ffffffff8170d594>] tracesys+0xdd/0xe2
[ 6620.015243] ------------[ cut here ]------------
[ 6620.018093] WARNING: CPU: 3 PID: 17998 at kernel/trace/trace_event_perf.c:309 perf_ftrace_event_register+0x13f/0x150()
[ 6620.022809] Modules linked in: lec snd_seq_dummy bridge stp fuse tun bnep hidp rfcomm nfnetlink ipt_ULOG scsi_transport_iscsi can_bcm can_raw nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs libcrc32c snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc e1000e ptp snd_timer pcspkr pps_core snd soundcore usb_debug
[ 6620.029752] CPU: 3 PID: 17998 Comm: trinity-child3 Tainted: G W 3.11.0-rc7+ #31
[ 6620.033043] ffffffff81a185c0 ffff8801e80b1d78 ffffffff816f9e4f 0000000000000000
[ 6620.034676] ffff8801e80b1db0 ffffffff81052dcd ffff8801f308f3b8 00000000ffffffed
[ 6620.036314] ffff8801f308f1e0 ffff8802266d01d8 0000000000000001 ffff8801e80b1dc0
[ 6620.038041] Call Trace:
[ 6620.039743] [<ffffffff816f9e4f>] dump_stack+0x54/0x74
[ 6620.041430] [<ffffffff81052dcd>] warn_slowpath_common+0x7d/0xa0
[ 6620.043131] [<ffffffff81052eaa>] warn_slowpath_null+0x1a/0x20
[ 6620.044810] [<ffffffff81135f0f>] perf_ftrace_event_register+0x13f/0x150
[ 6620.046492] [<ffffffff81135cdc>] perf_trace_destroy+0x2c/0x50
[ 6620.048168] [<ffffffff8113df49>] tp_perf_event_destroy+0x9/0x10
[ 6620.049876] [<ffffffff81140527>] free_event+0xa7/0x300
[ 6620.051545] [<ffffffff81141620>] __perf_event_exit_task+0xe0/0x130
[ 6620.053204] [<ffffffff8114a491>] perf_event_exit_task+0x1f1/0x230
[ 6620.054852] [<ffffffff810546dd>] do_exit+0x30d/0xcd0
[ 6620.056482] [<ffffffff8170cfc0>] ? ftrace_call+0x5/0x2f
[ 6620.058098] [<ffffffff8105643c>] do_group_exit+0x4c/0xc0
[ 6620.059739] [<ffffffff810564c4>] SyS_exit_group+0x14/0x20
[ 6620.061348] [<ffffffff8170d594>] tracesys+0xdd/0xe2
[ 6620.062955] ---[ end trace c7d2bbab21000c60 ]---
note how they're different CPUs & pids. Relevant ?
Dave
On Wed, 28 Aug 2013 14:29:02 -0400
> > >
> > > diff --git a/kernel/trace/trace_event_perf.c b/kernel/trace/trace_event_perf.c
> > > index 80c36bc..05167bb 100644
> > > --- a/kernel/trace/trace_event_perf.c
> > > +++ b/kernel/trace/trace_event_perf.c
> > > @@ -306,6 +306,7 @@ static int perf_ftrace_function_unregister(struct perf_event *event)
> > > {
> > > struct ftrace_ops *ops = &event->ftrace_ops;
> > > int ret = unregister_ftrace_function(ops);
> > > + WARN_ON(ret);
> > > ftrace_free_filter(ops);
> > > return ret;
> > > }
> >
> > I hit the WARN in the subject, and then this new one immediately afterwards.
Grumble. Then what I thought it might be, it isn't.
>
> actually looking closer..
>
> [ 6619.050768] WARNING: CPU: 1 PID: 16351 at kernel/trace/ftrace.c:1640 __ftrace_hash_rec_update.part.37+0x20a/0x240()
> [ 6619.053767] Modules linked in: lec snd_seq_dummy bridge stp fuse tun bnep hidp rfcomm nfnetlink ipt_ULOG scsi_transport_iscsi can_bcm can_raw nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs libcrc32c snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc e1000e ptp snd_timer pcspkr pps_core snd soundcore usb_debug
> [ 6619.060523] CPU: 1 PID: 16351 Comm: trinity-child2 Not tainted 3.11.0-rc7+ #31
> [ 6619.062161] ffffffff81a21901 ffff8802267b9ce0 ffffffff816f9e4f 0000000000000000
> [ 6619.063733] ffff8802267b9d18 ffffffff81052dcd 0000000000000000 0000000000000001
> [ 6619.065309] ffff8802203a3000 0000000000000000 ffff880225e962d0 ffff8802267b9d28
> [ 6619.066895] Call Trace:
> [ 6619.068437] [<ffffffff816f9e4f>] dump_stack+0x54/0x74
> [ 6619.070046] [<ffffffff81052dcd>] warn_slowpath_common+0x7d/0xa0
> [ 6619.071642] [<ffffffff81052eaa>] warn_slowpath_null+0x1a/0x20
> [ 6619.073224] [<ffffffff81115d1a>] __ftrace_hash_rec_update.part.37+0x20a/0x240
> [ 6619.074817] [<ffffffff81117e18>] ftrace_shutdown+0xb8/0x160
> [ 6619.076399] [<ffffffff811182a0>] unregister_ftrace_function+0x30/0x50
> [ 6619.077983] [<ffffffff81135e57>] perf_ftrace_event_register+0x87/0x150
> [ 6619.079565] [<ffffffff81135cdc>] perf_trace_destroy+0x2c/0x50
> [ 6619.081180] [<ffffffff8113df49>] tp_perf_event_destroy+0x9/0x10
> [ 6619.082742] [<ffffffff81140527>] free_event+0xa7/0x300
> [ 6619.084264] [<ffffffff81141620>] __perf_event_exit_task+0xe0/0x130
> [ 6619.085792] [<ffffffff8114a491>] perf_event_exit_task+0x1f1/0x230
> [ 6619.087329] [<ffffffff810546dd>] do_exit+0x30d/0xcd0
> [ 6619.088860] [<ffffffff8170cfc0>] ? ftrace_call+0x5/0x2f
> [ 6619.090460] [<ffffffff8105643c>] do_group_exit+0x4c/0xc0
> [ 6619.092036] [<ffffffff810564c4>] SyS_exit_group+0x14/0x20
> [ 6619.093614] [<ffffffff8170d594>] tracesys+0xdd/0xe2
>
> [ 6620.015243] ------------[ cut here ]------------
> [ 6620.018093] WARNING: CPU: 3 PID: 17998 at kernel/trace/trace_event_perf.c:309 perf_ftrace_event_register+0x13f/0x150()
> [ 6620.022809] Modules linked in: lec snd_seq_dummy bridge stp fuse tun bnep hidp rfcomm nfnetlink ipt_ULOG scsi_transport_iscsi can_bcm can_raw nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs libcrc32c snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc e1000e ptp snd_timer pcspkr pps_core snd soundcore usb_debug
> [ 6620.029752] CPU: 3 PID: 17998 Comm: trinity-child3 Tainted: G W 3.11.0-rc7+ #31
> [ 6620.033043] ffffffff81a185c0 ffff8801e80b1d78 ffffffff816f9e4f 0000000000000000
> [ 6620.034676] ffff8801e80b1db0 ffffffff81052dcd ffff8801f308f3b8 00000000ffffffed
> [ 6620.036314] ffff8801f308f1e0 ffff8802266d01d8 0000000000000001 ffff8801e80b1dc0
> [ 6620.038041] Call Trace:
> [ 6620.039743] [<ffffffff816f9e4f>] dump_stack+0x54/0x74
> [ 6620.041430] [<ffffffff81052dcd>] warn_slowpath_common+0x7d/0xa0
> [ 6620.043131] [<ffffffff81052eaa>] warn_slowpath_null+0x1a/0x20
> [ 6620.044810] [<ffffffff81135f0f>] perf_ftrace_event_register+0x13f/0x150
> [ 6620.046492] [<ffffffff81135cdc>] perf_trace_destroy+0x2c/0x50
> [ 6620.048168] [<ffffffff8113df49>] tp_perf_event_destroy+0x9/0x10
> [ 6620.049876] [<ffffffff81140527>] free_event+0xa7/0x300
> [ 6620.051545] [<ffffffff81141620>] __perf_event_exit_task+0xe0/0x130
> [ 6620.053204] [<ffffffff8114a491>] perf_event_exit_task+0x1f1/0x230
> [ 6620.054852] [<ffffffff810546dd>] do_exit+0x30d/0xcd0
> [ 6620.056482] [<ffffffff8170cfc0>] ? ftrace_call+0x5/0x2f
> [ 6620.058098] [<ffffffff8105643c>] do_group_exit+0x4c/0xc0
> [ 6620.059739] [<ffffffff810564c4>] SyS_exit_group+0x14/0x20
> [ 6620.061348] [<ffffffff8170d594>] tracesys+0xdd/0xe2
> [ 6620.062955] ---[ end trace c7d2bbab21000c60 ]---
>
> note how they're different CPUs & pids. Relevant ?
Unfortunately no.
The first failure disables function tracing completely, which is one of
the causes to return an error, which triggered the warning I added.
I was hoping that it failed for another reason and then that would
cause things to break. But you said the hash corruption happened first
(the original bug), so that's not the case.
Back to staring at code.
Thanks,
-- Steve
On Wed, Aug 28, 2013 at 03:27:45PM -0400, Steven Rostedt wrote:
> > [ 6619.050768] WARNING: CPU: 1 PID: 16351 at kernel/trace/ftrace.c:1640 __ftrace_hash_rec_update.part.37+0x20a/0x240()
> > [ 6619.053767] Modules linked in: lec snd_seq_dummy bridge stp fuse tun bnep hidp rfcomm nfnetlink ipt_ULOG scsi_transport_iscsi can_bcm can_raw nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs libcrc32c snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc e1000e ptp snd_timer pcspkr pps_core snd soundcore usb_debug
> > [ 6619.060523] CPU: 1 PID: 16351 Comm: trinity-child2 Not tainted 3.11.0-rc7+ #31
> > [ 6619.062161] ffffffff81a21901 ffff8802267b9ce0 ffffffff816f9e4f 0000000000000000
> > [ 6619.063733] ffff8802267b9d18 ffffffff81052dcd 0000000000000000 0000000000000001
> > [ 6619.065309] ffff8802203a3000 0000000000000000 ffff880225e962d0 ffff8802267b9d28
> > [ 6619.066895] Call Trace:
> > [ 6619.068437] [<ffffffff816f9e4f>] dump_stack+0x54/0x74
> > [ 6619.070046] [<ffffffff81052dcd>] warn_slowpath_common+0x7d/0xa0
> > [ 6619.071642] [<ffffffff81052eaa>] warn_slowpath_null+0x1a/0x20
> > [ 6619.073224] [<ffffffff81115d1a>] __ftrace_hash_rec_update.part.37+0x20a/0x240
> > [ 6619.074817] [<ffffffff81117e18>] ftrace_shutdown+0xb8/0x160
> > [ 6619.076399] [<ffffffff811182a0>] unregister_ftrace_function+0x30/0x50
> > [ 6619.077983] [<ffffffff81135e57>] perf_ftrace_event_register+0x87/0x150
> > [ 6619.079565] [<ffffffff81135cdc>] perf_trace_destroy+0x2c/0x50
> > [ 6619.081180] [<ffffffff8113df49>] tp_perf_event_destroy+0x9/0x10
> > [ 6619.082742] [<ffffffff81140527>] free_event+0xa7/0x300
> > [ 6619.084264] [<ffffffff81141620>] __perf_event_exit_task+0xe0/0x130
> > [ 6619.085792] [<ffffffff8114a491>] perf_event_exit_task+0x1f1/0x230
> > [ 6619.087329] [<ffffffff810546dd>] do_exit+0x30d/0xcd0
> > [ 6619.088860] [<ffffffff8170cfc0>] ? ftrace_call+0x5/0x2f
> > [ 6619.090460] [<ffffffff8105643c>] do_group_exit+0x4c/0xc0
> > [ 6619.092036] [<ffffffff810564c4>] SyS_exit_group+0x14/0x20
> > [ 6619.093614] [<ffffffff8170d594>] tracesys+0xdd/0xe2
>
> The first failure disables function tracing completely, which is one of
> the causes to return an error, which triggered the warning I added.
>
> I was hoping that it failed for another reason and then that would
> cause things to break. But you said the hash corruption happened first
> (the original bug), so that's not the case.
>
> Back to staring at code.
Steve, any further thoughts on this ? I can't do more than a few hours of fuzz-testing
without eventually running into this.
Dave
On Mon, 2013-09-30 at 13:12 -0400, Dave Jones wrote:
> On Wed, Aug 28, 2013 at 03:27:45PM -0400, Steven Rostedt wrote:
>
> > > [ 6619.050768] WARNING: CPU: 1 PID: 16351 at kernel/trace/ftrace.c:1640 __ftrace_hash_rec_update.part.37+0x20a/0x240()
> > > [ 6619.053767] Modules linked in: lec snd_seq_dummy bridge stp fuse tun bnep hidp rfcomm nfnetlink ipt_ULOG scsi_transport_iscsi can_bcm can_raw nfc caif_socket caif af_802154 phonet af_rxrpc bluetooth rfkill can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 xfs libcrc32c snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc e1000e ptp snd_timer pcspkr pps_core snd soundcore usb_debug
> > > [ 6619.060523] CPU: 1 PID: 16351 Comm: trinity-child2 Not tainted 3.11.0-rc7+ #31
> > > [ 6619.062161] ffffffff81a21901 ffff8802267b9ce0 ffffffff816f9e4f 0000000000000000
> > > [ 6619.063733] ffff8802267b9d18 ffffffff81052dcd 0000000000000000 0000000000000001
> > > [ 6619.065309] ffff8802203a3000 0000000000000000 ffff880225e962d0 ffff8802267b9d28
> > > [ 6619.066895] Call Trace:
> > > [ 6619.068437] [<ffffffff816f9e4f>] dump_stack+0x54/0x74
> > > [ 6619.070046] [<ffffffff81052dcd>] warn_slowpath_common+0x7d/0xa0
> > > [ 6619.071642] [<ffffffff81052eaa>] warn_slowpath_null+0x1a/0x20
> > > [ 6619.073224] [<ffffffff81115d1a>] __ftrace_hash_rec_update.part.37+0x20a/0x240
> > > [ 6619.074817] [<ffffffff81117e18>] ftrace_shutdown+0xb8/0x160
> > > [ 6619.076399] [<ffffffff811182a0>] unregister_ftrace_function+0x30/0x50
> > > [ 6619.077983] [<ffffffff81135e57>] perf_ftrace_event_register+0x87/0x150
> > > [ 6619.079565] [<ffffffff81135cdc>] perf_trace_destroy+0x2c/0x50
> > > [ 6619.081180] [<ffffffff8113df49>] tp_perf_event_destroy+0x9/0x10
> > > [ 6619.082742] [<ffffffff81140527>] free_event+0xa7/0x300
> > > [ 6619.084264] [<ffffffff81141620>] __perf_event_exit_task+0xe0/0x130
> > > [ 6619.085792] [<ffffffff8114a491>] perf_event_exit_task+0x1f1/0x230
> > > [ 6619.087329] [<ffffffff810546dd>] do_exit+0x30d/0xcd0
> > > [ 6619.088860] [<ffffffff8170cfc0>] ? ftrace_call+0x5/0x2f
> > > [ 6619.090460] [<ffffffff8105643c>] do_group_exit+0x4c/0xc0
> > > [ 6619.092036] [<ffffffff810564c4>] SyS_exit_group+0x14/0x20
> > > [ 6619.093614] [<ffffffff8170d594>] tracesys+0xdd/0xe2
> >
> > The first failure disables function tracing completely, which is one of
> > the causes to return an error, which triggered the warning I added.
> >
> > I was hoping that it failed for another reason and then that would
> > cause things to break. But you said the hash corruption happened first
> > (the original bug), so that's not the case.
> >
> > Back to staring at code.
>
> Steve, any further thoughts on this ? I can't do more than a few hours of fuzz-testing
> without eventually running into this.
I'm currently traveling, but as it seems that you have a pretty good
reproducer, can trace what trinity does up to the point it crashes?
I think we can do that with other buffers. If you download the latest
trace-cmd, you can run:
trace-cmd record -e syscalls -B trinity trinity <args>
This will create a ftrace sub buffer called trinity and shouldn't be
affected by the other ftrace functions. Then it should trace all the
syscalls that trinity does. I guess a strace could be used too.
-- Steve
On Mon, Sep 30, 2013 at 11:56:06PM -0400, Steven Rostedt wrote:
> > Steve, any further thoughts on this ? I can't do more than a few hours of fuzz-testing
> > without eventually running into this.
>
> I'm currently traveling, but as it seems that you have a pretty good
> reproducer, can trace what trinity does up to the point it crashes?
>
> I think we can do that with other buffers. If you download the latest
> trace-cmd, you can run:
>
> trace-cmd record -e syscalls -B trinity trinity <args>
>
> This will create a ftrace sub buffer called trinity and shouldn't be
> affected by the other ftrace functions. Then it should trace all the
> syscalls that trinity does. I guess a strace could be used too.
It seems like trace-cmd needs to be run as root. all hell will break loose if trinity gets root privs.
Dave
On Tue, 2013-10-01 at 00:20 -0400, Dave Jones wrote:
> It seems like trace-cmd needs to be run as root. all hell will break loose if trinity gets root privs.
Then run this:
trace-cmd record -e syscalls -B trinity su davej -c 'trinity <args>'
-- Steve
On Tue, Oct 01, 2013 at 08:28:51AM -0400, Steven Rostedt wrote:
> On Tue, 2013-10-01 at 00:20 -0400, Dave Jones wrote:
>
> > It seems like trace-cmd needs to be run as root. all hell will break loose if trinity gets root privs.
>
> Then run this:
>
> trace-cmd record -e syscalls -B trinity su davej -c 'trinity <args>'
I feel like I'm peeling an onion.
I keep hititng that other ftrace bug instead:
WARNING: CPU: 2 PID: 15596 at kernel/trace/ftrace.c:1701 ftrace_bug+0x206/0x270()
Modules linked in: snd_seq_dummy(+) rfcomm hidp bnep nfnetlink scsi_transport_iscsi nfc caif_socket caif af_802154 phonet af_rxrpc can_raw can_bcm bluetooth rfkill can llc2 pppoe ppp
ox ppp_generic slhc irda crc_ccitt rds ipt_ULOG af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 coretemp hwmon x86_pkg_temp_thermal kvm_intel xfs kvm libcrc32c snd_hda_codec_hdm
i snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_seq crct10dif_pclmul snd_seq_device crc32c_intel ghash_clmulni_intel snd_pcm e1000e microcode serio_raw pcspkr snd_page_alloc shpch
p usb_debug snd_timer ptp snd pps_core soundcore
CPU: 2 PID: 15596 Comm: modprobe Not tainted 3.12.0-rc3+ #92
ffffffff81a2a214 ffff880236abfc30 ffffffff8172a363 0000000000000000
ffff880236abfc68 ffffffff8105523d 0000000000000000 ffffffffa034a000
ffff880239d5b0e0 0000000000000000 ffff880234edb000 ffff880236abfc78
Call Trace:
[<ffffffff8172a363>] dump_stack+0x4e/0x82
[<ffffffff8105523d>] warn_slowpath_common+0x7d/0xa0
[<ffffffffa034a000>] ? 0xffffffffa0349fff
[<ffffffff8105531a>] warn_slowpath_null+0x1a/0x20
[<ffffffff81120776>] ftrace_bug+0x206/0x270
[<ffffffffa034a000>] ? 0xffffffffa0349fff
[<ffffffff81120aec>] ftrace_process_locs+0x30c/0x640
[<ffffffff81120e5e>] ftrace_module_notify_enter+0x3e/0x50
[<ffffffff81738aa6>] notifier_call_chain+0x66/0x150
[<ffffffff8108b197>] __blocking_notifier_call_chain+0x67/0xc0
[<ffffffff8108b206>] blocking_notifier_call_chain+0x16/0x20
[<ffffffff810daddd>] load_module+0x1f7d/0x26a0
[<ffffffff810d5f90>] ? store_uevent+0x40/0x40
[<ffffffff810db696>] SyS_finit_module+0x86/0xb0
[<ffffffff8173d4e4>] tracesys+0xdd/0xe2
---[ end trace d2b5caf2401c5667 ]---
ftrace faulted on writing [<ffffffffa034a000>] dummy_free+0x0/0x10 [snd_seq_dummy]
This locks up hard, and then I end up with 0 byte log files when I reboot :-/
Dave
On Wed, 2013-10-02 at 10:16 -0400, Dave Jones wrote:
> On Tue, Oct 01, 2013 at 08:28:51AM -0400, Steven Rostedt wrote:
> > On Tue, 2013-10-01 at 00:20 -0400, Dave Jones wrote:
> >
> > > It seems like trace-cmd needs to be run as root. all hell will break loose if trinity gets root privs.
> >
> > Then run this:
> >
> > trace-cmd record -e syscalls -B trinity su davej -c 'trinity <args>'
>
> I feel like I'm peeling an onion.
>
> I keep hititng that other ftrace bug instead:
>
> WARNING: CPU: 2 PID: 15596 at kernel/trace/ftrace.c:1701 ftrace_bug+0x206/0x270()
> Modules linked in: snd_seq_dummy(+) rfcomm hidp bnep nfnetlink scsi_transport_iscsi nfc caif_socket caif af_802154 phonet af_rxrpc can_raw can_bcm bluetooth rfkill can llc2 pppoe ppp
> ox ppp_generic slhc irda crc_ccitt rds ipt_ULOG af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 coretemp hwmon x86_pkg_temp_thermal kvm_intel xfs kvm libcrc32c snd_hda_codec_hdm
> i snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_seq crct10dif_pclmul snd_seq_device crc32c_intel ghash_clmulni_intel snd_pcm e1000e microcode serio_raw pcspkr snd_page_alloc shpch
> p usb_debug snd_timer ptp snd pps_core soundcore
> CPU: 2 PID: 15596 Comm: modprobe Not tainted 3.12.0-rc3+ #92
> ffffffff81a2a214 ffff880236abfc30 ffffffff8172a363 0000000000000000
> ffff880236abfc68 ffffffff8105523d 0000000000000000 ffffffffa034a000
> ffff880239d5b0e0 0000000000000000 ffff880234edb000 ffff880236abfc78
> Call Trace:
> [<ffffffff8172a363>] dump_stack+0x4e/0x82
> [<ffffffff8105523d>] warn_slowpath_common+0x7d/0xa0
> [<ffffffffa034a000>] ? 0xffffffffa0349fff
> [<ffffffff8105531a>] warn_slowpath_null+0x1a/0x20
> [<ffffffff81120776>] ftrace_bug+0x206/0x270
> [<ffffffffa034a000>] ? 0xffffffffa0349fff
> [<ffffffff81120aec>] ftrace_process_locs+0x30c/0x640
> [<ffffffff81120e5e>] ftrace_module_notify_enter+0x3e/0x50
> [<ffffffff81738aa6>] notifier_call_chain+0x66/0x150
> [<ffffffff8108b197>] __blocking_notifier_call_chain+0x67/0xc0
> [<ffffffff8108b206>] blocking_notifier_call_chain+0x16/0x20
> [<ffffffff810daddd>] load_module+0x1f7d/0x26a0
So trinity is loading a module?
> [<ffffffff810d5f90>] ? store_uevent+0x40/0x40
> [<ffffffff810db696>] SyS_finit_module+0x86/0xb0
> [<ffffffff8173d4e4>] tracesys+0xdd/0xe2
> ---[ end trace d2b5caf2401c5667 ]---
> ftrace faulted on writing [<ffffffffa034a000>] dummy_free+0x0/0x10 [snd_seq_dummy]
Is this module compiled for this kernel? What happened was that the
address it tried to write to wasn't writable. Does function tracing
normally work? Speaking of which, the trace-cmd line I gave should not
have started function tracing, so something else must have done it.
-- Steve
>
>
> This locks up hard, and then I end up with 0 byte log files when I reboot :-/
>
> Dave
On Wed, Oct 02, 2013 at 12:43:26PM -0400, Steven Rostedt wrote:
> > I keep hititng that other ftrace bug instead:
> >
> > WARNING: CPU: 2 PID: 15596 at kernel/trace/ftrace.c:1701 ftrace_bug+0x206/0x270()
> > Modules linked in: snd_seq_dummy(+) rfcomm hidp bnep nfnetlink scsi_transport_iscsi nfc caif_socket caif af_802154 phonet af_rxrpc can_raw can_bcm bluetooth rfkill can llc2 pppoe ppp
> > ox ppp_generic slhc irda crc_ccitt rds ipt_ULOG af_key rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 coretemp hwmon x86_pkg_temp_thermal kvm_intel xfs kvm libcrc32c snd_hda_codec_hdm
> > i snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_seq crct10dif_pclmul snd_seq_device crc32c_intel ghash_clmulni_intel snd_pcm e1000e microcode serio_raw pcspkr snd_page_alloc shpch
> > p usb_debug snd_timer ptp snd pps_core soundcore
> > CPU: 2 PID: 15596 Comm: modprobe Not tainted 3.12.0-rc3+ #92
> > ffffffff81a2a214 ffff880236abfc30 ffffffff8172a363 0000000000000000
> > ffff880236abfc68 ffffffff8105523d 0000000000000000 ffffffffa034a000
> > ffff880239d5b0e0 0000000000000000 ffff880234edb000 ffff880236abfc78
> > Call Trace:
> > [<ffffffff8172a363>] dump_stack+0x4e/0x82
> > [<ffffffff8105523d>] warn_slowpath_common+0x7d/0xa0
> > [<ffffffffa034a000>] ? 0xffffffffa0349fff
> > [<ffffffff8105531a>] warn_slowpath_null+0x1a/0x20
> > [<ffffffff81120776>] ftrace_bug+0x206/0x270
> > [<ffffffffa034a000>] ? 0xffffffffa0349fff
> > [<ffffffff81120aec>] ftrace_process_locs+0x30c/0x640
> > [<ffffffff81120e5e>] ftrace_module_notify_enter+0x3e/0x50
> > [<ffffffff81738aa6>] notifier_call_chain+0x66/0x150
> > [<ffffffff8108b197>] __blocking_notifier_call_chain+0x67/0xc0
> > [<ffffffff8108b206>] blocking_notifier_call_chain+0x16/0x20
> > [<ffffffff810daddd>] load_module+0x1f7d/0x26a0
>
> So trinity is loading a module?
It probably triggered it by reading some /dev node.
> > [<ffffffff810d5f90>] ? store_uevent+0x40/0x40
> > [<ffffffff810db696>] SyS_finit_module+0x86/0xb0
> > [<ffffffff8173d4e4>] tracesys+0xdd/0xe2
> > ---[ end trace d2b5caf2401c5667 ]---
> > ftrace faulted on writing [<ffffffffa034a000>] dummy_free+0x0/0x10 [snd_seq_dummy]
>
> Is this module compiled for this kernel?
should be.
> What happened was that the
> address it tried to write to wasn't writable. Does function tracing
> normally work?
example you want me to try ?
> Speaking of which, the trace-cmd line I gave should not
> have started function tracing, so something else must have done it.
/sys/kernel/debug is 0700 so the trinity processes shouldn't have had
abilities to even do anything there.
Dave