* __ftrace_hash_rec_update FTRACE_WARN_ON. @ 2013-07-05 14:26 Dave Jones 2013-07-05 14:53 ` Steven Rostedt 0 siblings, 1 reply; 12+ messages in thread From: Dave Jones @ 2013-07-05 14:26 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-kernel WARNING: at kernel/trace/ftrace.c:1605 __ftrace_hash_rec_update.part.37+0x20a/0x240() Modules linked in: sctp libcrc32c snd_seq_dummy fuse tun rfcomm bnep scsi_transport_iscsi hidp nfnetlink can_bcm irda caif_socket nfc caif netrom crc_ccitt rose x25 appletalk ipt_ULOG rds bluetooth can_raw ipx phonet can rfkill af_802154 pppoe pppox p8023 llc2 af_key ppp_generic psnap p8022 atm llc slhc ax25 af_rxrpc snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_intel snd_hda_codec snd_hwdep snd_seq pcspkr snd_seq_device snd_pcm e1000e snd_page_alloc snd_timer snd ptp soundcore pps_core CPU: 1 PID: 15820 Comm: trinity-child2 Not tainted 3.10.0+ #21 ffffffff81a1f20b ffff8801be9dfc60 ffffffff816f2120 0000000000000000 ffff8801be9dfc98 ffffffff8104ca81 0000000000000000 0000000000000001 ffff8801be424000 0000000000000000 ffff88022bd25518 ffff8801be9dfca8 Call Trace: [<ffffffff816f2120>] dump_stack+0x4e/0x82 [<ffffffff8104ca81>] warn_slowpath_common+0x61/0x80 [<ffffffff8104cb5a>] warn_slowpath_null+0x1a/0x20 [<ffffffff8111489a>] __ftrace_hash_rec_update.part.37+0x20a/0x240 [<ffffffff811168a8>] ftrace_shutdown+0xb8/0x170 [<ffffffff81116d40>] unregister_ftrace_function+0x30/0x50 [<ffffffff81134487>] perf_ftrace_event_register+0x87/0x130 [<ffffffff811342ec>] perf_trace_destroy+0x2c/0x50 [<ffffffff8113caf9>] tp_perf_event_destroy+0x9/0x10 [<ffffffff8113f0f7>] free_event+0xa7/0x310 [<ffffffff8113f3c4>] perf_event_release_kernel+0x64/0x90 [<ffffffff8113f830>] put_event+0x120/0x1b0 [<ffffffff8113f740>] ? put_event+0x30/0x1b0 [<ffffffff8113f8d0>] perf_release+0x10/0x20 [<ffffffff811b7d15>] __fput+0xf5/0x2d0 [<ffffffff811b7fae>] ____fput+0xe/0x10 [<ffffffff8107798c>] task_work_run+0xac/0xe0 [<ffffffff81051d27>] do_exit+0x2c7/0xcd0 [<ffffffff81704b00>] ? ftrace_call+0x5/0x2f [<ffffffff81053afc>] do_group_exit+0x4c/0xc0 [<ffffffff81053b84>] SyS_exit_group+0x14/0x20 [<ffffffff817050d4>] tracesys+0xdd/0xe2 ---[ end trace df06ab36fcd44d8b ]--- 1605 if (FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0)) 1606 return; ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: __ftrace_hash_rec_update FTRACE_WARN_ON. 2013-07-05 14:26 __ftrace_hash_rec_update FTRACE_WARN_ON Dave Jones @ 2013-07-05 14:53 ` Steven Rostedt 2013-07-05 15:11 ` Dave Jones 2013-07-24 16:04 ` Jörn Engel 0 siblings, 2 replies; 12+ messages in thread From: Steven Rostedt @ 2013-07-05 14:53 UTC (permalink / raw) To: Dave Jones; +Cc: linux-kernel On Fri, 2013-07-05 at 10:26 -0400, Dave Jones wrote: > WARNING: at kernel/trace/ftrace.c:1605 __ftrace_hash_rec_update.part.37+0x20a/0x240() > Modules linked in: sctp libcrc32c snd_seq_dummy fuse tun rfcomm bnep scsi_transport_iscsi hidp nfnetlink can_bcm irda caif_socket nfc caif netrom crc_ccitt rose x25 appletalk ipt_ULOG rds bluetooth can_raw ipx phonet can rfkill af_802154 pppoe pppox p8023 llc2 af_key ppp_generic psnap p8022 atm llc slhc ax25 af_rxrpc snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_intel snd_hda_codec snd_hwdep snd_seq pcspkr snd_seq_device snd_pcm e1000e snd_page_alloc snd_timer snd ptp soundcore pps_core > CPU: 1 PID: 15820 Comm: trinity-child2 Not tainted 3.10.0+ #21 > ffffffff81a1f20b ffff8801be9dfc60 ffffffff816f2120 0000000000000000 > ffff8801be9dfc98 ffffffff8104ca81 0000000000000000 0000000000000001 > ffff8801be424000 0000000000000000 ffff88022bd25518 ffff8801be9dfca8 > Call Trace: > [<ffffffff816f2120>] dump_stack+0x4e/0x82 > [<ffffffff8104ca81>] warn_slowpath_common+0x61/0x80 > [<ffffffff8104cb5a>] warn_slowpath_null+0x1a/0x20 > [<ffffffff8111489a>] __ftrace_hash_rec_update.part.37+0x20a/0x240 > [<ffffffff811168a8>] ftrace_shutdown+0xb8/0x170 > [<ffffffff81116d40>] unregister_ftrace_function+0x30/0x50 > [<ffffffff81134487>] perf_ftrace_event_register+0x87/0x130 > [<ffffffff811342ec>] perf_trace_destroy+0x2c/0x50 > [<ffffffff8113caf9>] tp_perf_event_destroy+0x9/0x10 > [<ffffffff8113f0f7>] free_event+0xa7/0x310 > [<ffffffff8113f3c4>] perf_event_release_kernel+0x64/0x90 > [<ffffffff8113f830>] put_event+0x120/0x1b0 > [<ffffffff8113f740>] ? put_event+0x30/0x1b0 > [<ffffffff8113f8d0>] perf_release+0x10/0x20 > [<ffffffff811b7d15>] __fput+0xf5/0x2d0 > [<ffffffff811b7fae>] ____fput+0xe/0x10 > [<ffffffff8107798c>] task_work_run+0xac/0xe0 > [<ffffffff81051d27>] do_exit+0x2c7/0xcd0 > [<ffffffff81704b00>] ? ftrace_call+0x5/0x2f > [<ffffffff81053afc>] do_group_exit+0x4c/0xc0 > [<ffffffff81053b84>] SyS_exit_group+0x14/0x20 > [<ffffffff817050d4>] tracesys+0xdd/0xe2 > ---[ end trace df06ab36fcd44d8b ]--- > > > 1605 if (FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0)) > 1606 return; > Can you find an easy reproducer for this? -- Steve ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: __ftrace_hash_rec_update FTRACE_WARN_ON. 2013-07-05 14:53 ` Steven Rostedt @ 2013-07-05 15:11 ` Dave Jones 2013-07-24 16:04 ` Jörn Engel 1 sibling, 0 replies; 12+ messages in thread From: Dave Jones @ 2013-07-05 15:11 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-kernel On Fri, Jul 05, 2013 at 10:53:54AM -0400, Steven Rostedt wrote: > On Fri, 2013-07-05 at 10:26 -0400, Dave Jones wrote: > > WARNING: at kernel/trace/ftrace.c:1605 __ftrace_hash_rec_update.part.37+0x20a/0x240() > > Modules linked in: sctp libcrc32c snd_seq_dummy fuse tun rfcomm bnep scsi_transport_iscsi hidp nfnetlink can_bcm irda caif_socket nfc caif netrom crc_ccitt rose x25 appletalk ipt_ULOG rds bluetooth can_raw ipx phonet can rfkill af_802154 pppoe pppox p8023 llc2 af_key ppp_generic psnap p8022 atm llc slhc ax25 af_rxrpc snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_intel snd_hda_codec snd_hwdep snd_seq pcspkr snd_seq_device snd_pcm e1000e snd_page_alloc snd_timer snd ptp soundcore pps_core > > CPU: 1 PID: 15820 Comm: trinity-child2 Not tainted 3.10.0+ #21 > > ffffffff81a1f20b ffff8801be9dfc60 ffffffff816f2120 0000000000000000 > > ffff8801be9dfc98 ffffffff8104ca81 0000000000000000 0000000000000001 > > ffff8801be424000 0000000000000000 ffff88022bd25518 ffff8801be9dfca8 > > Call Trace: > > [<ffffffff816f2120>] dump_stack+0x4e/0x82 > > [<ffffffff8104ca81>] warn_slowpath_common+0x61/0x80 > > [<ffffffff8104cb5a>] warn_slowpath_null+0x1a/0x20 > > [<ffffffff8111489a>] __ftrace_hash_rec_update.part.37+0x20a/0x240 > > [<ffffffff811168a8>] ftrace_shutdown+0xb8/0x170 > > [<ffffffff81116d40>] unregister_ftrace_function+0x30/0x50 > > [<ffffffff81134487>] perf_ftrace_event_register+0x87/0x130 > > [<ffffffff811342ec>] perf_trace_destroy+0x2c/0x50 > > [<ffffffff8113caf9>] tp_perf_event_destroy+0x9/0x10 > > [<ffffffff8113f0f7>] free_event+0xa7/0x310 > > [<ffffffff8113f3c4>] perf_event_release_kernel+0x64/0x90 > > [<ffffffff8113f830>] put_event+0x120/0x1b0 > > [<ffffffff8113f740>] ? put_event+0x30/0x1b0 > > [<ffffffff8113f8d0>] perf_release+0x10/0x20 > > [<ffffffff811b7d15>] __fput+0xf5/0x2d0 > > [<ffffffff811b7fae>] ____fput+0xe/0x10 > > [<ffffffff8107798c>] task_work_run+0xac/0xe0 > > [<ffffffff81051d27>] do_exit+0x2c7/0xcd0 > > [<ffffffff81704b00>] ? ftrace_call+0x5/0x2f > > [<ffffffff81053afc>] do_group_exit+0x4c/0xc0 > > [<ffffffff81053b84>] SyS_exit_group+0x14/0x20 > > [<ffffffff817050d4>] tracesys+0xdd/0xe2 > > ---[ end trace df06ab36fcd44d8b ]--- > > > > > > 1605 if (FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0)) > > 1606 return; > > > > Can you find an easy reproducer for this? To be honest, probably not. Every run, I seem to be hitting new bugs right now. Dave ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: __ftrace_hash_rec_update FTRACE_WARN_ON. 2013-07-05 14:53 ` Steven Rostedt 2013-07-05 15:11 ` Dave Jones @ 2013-07-24 16:04 ` Jörn Engel 2013-07-25 1:24 ` Steven Rostedt 1 sibling, 1 reply; 12+ messages in thread From: Jörn Engel @ 2013-07-24 16:04 UTC (permalink / raw) To: Steven Rostedt; +Cc: Dave Jones, linux-kernel, steve On Fri, 5 July 2013 10:53:54 -0400, Steven Rostedt wrote: > > Can you find an easy reproducer for this? We might have found something: Jul 23 19:00:59 [28253.487058,08] WARNING: at kernel/trace/ftrace.c:1529 __ftrace_hash_rec_update+0x1e3/0x230() Jul 23 19:00:59 [28253.487203,08] Pid: 20903, comm: bash Tainted: G O 3.6.11+ #38405.trunk Jul 23 19:00:59 [28253.487206,08] Call Trace: Jul 23 19:00:59 [28253.487213,08] [<ffffffff8103e5ff>] warn_slowpath_common+0x7f/0xc0 Jul 23 19:00:59 [28253.487218,08] [<ffffffff8103e65a>] warn_slowpath_null+0x1a/0x20 Jul 23 19:00:59 [28253.487222,08] [<ffffffff810c2ee3>] __ftrace_hash_rec_update+0x1e3/0x230 Jul 23 19:00:59 [28253.487227,08] [<ffffffff810c4f28>] ftrace_hash_move+0x28/0x1d0 Jul 23 19:00:59 [28253.487232,08] [<ffffffff811401cc>] ? kfree+0x2c/0x110 Jul 23 19:00:59 [28253.487237,08] [<ffffffff810c68ee>] ftrace_regex_release+0x8e/0x150 Jul 23 19:00:59 [28253.487242,08] [<ffffffff81149f1e>] __fput+0xae/0x220 Jul 23 19:00:59 [28253.487247,08] [<ffffffff8114a09e>] ____fput+0xe/0x10 Jul 23 19:00:59 [28253.487252,08] [<ffffffff8105fa22>] task_work_run+0x72/0x90 Jul 23 19:00:59 [28253.487257,08] [<ffffffff810028ec>] do_notify_resume+0x6c/0xc0 Jul 23 19:00:59 [28253.487262,08] [<ffffffff8126596e>] ? trace_hardirqs_on_thunk+0x3a/0x3c Jul 23 19:00:59 [28253.487267,08] [<ffffffff815c0f88>] int_signal+0x12/0x17 Jul 23 19:00:59 [28253.487271,08] ---[ end trace 793179526ee09b2c ]--- Jul 23 19:21:02 [ 775.393547,08] WARNING: at kernel/trace/ftrace.c:1529 __ftrace_hash_rec_update+0x1e3/0x230() Jul 23 19:21:02 [ 775.393715,08] Pid: 6376, comm: bash Tainted: G O 3.6.11+ #38405.trunk Jul 23 19:21:02 [ 775.393718,08] Call Trace: Jul 23 19:21:02 [ 775.393727,08] [<ffffffff8103e5ff>] warn_slowpath_common+0x7f/0xc0 Jul 23 19:21:02 [ 775.393732,08] [<ffffffff8103e65a>] warn_slowpath_null+0x1a/0x20 Jul 23 19:21:02 [ 775.393737,08] [<ffffffff810c2ee3>] __ftrace_hash_rec_update+0x1e3/0x230 Jul 23 19:21:02 [ 775.393741,08] [<ffffffff810c4f28>] ftrace_hash_move+0x28/0x1d0 Jul 23 19:21:02 [ 775.393748,08] [<ffffffff811401cc>] ? kfree+0x2c/0x110 Jul 23 19:21:02 [ 775.393754,08] [<ffffffff810c68ee>] ftrace_regex_release+0x8e/0x150 Jul 23 19:21:02 [ 775.393771,08] [<ffffffff81149f1e>] __fput+0xae/0x220 Jul 23 19:21:02 [ 775.393784,08] [<ffffffff8114a09e>] ____fput+0xe/0x10 Jul 23 19:21:02 [ 775.393792,08] [<ffffffff8105fa22>] task_work_run+0x72/0x90 Jul 23 19:21:02 [ 775.393798,08] [<ffffffff810028ec>] do_notify_resume+0x6c/0xc0 Jul 23 19:21:02 [ 775.393804,08] [<ffffffff8126596e>] ? trace_hardirqs_on_thunk+0x3a/0x3c Jul 23 19:21:02 [ 775.393810,08] [<ffffffff815c0f88>] int_signal+0x12/0x17 Jul 23 19:21:02 [ 775.393814,08] ---[ end trace 3b86cc549cc5483e ]--- If I understand Steve correctly, you have to enable a trace somewhere in a module, them rmmod that module without disabling the trace. Easy enough to avoid, but maybe you are interested. Jörn -- One of the painful things about our time is that those who feel certainty are stupid, and those with any imagination and understanding are filled with doubt and indecision. -- Bertrand Russell ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: __ftrace_hash_rec_update FTRACE_WARN_ON. 2013-07-24 16:04 ` Jörn Engel @ 2013-07-25 1:24 ` Steven Rostedt 2013-07-25 5:46 ` Steve Hodgson 0 siblings, 1 reply; 12+ messages in thread From: Steven Rostedt @ 2013-07-25 1:24 UTC (permalink / raw) To: Jörn Engel; +Cc: Dave Jones, linux-kernel, steve On Wed, 2013-07-24 at 12:04 -0400, Jörn Engel wrote: > On Fri, 5 July 2013 10:53:54 -0400, Steven Rostedt wrote: > > > > Can you find an easy reproducer for this? > > We might have found something: > > Jul 23 19:00:59 [28253.487058,08] WARNING: at kernel/trace/ftrace.c:1529 __ftrace_hash_rec_update+0x1e3/0x230() > Jul 23 19:00:59 [28253.487203,08] Pid: 20903, comm: bash Tainted: G O 3.6.11+ #38405.trunk > Jul 23 19:00:59 [28253.487206,08] Call Trace: > Jul 23 19:00:59 [28253.487213,08] [<ffffffff8103e5ff>] warn_slowpath_common+0x7f/0xc0 > Jul 23 19:00:59 [28253.487218,08] [<ffffffff8103e65a>] warn_slowpath_null+0x1a/0x20 > Jul 23 19:00:59 [28253.487222,08] [<ffffffff810c2ee3>] __ftrace_hash_rec_update+0x1e3/0x230 > Jul 23 19:00:59 [28253.487227,08] [<ffffffff810c4f28>] ftrace_hash_move+0x28/0x1d0 > Jul 23 19:00:59 [28253.487232,08] [<ffffffff811401cc>] ? kfree+0x2c/0x110 > Jul 23 19:00:59 [28253.487237,08] [<ffffffff810c68ee>] ftrace_regex_release+0x8e/0x150 > Jul 23 19:00:59 [28253.487242,08] [<ffffffff81149f1e>] __fput+0xae/0x220 > Jul 23 19:00:59 [28253.487247,08] [<ffffffff8114a09e>] ____fput+0xe/0x10 > Jul 23 19:00:59 [28253.487252,08] [<ffffffff8105fa22>] task_work_run+0x72/0x90 > Jul 23 19:00:59 [28253.487257,08] [<ffffffff810028ec>] do_notify_resume+0x6c/0xc0 > Jul 23 19:00:59 [28253.487262,08] [<ffffffff8126596e>] ? trace_hardirqs_on_thunk+0x3a/0x3c > Jul 23 19:00:59 [28253.487267,08] [<ffffffff815c0f88>] int_signal+0x12/0x17 > Jul 23 19:00:59 [28253.487271,08] ---[ end trace 793179526ee09b2c ]--- > > Jul 23 19:21:02 [ 775.393547,08] WARNING: at kernel/trace/ftrace.c:1529 __ftrace_hash_rec_update+0x1e3/0x230() > Jul 23 19:21:02 [ 775.393715,08] Pid: 6376, comm: bash Tainted: G O 3.6.11+ #38405.trunk > Jul 23 19:21:02 [ 775.393718,08] Call Trace: > Jul 23 19:21:02 [ 775.393727,08] [<ffffffff8103e5ff>] warn_slowpath_common+0x7f/0xc0 > Jul 23 19:21:02 [ 775.393732,08] [<ffffffff8103e65a>] warn_slowpath_null+0x1a/0x20 > Jul 23 19:21:02 [ 775.393737,08] [<ffffffff810c2ee3>] __ftrace_hash_rec_update+0x1e3/0x230 > Jul 23 19:21:02 [ 775.393741,08] [<ffffffff810c4f28>] ftrace_hash_move+0x28/0x1d0 > Jul 23 19:21:02 [ 775.393748,08] [<ffffffff811401cc>] ? kfree+0x2c/0x110 > Jul 23 19:21:02 [ 775.393754,08] [<ffffffff810c68ee>] ftrace_regex_release+0x8e/0x150 > Jul 23 19:21:02 [ 775.393771,08] [<ffffffff81149f1e>] __fput+0xae/0x220 > Jul 23 19:21:02 [ 775.393784,08] [<ffffffff8114a09e>] ____fput+0xe/0x10 > Jul 23 19:21:02 [ 775.393792,08] [<ffffffff8105fa22>] task_work_run+0x72/0x90 > Jul 23 19:21:02 [ 775.393798,08] [<ffffffff810028ec>] do_notify_resume+0x6c/0xc0 > Jul 23 19:21:02 [ 775.393804,08] [<ffffffff8126596e>] ? trace_hardirqs_on_thunk+0x3a/0x3c > Jul 23 19:21:02 [ 775.393810,08] [<ffffffff815c0f88>] int_signal+0x12/0x17 > Jul 23 19:21:02 [ 775.393814,08] ---[ end trace 3b86cc549cc5483e ]--- > > If I understand Steve correctly, you have to enable a trace somewhere > in a module, them rmmod that module without disabling the trace. Easy > enough to avoid, but maybe you are interested. I'm a bit confused by this. What do you mean exactly by enable a trace somewhere in a module? The module enables the trace? Does it have its own ftrace_ops? Or the module just starts tracing? -- Steve ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: __ftrace_hash_rec_update FTRACE_WARN_ON. 2013-07-25 1:24 ` Steven Rostedt @ 2013-07-25 5:46 ` Steve Hodgson 2013-07-25 18:59 ` Steven Rostedt 0 siblings, 1 reply; 12+ messages in thread From: Steve Hodgson @ 2013-07-25 5:46 UTC (permalink / raw) To: Steven Rostedt; +Cc: Jörn Engel, Dave Jones, linux-kernel On Wed, Jul 24, 2013 at 6:24 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > > On Wed, 2013-07-24 at 12:04 -0400, Jörn Engel wrote: > > On Fri, 5 July 2013 10:53:54 -0400, Steven Rostedt wrote: > > > > > > Can you find an easy reproducer for this? > > > > We might have found something: > > > > Jul 23 19:00:59 [28253.487058,08] WARNING: at kernel/trace/ftrace.c:1529 __ftrace_hash_rec_update+0x1e3/0x230() > > Jul 23 19:00:59 [28253.487203,08] Pid: 20903, comm: bash Tainted: G O 3.6.11+ #38405.trunk > > Jul 23 19:00:59 [28253.487206,08] Call Trace: > > Jul 23 19:00:59 [28253.487213,08] [<ffffffff8103e5ff>] warn_slowpath_common+0x7f/0xc0 > > Jul 23 19:00:59 [28253.487218,08] [<ffffffff8103e65a>] warn_slowpath_null+0x1a/0x20 > > Jul 23 19:00:59 [28253.487222,08] [<ffffffff810c2ee3>] __ftrace_hash_rec_update+0x1e3/0x230 > > Jul 23 19:00:59 [28253.487227,08] [<ffffffff810c4f28>] ftrace_hash_move+0x28/0x1d0 > > Jul 23 19:00:59 [28253.487232,08] [<ffffffff811401cc>] ? kfree+0x2c/0x110 > > Jul 23 19:00:59 [28253.487237,08] [<ffffffff810c68ee>] ftrace_regex_release+0x8e/0x150 > > Jul 23 19:00:59 [28253.487242,08] [<ffffffff81149f1e>] __fput+0xae/0x220 > > Jul 23 19:00:59 [28253.487247,08] [<ffffffff8114a09e>] ____fput+0xe/0x10 > > Jul 23 19:00:59 [28253.487252,08] [<ffffffff8105fa22>] task_work_run+0x72/0x90 > > Jul 23 19:00:59 [28253.487257,08] [<ffffffff810028ec>] do_notify_resume+0x6c/0xc0 > > Jul 23 19:00:59 [28253.487262,08] [<ffffffff8126596e>] ? trace_hardirqs_on_thunk+0x3a/0x3c > > Jul 23 19:00:59 [28253.487267,08] [<ffffffff815c0f88>] int_signal+0x12/0x17 > > Jul 23 19:00:59 [28253.487271,08] ---[ end trace 793179526ee09b2c ]--- > > > > Jul 23 19:21:02 [ 775.393547,08] WARNING: at kernel/trace/ftrace.c:1529 __ftrace_hash_rec_update+0x1e3/0x230() > > Jul 23 19:21:02 [ 775.393715,08] Pid: 6376, comm: bash Tainted: G O 3.6.11+ #38405.trunk > > Jul 23 19:21:02 [ 775.393718,08] Call Trace: > > Jul 23 19:21:02 [ 775.393727,08] [<ffffffff8103e5ff>] warn_slowpath_common+0x7f/0xc0 > > Jul 23 19:21:02 [ 775.393732,08] [<ffffffff8103e65a>] warn_slowpath_null+0x1a/0x20 > > Jul 23 19:21:02 [ 775.393737,08] [<ffffffff810c2ee3>] __ftrace_hash_rec_update+0x1e3/0x230 > > Jul 23 19:21:02 [ 775.393741,08] [<ffffffff810c4f28>] ftrace_hash_move+0x28/0x1d0 > > Jul 23 19:21:02 [ 775.393748,08] [<ffffffff811401cc>] ? kfree+0x2c/0x110 > > Jul 23 19:21:02 [ 775.393754,08] [<ffffffff810c68ee>] ftrace_regex_release+0x8e/0x150 > > Jul 23 19:21:02 [ 775.393771,08] [<ffffffff81149f1e>] __fput+0xae/0x220 > > Jul 23 19:21:02 [ 775.393784,08] [<ffffffff8114a09e>] ____fput+0xe/0x10 > > Jul 23 19:21:02 [ 775.393792,08] [<ffffffff8105fa22>] task_work_run+0x72/0x90 > > Jul 23 19:21:02 [ 775.393798,08] [<ffffffff810028ec>] do_notify_resume+0x6c/0xc0 > > Jul 23 19:21:02 [ 775.393804,08] [<ffffffff8126596e>] ? trace_hardirqs_on_thunk+0x3a/0x3c > > Jul 23 19:21:02 [ 775.393810,08] [<ffffffff815c0f88>] int_signal+0x12/0x17 > > Jul 23 19:21:02 [ 775.393814,08] ---[ end trace 3b86cc549cc5483e ]--- > > > > If I understand Steve correctly, you have to enable a trace somewhere > > in a module, them rmmod that module without disabling the trace. Easy > > enough to avoid, but maybe you are interested. > > I'm a bit confused by this. What do you mean exactly by enable a trace > somewhere in a module? The module enables the trace? Does it have its > own ftrace_ops? Or the module just starts tracing? No, nothing so complicated. I added symbols from a kernel module into /sys/kernel/debug/tracing/set_ftrace_filter, enabled tracing, then unloaded the kernel module. Which I'll admit is a stupid thing to do. I was then punished for my stupidity by being unable to use ftrace until the next reboot. - Steve ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: __ftrace_hash_rec_update FTRACE_WARN_ON. 2013-07-25 5:46 ` Steve Hodgson @ 2013-07-25 18:59 ` Steven Rostedt 2013-07-26 3:23 ` Steven Rostedt 0 siblings, 1 reply; 12+ messages in thread From: Steven Rostedt @ 2013-07-25 18:59 UTC (permalink / raw) To: Steve Hodgson; +Cc: Jörn Engel, Dave Jones, linux-kernel On Wed, 2013-07-24 at 22:46 -0700, Steve Hodgson wrote: > No, nothing so complicated. > > I added symbols from a kernel module into > /sys/kernel/debug/tracing/set_ftrace_filter, enabled tracing, then > unloaded the kernel module. > > Which I'll admit is a stupid thing to do. I was then punished for my > stupidity by being unable to use ftrace until the next reboot. It's not stupid. ftrace should be robust enough to handle this. Anyway, thank you, I found a reproducer. Removing the module isn't good enough. You need to load it again. # cd /sys/kernel/debug/tracing # cat set_ftrace_filter #### all functions enabled #### # modprobe uinput # echo uniput_release > set_ftrace_filter # cat set_ftrace_filter uinput_release [uinput] # rmmod uinput # cat set_ftrace_filter # # note this is empty # modprobe uinput # cat set_ftrace_filter uinput_release [uinput] # # '<it magically appeared>' # echo > set_ftrace_filter [BOOM] Now that I know what's the problem, it shouldn't be too hard to fix. Thanks! -- Steve ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: __ftrace_hash_rec_update FTRACE_WARN_ON. 2013-07-25 18:59 ` Steven Rostedt @ 2013-07-26 3:23 ` Steven Rostedt 2013-07-27 19:16 ` Steve Hodgson 0 siblings, 1 reply; 12+ messages in thread From: Steven Rostedt @ 2013-07-26 3:23 UTC (permalink / raw) To: Steve Hodgson; +Cc: Jörn Engel, Dave Jones, linux-kernel On Thu, 2013-07-25 at 14:59 -0400, Steven Rostedt wrote: > Now that I know what's the problem, it shouldn't be too hard to fix. It was a bit more involved to fix than I expected. I don't like the fact that if you filter on only module functions and remove that module, you now remove the filter and it traces all functions. Oh well, that's the side effect of removing modules that you are only tracing. If you trace something other than the module you filter on, it will on remove the functions that belong to the module but keep the other functions. So, removing the module, is basically the same as doing: echo '!:mod:<module>' > set_ftrace_filter and acts the same, almost. It only affects the filter if the function trace is currently active. Otherwise it doesn't remove the functions from the filter, as it only removes functions from active filters. This is because ftrace is only aware of filters that are activated. I also added code (set for a separate patch, but combined for this email) that will add a 64 bit ref counter. Every time a module removes functions from ftrace, the counter is incremented. If a filter is activated it has its ref number checked with the current number. If it is different, then it tests all the functions in its filter to see if any should be removed (no longer exists). The reason for the warning, was that we enable the function and it was mapped in the filter. When we removed the module, we removed its functions from the table that keeps track of functions being traced (low level tracking, below filters). But we never cleared the filter. When the module was added again, it was put back into the same location, where the filter matched the address, but the low level table had the function disabled, and the filter said it was enabled. When an update was made, this discrepancy appeared and caused issues. You can try this patch to see if it fixes your issues. There may be some fuzz to apply it because I added it on top of my current queue that needs to go out for 3.11. -- Steve diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h index 9f15c00..3e6ed8f 100644 --- a/include/linux/ftrace.h +++ b/include/linux/ftrace.h @@ -114,6 +114,7 @@ struct ftrace_ops { struct ftrace_hash *notrace_hash; struct ftrace_hash *filter_hash; struct mutex regex_lock; + u64 mod_cnt; #endif }; diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c index 92d3334..366f524 100644 --- a/kernel/trace/ftrace.c +++ b/kernel/trace/ftrace.c @@ -93,6 +93,9 @@ struct ftrace_pid { struct pid *pid; }; +/* Keep track of modules unloading and ops updating filters */ +static u64 mod_ref_cnt; + /* * ftrace_disabled is set when an anomaly is discovered. * ftrace_disabled is much stronger than ftrace_enabled. @@ -321,6 +324,18 @@ static void add_ftrace_ops(struct ftrace_ops **list, struct ftrace_ops *ops) rcu_assign_pointer(*list, ops); } +#ifdef CONFIG_DYNAMIC_FTRACE +static void verify_ops(struct ftrace_ops *ops); +#else +static inline void verify_ops(struct ftrace_ops *ops) { } +#endif + +static void add_main_ftrace_ops(struct ftrace_ops *ops) +{ + verify_ops(ops); + add_ftrace_ops(&ftrace_ops_list, ops); +} + static int remove_ftrace_ops(struct ftrace_ops **list, struct ftrace_ops *ops) { struct ftrace_ops **p; @@ -352,7 +367,7 @@ static void add_ftrace_list_ops(struct ftrace_ops **list, int first = *list == &ftrace_list_end; add_ftrace_ops(list, ops); if (first) - add_ftrace_ops(&ftrace_ops_list, main_ops); + add_main_ftrace_ops(main_ops); } static int remove_ftrace_list_ops(struct ftrace_ops **list, @@ -405,7 +420,7 @@ static int __register_ftrace_function(struct ftrace_ops *ops) return -ENOMEM; add_ftrace_list_ops(&ftrace_control_list, &control_ops, ops); } else - add_ftrace_ops(&ftrace_ops_list, ops); + add_main_ftrace_ops(ops); if (ftrace_enabled) update_ftrace_function(); @@ -1351,6 +1366,38 @@ alloc_and_copy_ftrace_hash(int size_bits, struct ftrace_hash *hash) return NULL; } +static void verify_ops(struct ftrace_ops *ops) +{ + struct ftrace_hash *hash; + struct hlist_node *tn; + struct ftrace_func_entry *entry; + int size; + int i; + + /* + * If a module was removed, we may need to verify + * the filters of this ops. + */ + if (ops->mod_cnt == mod_ref_cnt) + return; + + /* We only need to verify the filter that may enable ops */ + hash = ops->filter_hash; + if (ftrace_hash_empty(hash)) + return; + + size = 1 << hash->size_bits; + for (i = 0; i < size; i++) { + hlist_for_each_entry_safe(entry, tn, &hash->buckets[i], hlist) { + if (!ftrace_location(entry->ip)) + free_hash_entry(hash, entry); + } + } + + /* This ops is now verified. */ + ops->mod_cnt = mod_ref_cnt; +} + static void ftrace_hash_rec_disable(struct ftrace_ops *ops, int filter_hash); static void @@ -4061,6 +4108,66 @@ static int ftrace_process_locs(struct module *mod, #ifdef CONFIG_MODULES +/* + * If the filter is cleared, then all functions may end up being + * traced. We need to pass that information down to update the + * records. + */ +static bool remove_rec_entry(struct ftrace_hash *hash, struct dyn_ftrace *rec) +{ + struct ftrace_func_entry *entry; + + entry = ftrace_lookup_ip(hash, rec->ip); + if (!entry) + return false; + + free_hash_entry(hash, entry); + + /* If we cleared the hash, then we now trace all functions */ + return ftrace_hash_empty(hash); +} + +static void clear_recs(struct ftrace_ops *ops, struct ftrace_page *pg) +{ + struct dyn_ftrace *rec; + bool update = false; + int i; + + /* This ops is registered and is cleared here */ + ops->mod_cnt = mod_ref_cnt; + + for (i = 0; i < pg->index; i++) { + rec = &pg->records[i]; + + /* If the filter hash gets cleared, we trace all functions */ + if (remove_rec_entry(ops->filter_hash, rec)) + update = true; + remove_rec_entry(ops->notrace_hash, rec); + } + + if (update) { + ftrace_hash_rec_enable(ops, 1); + if (ftrace_enabled) + ftrace_run_update_code(FTRACE_UPDATE_CALLS); + } +} + +static bool ops_has_filter(struct ftrace_ops *ops) +{ + return !ftrace_hash_empty(ops->filter_hash) || + !ftrace_hash_empty(ops->notrace_hash); +} + +static void clear_hashes(struct ftrace_page *pg) +{ + struct ftrace_ops *ops; + + for (ops = ftrace_ops_list; ops != &ftrace_list_end; ops = ops->next) { + if ((ops->flags & FTRACE_OPS_FL_ENABLED) && ops_has_filter(ops)) + clear_recs(ops, pg); + } +} + #define next_to_ftrace_page(p) container_of(p, struct ftrace_page, next) void ftrace_release_mod(struct module *mod) @@ -4068,6 +4175,7 @@ void ftrace_release_mod(struct module *mod) struct dyn_ftrace *rec; struct ftrace_page **last_pg; struct ftrace_page *pg; + bool update_ref = true; int order; mutex_lock(&ftrace_lock); @@ -4090,10 +4198,23 @@ void ftrace_release_mod(struct module *mod) if (WARN_ON(pg == ftrace_pages_start)) goto out_unlock; + /* + * A module is removing records from ftrace. + * Any ops not currently registered need to be + * verified before they get registered. + */ + if (update_ref) { + mod_ref_cnt++; + update_ref = false; + } + /* Check if we are deleting the last page */ if (pg == ftrace_pages) ftrace_pages = next_to_ftrace_page(last_pg); + /* Make sure no hashes reference this module record */ + clear_hashes(pg); + *last_pg = pg->next; order = get_count_order(pg->size / ENTRIES_PER_PAGE); free_pages((unsigned long)pg->records, order); ^ permalink raw reply related [flat|nested] 12+ messages in thread
* Re: __ftrace_hash_rec_update FTRACE_WARN_ON. 2013-07-26 3:23 ` Steven Rostedt @ 2013-07-27 19:16 ` Steve Hodgson 2013-07-31 0:51 ` Steven Rostedt 0 siblings, 1 reply; 12+ messages in thread From: Steve Hodgson @ 2013-07-27 19:16 UTC (permalink / raw) To: Steven Rostedt; +Cc: Jörn Engel, Dave Jones, linux-kernel On Thu, Jul 25, 2013 at 8:23 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Thu, 2013-07-25 at 14:59 -0400, Steven Rostedt wrote: > >> Now that I know what's the problem, it shouldn't be too hard to fix. > > It was a bit more involved to fix than I expected. I don't like the fact > that if you filter on only module functions and remove that module, you > now remove the filter and it traces all functions. Oh well, that's the > side effect of removing modules that you are only tracing. If you trace > something other than the module you filter on, it will on remove the > functions that belong to the module but keep the other functions. > > So, removing the module, is basically the same as doing: > > echo '!:mod:<module>' > set_ftrace_filter > > and acts the same, almost. It only affects the filter if the function > trace is currently active. Otherwise it doesn't remove the functions > from the filter, as it only removes functions from active filters. This > is because ftrace is only aware of filters that are activated. I also > added code (set for a separate patch, but combined for this email) that > will add a 64 bit ref counter. Every time a module removes functions > from ftrace, the counter is incremented. If a filter is activated it has > its ref number checked with the current number. If it is different, then > it tests all the functions in its filter to see if any should be removed > (no longer exists). > > The reason for the warning, was that we enable the function and it was > mapped in the filter. When we removed the module, we removed its > functions from the table that keeps track of functions being traced (low > level tracking, below filters). But we never cleared the filter. When > the module was added again, it was put back into the same location, > where the filter matched the address, but the low level table had the > function disabled, and the filter said it was enabled. When an update > was made, this discrepancy appeared and caused issues. > > You can try this patch to see if it fixes your issues. There may be some > fuzz to apply it because I added it on top of my current queue that > needs to go out for 3.11. This patch fixes ftrace across module removal/reinsertion on our 3.6.11 kernel. -- Steve Hodgson > > -- Steve > > diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h > index 9f15c00..3e6ed8f 100644 > --- a/include/linux/ftrace.h > +++ b/include/linux/ftrace.h > @@ -114,6 +114,7 @@ struct ftrace_ops { > struct ftrace_hash *notrace_hash; > struct ftrace_hash *filter_hash; > struct mutex regex_lock; > + u64 mod_cnt; > #endif > }; > > diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c > index 92d3334..366f524 100644 > --- a/kernel/trace/ftrace.c > +++ b/kernel/trace/ftrace.c > @@ -93,6 +93,9 @@ struct ftrace_pid { > struct pid *pid; > }; > > +/* Keep track of modules unloading and ops updating filters */ > +static u64 mod_ref_cnt; > + > /* > * ftrace_disabled is set when an anomaly is discovered. > * ftrace_disabled is much stronger than ftrace_enabled. > @@ -321,6 +324,18 @@ static void add_ftrace_ops(struct ftrace_ops **list, struct ftrace_ops *ops) > rcu_assign_pointer(*list, ops); > } > > +#ifdef CONFIG_DYNAMIC_FTRACE > +static void verify_ops(struct ftrace_ops *ops); > +#else > +static inline void verify_ops(struct ftrace_ops *ops) { } > +#endif > + > +static void add_main_ftrace_ops(struct ftrace_ops *ops) > +{ > + verify_ops(ops); > + add_ftrace_ops(&ftrace_ops_list, ops); > +} > + > static int remove_ftrace_ops(struct ftrace_ops **list, struct ftrace_ops *ops) > { > struct ftrace_ops **p; > @@ -352,7 +367,7 @@ static void add_ftrace_list_ops(struct ftrace_ops **list, > int first = *list == &ftrace_list_end; > add_ftrace_ops(list, ops); > if (first) > - add_ftrace_ops(&ftrace_ops_list, main_ops); > + add_main_ftrace_ops(main_ops); > } > > static int remove_ftrace_list_ops(struct ftrace_ops **list, > @@ -405,7 +420,7 @@ static int __register_ftrace_function(struct ftrace_ops *ops) > return -ENOMEM; > add_ftrace_list_ops(&ftrace_control_list, &control_ops, ops); > } else > - add_ftrace_ops(&ftrace_ops_list, ops); > + add_main_ftrace_ops(ops); > > if (ftrace_enabled) > update_ftrace_function(); > @@ -1351,6 +1366,38 @@ alloc_and_copy_ftrace_hash(int size_bits, struct ftrace_hash *hash) > return NULL; > } > > +static void verify_ops(struct ftrace_ops *ops) > +{ > + struct ftrace_hash *hash; > + struct hlist_node *tn; > + struct ftrace_func_entry *entry; > + int size; > + int i; > + > + /* > + * If a module was removed, we may need to verify > + * the filters of this ops. > + */ > + if (ops->mod_cnt == mod_ref_cnt) > + return; > + > + /* We only need to verify the filter that may enable ops */ > + hash = ops->filter_hash; > + if (ftrace_hash_empty(hash)) > + return; > + > + size = 1 << hash->size_bits; > + for (i = 0; i < size; i++) { > + hlist_for_each_entry_safe(entry, tn, &hash->buckets[i], hlist) { > + if (!ftrace_location(entry->ip)) > + free_hash_entry(hash, entry); > + } > + } > + > + /* This ops is now verified. */ > + ops->mod_cnt = mod_ref_cnt; > +} > + > static void > ftrace_hash_rec_disable(struct ftrace_ops *ops, int filter_hash); > static void > @@ -4061,6 +4108,66 @@ static int ftrace_process_locs(struct module *mod, > > #ifdef CONFIG_MODULES > > +/* > + * If the filter is cleared, then all functions may end up being > + * traced. We need to pass that information down to update the > + * records. > + */ > +static bool remove_rec_entry(struct ftrace_hash *hash, struct dyn_ftrace *rec) > +{ > + struct ftrace_func_entry *entry; > + > + entry = ftrace_lookup_ip(hash, rec->ip); > + if (!entry) > + return false; > + > + free_hash_entry(hash, entry); > + > + /* If we cleared the hash, then we now trace all functions */ > + return ftrace_hash_empty(hash); > +} > + > +static void clear_recs(struct ftrace_ops *ops, struct ftrace_page *pg) > +{ > + struct dyn_ftrace *rec; > + bool update = false; > + int i; > + > + /* This ops is registered and is cleared here */ > + ops->mod_cnt = mod_ref_cnt; > + > + for (i = 0; i < pg->index; i++) { > + rec = &pg->records[i]; > + > + /* If the filter hash gets cleared, we trace all functions */ > + if (remove_rec_entry(ops->filter_hash, rec)) > + update = true; > + remove_rec_entry(ops->notrace_hash, rec); > + } > + > + if (update) { > + ftrace_hash_rec_enable(ops, 1); > + if (ftrace_enabled) > + ftrace_run_update_code(FTRACE_UPDATE_CALLS); > + } > +} > + > +static bool ops_has_filter(struct ftrace_ops *ops) > +{ > + return !ftrace_hash_empty(ops->filter_hash) || > + !ftrace_hash_empty(ops->notrace_hash); > +} > + > +static void clear_hashes(struct ftrace_page *pg) > +{ > + struct ftrace_ops *ops; > + > + for (ops = ftrace_ops_list; ops != &ftrace_list_end; ops = ops->next) { > + if ((ops->flags & FTRACE_OPS_FL_ENABLED) && ops_has_filter(ops)) > + clear_recs(ops, pg); > + } > +} > + > #define next_to_ftrace_page(p) container_of(p, struct ftrace_page, next) > > void ftrace_release_mod(struct module *mod) > @@ -4068,6 +4175,7 @@ void ftrace_release_mod(struct module *mod) > struct dyn_ftrace *rec; > struct ftrace_page **last_pg; > struct ftrace_page *pg; > + bool update_ref = true; > int order; > > mutex_lock(&ftrace_lock); > @@ -4090,10 +4198,23 @@ void ftrace_release_mod(struct module *mod) > if (WARN_ON(pg == ftrace_pages_start)) > goto out_unlock; > > + /* > + * A module is removing records from ftrace. > + * Any ops not currently registered need to be > + * verified before they get registered. > + */ > + if (update_ref) { > + mod_ref_cnt++; > + update_ref = false; > + } > + > /* Check if we are deleting the last page */ > if (pg == ftrace_pages) > ftrace_pages = next_to_ftrace_page(last_pg); > > + /* Make sure no hashes reference this module record */ > + clear_hashes(pg); > + > *last_pg = pg->next; > order = get_count_order(pg->size / ENTRIES_PER_PAGE); > free_pages((unsigned long)pg->records, order); > > ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: __ftrace_hash_rec_update FTRACE_WARN_ON. 2013-07-27 19:16 ` Steve Hodgson @ 2013-07-31 0:51 ` Steven Rostedt 2013-08-02 4:51 ` Steve Hodgson 0 siblings, 1 reply; 12+ messages in thread From: Steven Rostedt @ 2013-07-31 0:51 UTC (permalink / raw) To: Steve Hodgson; +Cc: Jörn Engel, Dave Jones, linux-kernel On Sat, 2013-07-27 at 12:16 -0700, Steve Hodgson wrote: > This patch fixes ftrace across module removal/reinsertion on our 3.6.11 kernel. I found a few corner cases that this patch doesn't work with, and the solution is just getting uglier and uglier. I found a new solution that seems to handle all the corner cases (including this one). Can you test this as well. I want to add your tested-by tag for this too. Thanks! -- Steve >From 4c647dde26cf8c47ccaaed6f2e2fffee5dab5871 Mon Sep 17 00:00:00 2001 From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org> Date: Tue, 30 Jul 2013 00:04:32 -0400 Subject: [PATCH] ftrace: Check module functions being traced on reload MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit There's been a nasty bug that would show up and not give much info. The bug displayed the following warning: WARNING: at kernel/trace/ftrace.c:1529 __ftrace_hash_rec_update+0x1e3/0x230() Pid: 20903, comm: bash Tainted: G O 3.6.11+ #38405.trunk Call Trace: [<ffffffff8103e5ff>] warn_slowpath_common+0x7f/0xc0 [<ffffffff8103e65a>] warn_slowpath_null+0x1a/0x20 [<ffffffff810c2ee3>] __ftrace_hash_rec_update+0x1e3/0x230 [<ffffffff810c4f28>] ftrace_hash_move+0x28/0x1d0 [<ffffffff811401cc>] ? kfree+0x2c/0x110 [<ffffffff810c68ee>] ftrace_regex_release+0x8e/0x150 [<ffffffff81149f1e>] __fput+0xae/0x220 [<ffffffff8114a09e>] ____fput+0xe/0x10 [<ffffffff8105fa22>] task_work_run+0x72/0x90 [<ffffffff810028ec>] do_notify_resume+0x6c/0xc0 [<ffffffff8126596e>] ? trace_hardirqs_on_thunk+0x3a/0x3c [<ffffffff815c0f88>] int_signal+0x12/0x17 ---[ end trace 793179526ee09b2c ]--- It was finally narrowed down to unloading a module that was being traced. It was actually more than that. When functions are being traced, there's a table of all functions that have a ref count of the number of active tracers attached to that function. When a function trace callback is registered to a function, the function's record ref count is incremented. When it is unregistered, the function's record ref count is decremented. If an inconsistency is detected (ref count goes below zero) the above warning is shown and the function tracing is permanently disabled until reboot. The ftrace callback ops holds a hash of functions that it filters on (and/or filters off). If the hash is empty, the default means to filter all functions (for the filter_hash) or to disable no functions (for the notrace_hash). When a module is unloaded, it frees the function records that represent the module functions. These records exist on their own pages, that is function records for one module will not exist on the same page as function records for other modules or even the core kernel. Now when a module unloads, the records that represents its functions are freed. When the module is loaded again, the records are recreated with a default ref count of zero (unless there's a callback that traces all functions, then they will also be traced, and the ref count will be incremented). The problem is that if an ftrace callback hash includes functions of the module being unloaded, those hash entries will not be removed. If the module is reloaded in the same location, the hash entries still point to the functions of the module but the module's ref counts do not reflect that. With the help of Steve and Joern, we found a reproducer: Using uinput module and uinput_release function. cd /sys/kernel/debug/tracing modprobe uinput echo uinput_release > set_ftrace_filter echo function > current_tracer rmmod uinput modprobe uinput # check /proc/modules to see if loaded in same addr, otherwise try again echo nop > current_tracer [BOOM] The above loads the uinput module, which creates a table of functions that can be traced within the module. We add uinput_release to the filter_hash to trace just that function. Enable function tracincg, which increments the ref count of the record associated to uinput_release. Remove uinput, which frees the records including the one that represents uinput_release. Load the uinput module again (and make sure it's at the same address). This recreates the function records all with a ref count of zero, including uinput_release. Disable function tracing, which will decrement the ref count for uinput_release which is now zero because of the module removal and reload, and we have a mismatch (below zero ref count). The solution is to check all currently tracing ftrace callbacks to see if any are tracing any of the module's functions when a module is loaded (it already does that with callbacks that trace all functions). If a callback happens to have a module function being traced, it increments that records ref count and starts tracing that function. There may be a strange side effect with this, where tracing module functions on unload and then reloading a new module may have that new module's functions being traced. This may be something that confuses the user, but it's not a big deal. Another approach is to disable all callback hashes on module unload, but this leaves some ftrace callbacks that may not be registered, but can still have hashes tracing the module's function where ftrace doesn't know about it. That situation can cause the same bug. This solution solves that case too. Another benefit of this solution, is it is possible to trace a module's function on unload and load. Link: http://lkml.kernel.org/r/CADHUQJ58icP+d3QTXheiCnZwu6hrAqG2heMhhcuQvghXavHRFw@mail.gmail.com Reported-by: Jörn Engel <joern@logfs.org> Reported-by: Dave Jones <davej@redhat.com> Reported-by: Steve Hodgson <steve@purestorage.com> Soon-to-be-tested-by: Steve Hodgson <steve@purestorage.com> Signed-off-by: Steven Rostedt <rostedt@goodmis.org> --- kernel/trace/ftrace.c | 71 ++++++++++++++++++++++++++++++++++++++++++++------- 1 file changed, 62 insertions(+), 9 deletions(-) diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c index 92d3334..a6d098c 100644 --- a/kernel/trace/ftrace.c +++ b/kernel/trace/ftrace.c @@ -2169,12 +2169,57 @@ static cycle_t ftrace_update_time; static unsigned long ftrace_update_cnt; unsigned long ftrace_update_tot_cnt; -static int ops_traces_mod(struct ftrace_ops *ops) +static inline int ops_traces_mod(struct ftrace_ops *ops) { - struct ftrace_hash *hash; + /* + * Filter_hash being empty will default to trace module. + * But notrace hash requires a test of individual module functions. + */ + return ftrace_hash_empty(ops->filter_hash) && + ftrace_hash_empty(ops->notrace_hash); +} + +/* + * Check if the current ops references the record. + * + * If the ops traces all functions, then it was already accounted for. + * If the ops does not trace the current record function, skip it. + * If the ops ignores the function via notrace filter, skip it. + */ +static inline bool +ops_references_rec(struct ftrace_ops *ops, struct dyn_ftrace *rec) +{ + /* If ops isn't enabled, ignore it */ + if (!(ops->flags & FTRACE_OPS_FL_ENABLED)) + return 0; + + /* If ops traces all mods, we already accounted for it */ + if (ops_traces_mod(ops)) + return 0; + + /* The function must be in the filter */ + if (!ftrace_hash_empty(ops->filter_hash) && + !ftrace_lookup_ip(ops->filter_hash, rec->ip)) + return 0; - hash = ops->filter_hash; - return ftrace_hash_empty(hash); + /* If in notrace hash, we ignore it too */ + if (ftrace_lookup_ip(ops->notrace_hash, rec->ip)) + return 0; + + return 1; +} + +static int referenced_filters(struct dyn_ftrace *rec) +{ + struct ftrace_ops *ops; + int cnt = 0; + + for (ops = ftrace_ops_list; ops != &ftrace_list_end; ops = ops->next) { + if (ops_references_rec(ops, rec)) + cnt++; + } + + return cnt; } static int ftrace_update_code(struct module *mod) @@ -2183,6 +2228,7 @@ static int ftrace_update_code(struct module *mod) struct dyn_ftrace *p; cycle_t start, stop; unsigned long ref = 0; + bool test = false; int i; /* @@ -2196,9 +2242,12 @@ static int ftrace_update_code(struct module *mod) for (ops = ftrace_ops_list; ops != &ftrace_list_end; ops = ops->next) { - if (ops->flags & FTRACE_OPS_FL_ENABLED && - ops_traces_mod(ops)) - ref++; + if (ops->flags & FTRACE_OPS_FL_ENABLED) { + if (ops_traces_mod(ops)) + ref++; + else + test = true; + } } } @@ -2208,12 +2257,16 @@ static int ftrace_update_code(struct module *mod) for (pg = ftrace_new_pgs; pg; pg = pg->next) { for (i = 0; i < pg->index; i++) { + int cnt = ref; + /* If something went wrong, bail without enabling anything */ if (unlikely(ftrace_disabled)) return -1; p = &pg->records[i]; - p->flags = ref; + if (test) + cnt += referenced_filters(p); + p->flags = cnt; /* * Do the initial record conversion from mcount jump @@ -2233,7 +2286,7 @@ static int ftrace_update_code(struct module *mod) * conversion puts the module to the correct state, thus * passing the ftrace_make_call check. */ - if (ftrace_start_up && ref) { + if (ftrace_start_up && cnt) { int failed = __ftrace_replace_code(p, 1); if (failed) ftrace_bug(failed, p->ip); -- 1.8.1.4 ^ permalink raw reply related [flat|nested] 12+ messages in thread
* Re: __ftrace_hash_rec_update FTRACE_WARN_ON. 2013-07-31 0:51 ` Steven Rostedt @ 2013-08-02 4:51 ` Steve Hodgson 2013-08-02 11:02 ` Steven Rostedt 0 siblings, 1 reply; 12+ messages in thread From: Steve Hodgson @ 2013-08-02 4:51 UTC (permalink / raw) To: Steven Rostedt; +Cc: Jörn Engel, Dave Jones, linux-kernel On Tue, Jul 30, 2013 at 5:51 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Sat, 2013-07-27 at 12:16 -0700, Steve Hodgson wrote: > >> This patch fixes ftrace across module removal/reinsertion on our 3.6.11 kernel. > > I found a few corner cases that this patch doesn't work with, and the > solution is just getting uglier and uglier. > > I found a new solution that seems to handle all the corner cases > (including this one). Can you test this as well. I want to add your > tested-by tag for this too. > > Thanks! > > -- Steve This patch also fixes the issue for me: ftrace works fine across module removal. Sorry for being a little slow in testing this. - Steve > > From 4c647dde26cf8c47ccaaed6f2e2fffee5dab5871 Mon Sep 17 00:00:00 2001 > From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org> > Date: Tue, 30 Jul 2013 00:04:32 -0400 > Subject: [PATCH] ftrace: Check module functions being traced on reload > MIME-Version: 1.0 > Content-Type: text/plain; charset=UTF-8 > Content-Transfer-Encoding: 8bit > > There's been a nasty bug that would show up and not give much info. > The bug displayed the following warning: > > WARNING: at kernel/trace/ftrace.c:1529 __ftrace_hash_rec_update+0x1e3/0x230() > Pid: 20903, comm: bash Tainted: G O 3.6.11+ #38405.trunk > Call Trace: > [<ffffffff8103e5ff>] warn_slowpath_common+0x7f/0xc0 > [<ffffffff8103e65a>] warn_slowpath_null+0x1a/0x20 > [<ffffffff810c2ee3>] __ftrace_hash_rec_update+0x1e3/0x230 > [<ffffffff810c4f28>] ftrace_hash_move+0x28/0x1d0 > [<ffffffff811401cc>] ? kfree+0x2c/0x110 > [<ffffffff810c68ee>] ftrace_regex_release+0x8e/0x150 > [<ffffffff81149f1e>] __fput+0xae/0x220 > [<ffffffff8114a09e>] ____fput+0xe/0x10 > [<ffffffff8105fa22>] task_work_run+0x72/0x90 > [<ffffffff810028ec>] do_notify_resume+0x6c/0xc0 > [<ffffffff8126596e>] ? trace_hardirqs_on_thunk+0x3a/0x3c > [<ffffffff815c0f88>] int_signal+0x12/0x17 > ---[ end trace 793179526ee09b2c ]--- > > It was finally narrowed down to unloading a module that was being traced. > > It was actually more than that. When functions are being traced, there's > a table of all functions that have a ref count of the number of active > tracers attached to that function. When a function trace callback is > registered to a function, the function's record ref count is incremented. > When it is unregistered, the function's record ref count is decremented. > If an inconsistency is detected (ref count goes below zero) the above > warning is shown and the function tracing is permanently disabled until > reboot. > > The ftrace callback ops holds a hash of functions that it filters on > (and/or filters off). If the hash is empty, the default means to filter > all functions (for the filter_hash) or to disable no functions (for the > notrace_hash). > > When a module is unloaded, it frees the function records that represent > the module functions. These records exist on their own pages, that is > function records for one module will not exist on the same page as > function records for other modules or even the core kernel. > > Now when a module unloads, the records that represents its functions are > freed. When the module is loaded again, the records are recreated with > a default ref count of zero (unless there's a callback that traces all > functions, then they will also be traced, and the ref count will be > incremented). > > The problem is that if an ftrace callback hash includes functions of the > module being unloaded, those hash entries will not be removed. If the > module is reloaded in the same location, the hash entries still point > to the functions of the module but the module's ref counts do not reflect > that. > > With the help of Steve and Joern, we found a reproducer: > > Using uinput module and uinput_release function. > > cd /sys/kernel/debug/tracing > modprobe uinput > echo uinput_release > set_ftrace_filter > echo function > current_tracer > rmmod uinput > modprobe uinput > # check /proc/modules to see if loaded in same addr, otherwise try again > echo nop > current_tracer > > [BOOM] > > The above loads the uinput module, which creates a table of functions that > can be traced within the module. > > We add uinput_release to the filter_hash to trace just that function. > > Enable function tracincg, which increments the ref count of the record > associated to uinput_release. > > Remove uinput, which frees the records including the one that represents > uinput_release. > > Load the uinput module again (and make sure it's at the same address). > This recreates the function records all with a ref count of zero, > including uinput_release. > > Disable function tracing, which will decrement the ref count for uinput_release > which is now zero because of the module removal and reload, and we have > a mismatch (below zero ref count). > > The solution is to check all currently tracing ftrace callbacks to see if any > are tracing any of the module's functions when a module is loaded (it already does > that with callbacks that trace all functions). If a callback happens to have > a module function being traced, it increments that records ref count and starts > tracing that function. > > There may be a strange side effect with this, where tracing module functions > on unload and then reloading a new module may have that new module's functions > being traced. This may be something that confuses the user, but it's not > a big deal. Another approach is to disable all callback hashes on module unload, > but this leaves some ftrace callbacks that may not be registered, but can > still have hashes tracing the module's function where ftrace doesn't know about > it. That situation can cause the same bug. This solution solves that case too. > Another benefit of this solution, is it is possible to trace a module's > function on unload and load. > > Link: http://lkml.kernel.org/r/CADHUQJ58icP+d3QTXheiCnZwu6hrAqG2heMhhcuQvghXavHRFw@mail.gmail.com > > Reported-by: Jörn Engel <joern@logfs.org> > Reported-by: Dave Jones <davej@redhat.com> > Reported-by: Steve Hodgson <steve@purestorage.com> > Soon-to-be-tested-by: Steve Hodgson <steve@purestorage.com> > Signed-off-by: Steven Rostedt <rostedt@goodmis.org> > --- > kernel/trace/ftrace.c | 71 ++++++++++++++++++++++++++++++++++++++++++++------- > 1 file changed, 62 insertions(+), 9 deletions(-) > > diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c > index 92d3334..a6d098c 100644 > --- a/kernel/trace/ftrace.c > +++ b/kernel/trace/ftrace.c > @@ -2169,12 +2169,57 @@ static cycle_t ftrace_update_time; > static unsigned long ftrace_update_cnt; > unsigned long ftrace_update_tot_cnt; > > -static int ops_traces_mod(struct ftrace_ops *ops) > +static inline int ops_traces_mod(struct ftrace_ops *ops) > { > - struct ftrace_hash *hash; > + /* > + * Filter_hash being empty will default to trace module. > + * But notrace hash requires a test of individual module functions. > + */ > + return ftrace_hash_empty(ops->filter_hash) && > + ftrace_hash_empty(ops->notrace_hash); > +} > + > +/* > + * Check if the current ops references the record. > + * > + * If the ops traces all functions, then it was already accounted for. > + * If the ops does not trace the current record function, skip it. > + * If the ops ignores the function via notrace filter, skip it. > + */ > +static inline bool > +ops_references_rec(struct ftrace_ops *ops, struct dyn_ftrace *rec) > +{ > + /* If ops isn't enabled, ignore it */ > + if (!(ops->flags & FTRACE_OPS_FL_ENABLED)) > + return 0; > + > + /* If ops traces all mods, we already accounted for it */ > + if (ops_traces_mod(ops)) > + return 0; > + > + /* The function must be in the filter */ > + if (!ftrace_hash_empty(ops->filter_hash) && > + !ftrace_lookup_ip(ops->filter_hash, rec->ip)) > + return 0; > > - hash = ops->filter_hash; > - return ftrace_hash_empty(hash); > + /* If in notrace hash, we ignore it too */ > + if (ftrace_lookup_ip(ops->notrace_hash, rec->ip)) > + return 0; > + > + return 1; > +} > + > +static int referenced_filters(struct dyn_ftrace *rec) > +{ > + struct ftrace_ops *ops; > + int cnt = 0; > + > + for (ops = ftrace_ops_list; ops != &ftrace_list_end; ops = ops->next) { > + if (ops_references_rec(ops, rec)) > + cnt++; > + } > + > + return cnt; > } > > static int ftrace_update_code(struct module *mod) > @@ -2183,6 +2228,7 @@ static int ftrace_update_code(struct module *mod) > struct dyn_ftrace *p; > cycle_t start, stop; > unsigned long ref = 0; > + bool test = false; > int i; > > /* > @@ -2196,9 +2242,12 @@ static int ftrace_update_code(struct module *mod) > > for (ops = ftrace_ops_list; > ops != &ftrace_list_end; ops = ops->next) { > - if (ops->flags & FTRACE_OPS_FL_ENABLED && > - ops_traces_mod(ops)) > - ref++; > + if (ops->flags & FTRACE_OPS_FL_ENABLED) { > + if (ops_traces_mod(ops)) > + ref++; > + else > + test = true; > + } > } > } > > @@ -2208,12 +2257,16 @@ static int ftrace_update_code(struct module *mod) > for (pg = ftrace_new_pgs; pg; pg = pg->next) { > > for (i = 0; i < pg->index; i++) { > + int cnt = ref; > + > /* If something went wrong, bail without enabling anything */ > if (unlikely(ftrace_disabled)) > return -1; > > p = &pg->records[i]; > - p->flags = ref; > + if (test) > + cnt += referenced_filters(p); > + p->flags = cnt; > > /* > * Do the initial record conversion from mcount jump > @@ -2233,7 +2286,7 @@ static int ftrace_update_code(struct module *mod) > * conversion puts the module to the correct state, thus > * passing the ftrace_make_call check. > */ > - if (ftrace_start_up && ref) { > + if (ftrace_start_up && cnt) { > int failed = __ftrace_replace_code(p, 1); > if (failed) > ftrace_bug(failed, p->ip); > -- > 1.8.1.4 > > > ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: __ftrace_hash_rec_update FTRACE_WARN_ON. 2013-08-02 4:51 ` Steve Hodgson @ 2013-08-02 11:02 ` Steven Rostedt 0 siblings, 0 replies; 12+ messages in thread From: Steven Rostedt @ 2013-08-02 11:02 UTC (permalink / raw) To: Steve Hodgson; +Cc: Jörn Engel, Dave Jones, linux-kernel On Thu, 2013-08-01 at 21:51 -0700, Steve Hodgson wrote: > This patch also fixes the issue for me: ftrace works fine across module removal. > > Sorry for being a little slow in testing this. > No problem. Thanks for testing :-) -- Steve ^ permalink raw reply [flat|nested] 12+ messages in thread
end of thread, other threads:[~2013-08-02 11:02 UTC | newest] Thread overview: 12+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2013-07-05 14:26 __ftrace_hash_rec_update FTRACE_WARN_ON Dave Jones 2013-07-05 14:53 ` Steven Rostedt 2013-07-05 15:11 ` Dave Jones 2013-07-24 16:04 ` Jörn Engel 2013-07-25 1:24 ` Steven Rostedt 2013-07-25 5:46 ` Steve Hodgson 2013-07-25 18:59 ` Steven Rostedt 2013-07-26 3:23 ` Steven Rostedt 2013-07-27 19:16 ` Steve Hodgson 2013-07-31 0:51 ` Steven Rostedt 2013-08-02 4:51 ` Steve Hodgson 2013-08-02 11:02 ` Steven Rostedt
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox