Bug 15510 - suspicious rcu_dereference_check() usage in scheduler_tick
Summary: suspicious rcu_dereference_check() usage in scheduler_tick
Status: RESOLVED UNREPRODUCIBLE
Alias: None
Product: Process Management
Classification: Unclassified
Component: Scheduler (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Ingo Molnar
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-03-10 18:20 UTC by Christian Casteyde
Modified: 2010-04-13 22:29 UTC (History)
0 users

See Also:
Kernel Version:
Subsystem:
Regression: Yes
Bisected commit-id:


Attachments

Description Christian Casteyde 2010-03-10 18:20:08 UTC
Acer Aspire 1511LMi
Athlon 64 3000 in 64bits mode
1.2 GB RAM
Bluewhite 64 13 (64 bits port of Slackware)

Since 2.6.34-rc1, I get the following warning at boot on my computer, when I use debugging/kernel hacking options. This warning didn't occur with previous kernels, however it may be because some new checks were added in 34-rc1.

      hard-irq read-recursion/132:  ok  |
      soft-irq read-recursion/132:  ok  |
      hard-irq read-recursion/213:  ok  |
      soft-irq read-recursion/213:  ok  |
      hard-irq read-recursion/231:  ok  |
      soft-irq read-recursion/231:  ok  |
      hard-irq read-recursion/312:  ok  |
      soft-irq read-recursion/312:  ok  |
      hard-irq read-recursion/321:  ok  |
      soft-irq read-recursion/321:  ok  |
-------------------------------------------------------
Good, all 218 testcases passed! |
---------------------------------
ODEBUG: 10 of 10 active objects replaced

===================================================
[ INFO: suspicious rcu_dereference_check() usage. ]
---------------------------------------------------
kernel/sched_fair.c:3479 invoked rcu_dereference_check() without protection!

other info that might help us debug this:

no locks held by swapper/0.

stack backtrace:
Pid: 0, comm: swapper Not tainted 2.6.34-rc1 #2
Call Trace:
 <IRQ>  [<ffffffff8106b081>] lockdep_rcu_dereference+0x91/0xa0
 [<ffffffff8103db8c>] scheduler_tick+0x1ec/0x2d0
 [<ffffffff8104d93f>] update_process_times+0x4f/0x70
 [<ffffffff81067277>] tick_periodic+0x27/0x70
 [<ffffffff810672df>] tick_handle_periodic+0x1f/0x70
 [<ffffffff81005f29>] timer_interrupt+0x19/0x20
 [<ffffffff8107edda>] handle_IRQ_event+0x3a/0xd0
 [<ffffffff81081628>] handle_level_irq+0x98/0x130
 [<ffffffff810056c6>] handle_irq+0x46/0xa0
 [<ffffffff8100496e>] do_IRQ+0x6e/0xf0
 [<ffffffff8157f213>] ret_from_intr+0x0/0xf
 <EOI>  [<ffffffff8157ee48>] ? _raw_spin_unlock_irqrestore+0x68/0x80
 [<ffffffff8107f880>] __setup_irq+0x190/0x360
 [<ffffffff8107fa7a>] setup_irq+0x2a/0x40
 [<ffffffff81aaee42>] setup_default_timer_irq+0x12/0x20
 [<ffffffff81aaee67>] hpet_time_init+0x17/0x20
 [<ffffffff81aaee1a>] x86_late_time_init+0xa/0x20
 [<ffffffff81aade53>] start_kernel+0x2c3/0x380
 [<ffffffff81aad28b>] x86_64_start_reservations+0x9b/0xb0
 [<ffffffff81aad391>] x86_64_start_kernel+0xf1/0x120
Fast TSC calibration using PIT
Detected 2144.644 MHz processor.
Calibrating delay loop (skipped), value calculated using timer frequency.. 4291.00 BogoMIPS (lpj=7148813)
Mount-cache hash table entries: 256
tseg: 0000000000
CPU: Physical Processor ID: 0
CPU: Processor Core ID: 0
mce: CPU supports 5 MCE banks
Performance Events: AMD PMU driver.
...

This machine is uniprocessor, the kernel is not built with SMP support.
Comment 1 Christian Casteyde 2010-03-31 20:03:39 UTC
Still present in -rc3, but with a somewhat different call stack:

===================================================
[ INFO: suspicious rcu_dereference_check() usage. ]
---------------------------------------------------
net/netfilter/nf_log.c:55 invoked rcu_dereference_check() without protection!

other info that might help us debug this:


rcu_scheduler_active = 1, debug_locks = 0
1 lock held by swapper/1:
 #0:  (nf_log_mutex){+.+...}, at: [<ffffffff814794f7>] nf_log_register+0x57/0x130

stack backtrace:
Pid: 1, comm: swapper Not tainted 2.6.34-rc3 #3
Call Trace:
 [<ffffffff8105e058>] lockdep_rcu_dereference+0xb8/0xc0
 [<ffffffff81ac8349>] ? log_tg_init+0x0/0x29
 [<ffffffff814795b0>] nf_log_register+0x110/0x130
 [<ffffffff81ac8349>] ? log_tg_init+0x0/0x29
 [<ffffffff81ac836e>] log_tg_init+0x25/0x29
 [<ffffffff810001c7>] do_one_initcall+0x37/0x190
 [<ffffffff81a9e5bd>] kernel_init+0xe0/0x16c
 [<ffffffff815a3152>] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [<ffffffff81003074>] kernel_thread_helper+0x4/0x10
 [<ffffffff815a40fe>] ? restore_args+0x0/0x30
 [<ffffffff81a9e4dd>] ? kernel_init+0x0/0x16c
 [<ffffffff81003070>] ? kernel_thread_helper+0x0/0x10

Maybe it's not the same bug, I dont' know...
Comment 2 Christian Casteyde 2010-04-13 22:04:34 UTC
Update: Still present in -rc4, with the same call stack as in comment #1:

===================================================
[ INFO: suspicious rcu_dereference_check() usage. ]
---------------------------------------------------
net/netfilter/nf_log.c:55 invoked rcu_dereference_check() without protection!

other info that might help us debug this:


rcu_scheduler_active = 1, debug_locks = 0
1 lock held by swapper/1:
 #0:  (nf_log_mutex){+.+...}, at: [<ffffffff814799e7>] nf_log_register+0x57/0x130

stack backtrace:
Pid: 1, comm: swapper Not tainted 2.6.34-rc4 #1
Call Trace:
 [<ffffffff8105e2e8>] lockdep_rcu_dereference+0xb8/0xc0
 [<ffffffff81ac83b9>] ? log_tg_init+0x0/0x29
 [<ffffffff81479aa0>] nf_log_register+0x110/0x130
 [<ffffffff81ac83b9>] ? log_tg_init+0x0/0x29
 [<ffffffff81ac83de>] log_tg_init+0x25/0x29
 [<ffffffff810001c7>] do_one_initcall+0x37/0x190
 [<ffffffff81a9e5bd>] kernel_init+0xe0/0x16c
 [<ffffffff815a36e2>] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [<ffffffff81003074>] kernel_thread_helper+0x4/0x10
 [<ffffffff815a467e>] ? restore_args+0x0/0x30

It may be another bug, so maybe I should report it separatly.
Comment 3 Christian Casteyde 2010-04-13 22:29:39 UTC
I'm quite convinced it's not the same bug, I didn't managed to get the initial call stack anymore, but the new warning is always triggered.
I'm opening another bug to trace it, and I'm closing this one.

Note You need to log in before you can comment on or make changes to this bug.