[PATCH] tracing: Move postpone selftests to core from early_initcall

[PATCH] tracing: Move postpone selftests to core from early_initcall

[Steven Rostedt]

I hit the following lockdep splat when booting with ftrace selftests
enabled, as well as CONFIG_PREEMPT and LOCKDEP.

 Testing dynamic ftrace ops #1:
 (1 0 1 0 0)
 (1 1 2 0 0)
 (2 1 3 0 169)
 (2 2 4 0 50066)
 ------------[ cut here ]------------
 WARNING: CPU: 0 PID: 13 at kernel/rcu/srcutree.c:202 check_init_srcu_struct+0x60/0x70
 Modules linked in:
 CPU: 0 PID: 13 Comm: rcu_tasks_kthre Not tainted 4.12.0-rc1-test+ #587
 Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v02.05 05/07/2012
 task: ffff880119628040 task.stack: ffffc900006a4000
 RIP: 0010:check_init_srcu_struct+0x60/0x70
 RSP: 0000:ffffc900006a7d98 EFLAGS: 00010246
 RAX: 0000000000000246 RBX: 0000000000000000 RCX: 0000000000000000
 RDX: ffff880119628040 RSI: 00000000ffffffff RDI: ffffffff81e5fb40
 RBP: ffffc900006a7e20 R08: 00000023b403c000 R09: 0000000000000001
 R10: ffffc900006a7e40 R11: 0000000000000000 R12: ffffffff81e5fb40
 R13: 0000000000000286 R14: ffff880119628040 R15: ffffc900006a7e98
 FS:  0000000000000000(0000) GS:ffff88011ea00000(0000) knlGS:0000000000000000
 CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
 CR2: ffff88011edff000 CR3: 0000000001e0f000 CR4: 00000000001406f0
 Call Trace:
  ? __synchronize_srcu+0x6e/0x140
  ? lock_acquire+0xdc/0x1d0
  ? ktime_get_mono_fast_ns+0x5d/0xb0
  synchronize_srcu+0x6f/0x110
  ? synchronize_srcu+0x6f/0x110
  rcu_tasks_kthread+0x20a/0x540
  kthread+0x114/0x150
  ? __rcu_read_unlock+0x70/0x70
  ? kthread_create_on_node+0x40/0x40
  ret_from_fork+0x2e/0x40
 Code: f6 83 70 06 00 00 03 49 89 c5 74 0d be 01 00 00 00 48 89 df e8 42 fa ff ff 4c 89 ee 4c 89 e7 e8 b7 42 75 00 5b 41 5c 41 5d 5d c3 <0f> ff eb aa 66 90 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00
 ---[ end trace 5c3f4206ce50f6ac ]---

What happens is that the selftests include a creating of a dynamically
allocated ftrace_ops, which requires the use of synchronize_rcu_tasks()
which uses srcu, and triggers the above warning.

It appears that synchronize_rcu_tasks() is not set up at early_initcall(),
but it is at core_initcall(). By moving the tests down to that location
works out properly.

Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 3f2aed4..fcc9a2d 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1558,7 +1558,7 @@ static __init int init_trace_selftests(void)
 
 	return 0;
 }
-early_initcall(init_trace_selftests);
+core_initcall(init_trace_selftests);
 #else
 static inline int run_tracer_selftest(struct tracer *type)
 {
-- 
2.9.3

Re: [PATCH] tracing: Move postpone selftests to core from early_initcall

[Paul E. McKenney]

On Wed, May 17, 2017 at 11:14:35AM -0400, Steven Rostedt wrote:
> 
> I hit the following lockdep splat when booting with ftrace selftests
> enabled, as well as CONFIG_PREEMPT and LOCKDEP.
> 
>  Testing dynamic ftrace ops #1:
>  (1 0 1 0 0)
>  (1 1 2 0 0)
>  (2 1 3 0 169)
>  (2 2 4 0 50066)
>  ------------[ cut here ]------------
>  WARNING: CPU: 0 PID: 13 at kernel/rcu/srcutree.c:202 check_init_srcu_struct+0x60/0x70
>  Modules linked in:
>  CPU: 0 PID: 13 Comm: rcu_tasks_kthre Not tainted 4.12.0-rc1-test+ #587
>  Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v02.05 05/07/2012
>  task: ffff880119628040 task.stack: ffffc900006a4000
>  RIP: 0010:check_init_srcu_struct+0x60/0x70
>  RSP: 0000:ffffc900006a7d98 EFLAGS: 00010246
>  RAX: 0000000000000246 RBX: 0000000000000000 RCX: 0000000000000000
>  RDX: ffff880119628040 RSI: 00000000ffffffff RDI: ffffffff81e5fb40
>  RBP: ffffc900006a7e20 R08: 00000023b403c000 R09: 0000000000000001
>  R10: ffffc900006a7e40 R11: 0000000000000000 R12: ffffffff81e5fb40
>  R13: 0000000000000286 R14: ffff880119628040 R15: ffffc900006a7e98
>  FS:  0000000000000000(0000) GS:ffff88011ea00000(0000) knlGS:0000000000000000
>  CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>  CR2: ffff88011edff000 CR3: 0000000001e0f000 CR4: 00000000001406f0
>  Call Trace:
>   ? __synchronize_srcu+0x6e/0x140
>   ? lock_acquire+0xdc/0x1d0
>   ? ktime_get_mono_fast_ns+0x5d/0xb0
>   synchronize_srcu+0x6f/0x110
>   ? synchronize_srcu+0x6f/0x110
>   rcu_tasks_kthread+0x20a/0x540
>   kthread+0x114/0x150
>   ? __rcu_read_unlock+0x70/0x70
>   ? kthread_create_on_node+0x40/0x40
>   ret_from_fork+0x2e/0x40
>  Code: f6 83 70 06 00 00 03 49 89 c5 74 0d be 01 00 00 00 48 89 df e8 42 fa ff ff 4c 89 ee 4c 89 e7 e8 b7 42 75 00 5b 41 5c 41 5d 5d c3 <0f> ff eb aa 66 90 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00
>  ---[ end trace 5c3f4206ce50f6ac ]---
> 
> What happens is that the selftests include a creating of a dynamically
> allocated ftrace_ops, which requires the use of synchronize_rcu_tasks()
> which uses srcu, and triggers the above warning.
> 
> It appears that synchronize_rcu_tasks() is not set up at early_initcall(),
> but it is at core_initcall(). By moving the tests down to that location
> works out properly.
> 
> Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

Acked-by: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>

But it looks like I need to raise the priority of making SRCU
safe throughout boot, including the "mid-boot dead zone"...

							Thanx, Paul

> ---
>  kernel/trace/trace.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 3f2aed4..fcc9a2d 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -1558,7 +1558,7 @@ static __init int init_trace_selftests(void)
> 
>  	return 0;
>  }
> -early_initcall(init_trace_selftests);
> +core_initcall(init_trace_selftests);
>  #else
>  static inline int run_tracer_selftest(struct tracer *type)
>  {
> -- 
> 2.9.3
>