Hi Finn,
Am 30.03.2024 um 19:23 schrieb Finn Thain:
On Sat, 30 Mar 2024, Michael Schmitz wrote:
The MFP timer C is not reentered in 66 boots even though I've seen it
appear in the stack trace of 8 recursion warnings.
The spinlock recursion warning gives the address of the spinlock. Did you
figure out which spinlock it is? Also, did you capture all 8 backtraces?
The lock is that in 'runqueues', the single struct rq in use on a single
processor system.
That much was clear from the backtrace and looking at the code in
scheduler_tick() before.
I've attached all eight backtraces - the stack contents only varies in a
few positions, mostly explainable by differences in the initial stack
pointer.
Cheers,
Michael
BUG: spinlock recursion on CPU#0, swapper/1
lock: 0x447600, .magic: dead4ead, .owner: swapper/1, .owner_cpu: 0
CPU: 0 PID: 1 Comm: swapper Not tainted 6.8.0-rc7-atari-fpuemu-spinlocktest+ #1775
Stack from 00831e98:
00831e98 003e766e 003e766e 00000000 0000000d 00335630 003e766e 0003aac6
00447600 003dc464 00830000 000321a6 00447600 0083c000 00831ee0 000321cc
00447600 00000000 00831eec 000335be 00814080 0003fdea 00055464 00002604
00006e16 00000000 00000000 0003fe5e 0000000d 00000000 00000000 00000000
00443048 0032c472 0047aa4c 0047aaa8 00000000 00000000 0003fef6 0047aa4c
00000000 0047aa4c 0003ff4e 0047aa4c 0047aaa8 0047aa4c 0047aaa8 0047aa4c
Call Trace: [<00335630>] dump_stack+0xc/0x10
[<0003aac6>] do_raw_spin_lock+0x34/0x58
[<000321a6>] raw_spin_rq_lock_nested+0x24/0x38
[<000321cc>] raw_spin_rq_lock.constprop.135+0x12/0x18
[<000335be>] scheduler_tick+0x10/0x66
[<0003fdea>] __irq_wake_thread+0x0/0x40
[<00055464>] update_process_times+0x5e/0x66
[<00002604>] ret_from_kernel_thread+0x4/0x14
[<00006e16>] mfp_timer_c_handler+0x5a/0x70
[<0003fe5e>] __handle_irq_event_percpu+0x34/0xbc
[<0032c472>] sprintf+0x0/0x24
[<0003fef6>] handle_irq_event_percpu+0x10/0x3a
[<0003ff4e>] handle_irq_event+0x2e/0x54
[<000424f6>] handle_simple_irq+0x56/0x66
[<00335976>] kernel_init+0x0/0xf2
[<0003fa00>] handle_irq_desc+0x1e/0x28
[<000028c0>] do_IRQ+0x20/0x32
[<000027f4>] user_irqvec_fixup+0xc/0x14
[<0032c472>] sprintf+0x0/0x24
[<00002600>] ret_from_kernel_thread+0x0/0x14
RCU Tasks: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
RCU Tasks Trace: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
--
BUG: spinlock recursion on CPU#0, pool_workqueue_/3
lock: 0x447600, .magic: dead4ead, .owner: pool_workqueue_/3, .owner_cpu: 0
CPU: 0 PID: 3 Comm: pool_workqueue_ Not tainted 6.8.0-rc7-atari-fpuemu-spinlocktest+ #1775
Stack from 00837e98:
00837e98 003e766e 003e766e 00000000 0000000d 00335630 003e766e 0003aac6
00447600 003dc464 00836000 000321a6 00447600 0083cc20 00837ee0 000321cc
00447600 00000000 00837eec 000335be 00814080 0003fdea 00055464 00002604
00006e16 00000000 00000000 0003fe5e 0000000d 00000000 00000000 00339ee0
0033a016 000183f2 0047aa4c 0047aaa8 00000000 00000000 0003fef6 0047aa4c
00000000 0047aa4c 0003ff4e 0047aa4c 0047aaa8 0047aa4c 0047aaa8 0047aa4c
Call Trace: [<00335630>] dump_stack+0xc/0x10
[<0003aac6>] do_raw_spin_lock+0x34/0x58
[<000321a6>] raw_spin_rq_lock_nested+0x24/0x38
[<000321cc>] raw_spin_rq_lock.constprop.135+0x12/0x18
[<000335be>] scheduler_tick+0x10/0x66
[<0003fdea>] __irq_wake_thread+0x0/0x40
[<00055464>] update_process_times+0x5e/0x66
[<00002604>] ret_from_kernel_thread+0x4/0x14
[<00006e16>] mfp_timer_c_handler+0x5a/0x70
[<0003fe5e>] __handle_irq_event_percpu+0x34/0xbc
[<00339ee0>] _raw_spin_lock+0x0/0x22
[<0033a016>] _raw_spin_unlock+0x0/0x32
[<000183f2>] kernel_thread+0x0/0x6c
[<0003fef6>] handle_irq_event_percpu+0x10/0x3a
[<0003ff4e>] handle_irq_event+0x2e/0x54
[<000424f6>] handle_simple_irq+0x56/0x66
[<0002de6e>] kthread+0x0/0xd4
[<0003fa00>] handle_irq_desc+0x1e/0x28
[<000028c0>] do_IRQ+0x20/0x32
[<000027f4>] user_irqvec_fixup+0xc/0x14
[<00339ee0>] _raw_spin_lock+0x0/0x22
[<0033a016>] _raw_spin_unlock+0x0/0x32
[<000183f2>] kernel_thread+0x0/0x6c
--
BUG: spinlock recursion on CPU#0, swapper/2
lock: 0x447600, .magic: dead4ead, .owner: swapper/2, .owner_cpu: 0
CPU: 0 PID: 2 Comm: swapper Not tainted 6.8.0-rc7-atari-fpuemu-spinlocktest+ #1775
Stack from 00835e98:
00835e98 003e766e 003e766e 00000000 0000000d 00335630 003e766e 0003aac6
00447600 003dc464 00834000 000321a6 00447600 0083c610 00835ee0 000321cc
00447600 00000000 00835eec 000335be 00814080 0003fdea 00055464 00002604
00006e16 00000000 00000000 0003fe5e 0000000d 00000000 00000000 00831f10
00000102 0032c472 0047aa4c 0047aaa8 00000000 00000000 0003fef6 0047aa4c
00000000 0047aa4c 0003ff4e 0047aa4c 0047aaa8 0047aa4c 0047aaa8 0047aa4c
Call Trace: [<00335630>] dump_stack+0xc/0x10
[<0003aac6>] do_raw_spin_lock+0x34/0x58
[<000321a6>] raw_spin_rq_lock_nested+0x24/0x38
[<000321cc>] raw_spin_rq_lock.constprop.135+0x12/0x18
[<000335be>] scheduler_tick+0x10/0x66
[<0003fdea>] __irq_wake_thread+0x0/0x40
[<00055464>] update_process_times+0x5e/0x66
[<00002604>] ret_from_kernel_thread+0x4/0x14
[<00006e16>] mfp_timer_c_handler+0x5a/0x70
[<0003fe5e>] __handle_irq_event_percpu+0x34/0xbc
[<0032c472>] sprintf+0x0/0x24
[<0003fef6>] handle_irq_event_percpu+0x10/0x3a
[<0003ff4e>] handle_irq_event+0x2e/0x54
[<000424f6>] handle_simple_irq+0x56/0x66
[<0002dfd2>] kthreadd+0x0/0x12a
[<0003fa00>] handle_irq_desc+0x1e/0x28
[<000028c0>] do_IRQ+0x20/0x32
[<000027f4>] user_irqvec_fixup+0xc/0x14
[<0032c472>] sprintf+0x0/0x24
[<00002600>] ret_from_kernel_thread+0x0/0x14
RCU Tasks: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
RCU Tasks Trace: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
--
BUG: spinlock recursion on CPU#0, swapper/2
lock: 0x447600, .magic: dead4ead, .owner: swapper/2, .owner_cpu: 0
CPU: 0 PID: 2 Comm: swapper Not tainted 6.8.0-rc7-atari-fpuemu-spinlocktest+ #1775
Stack from 00835e98:
00835e98 003e766e 003e766e 00000000 0000000d 00335630 003e766e 0003aac6
00447600 003dc464 00834000 000321a6 00447600 0083c610 00835ee0 000321cc
00447600 00000000 00835eec 000335be 00814080 0003fdea 00055464 00002604
00006e16 00000000 00000000 0003fe5e 0000000d 00000000 00000000 00831f10
00000102 0032c472 0047aa4c 0047aaa8 00000000 00000000 0003fef6 0047aa4c
00000000 0047aa4c 0003ff4e 0047aa4c 0047aaa8 0047aa4c 0047aaa8 0047aa4c
Call Trace: [<00335630>] dump_stack+0xc/0x10
[<0003aac6>] do_raw_spin_lock+0x34/0x58
[<000321a6>] raw_spin_rq_lock_nested+0x24/0x38
[<000321cc>] raw_spin_rq_lock.constprop.135+0x12/0x18
[<000335be>] scheduler_tick+0x10/0x66
[<0003fdea>] __irq_wake_thread+0x0/0x40
[<00055464>] update_process_times+0x5e/0x66
[<00002604>] ret_from_kernel_thread+0x4/0x14
[<00006e16>] mfp_timer_c_handler+0x5a/0x70
[<0003fe5e>] __handle_irq_event_percpu+0x34/0xbc
[<0032c472>] sprintf+0x0/0x24
[<0003fef6>] handle_irq_event_percpu+0x10/0x3a
[<0003ff4e>] handle_irq_event+0x2e/0x54
[<000424f6>] handle_simple_irq+0x56/0x66
[<0002dfd2>] kthreadd+0x0/0x12a
[<0003fa00>] handle_irq_desc+0x1e/0x28
[<000028c0>] do_IRQ+0x20/0x32
[<000027f4>] user_irqvec_fixup+0xc/0x14
[<0032c472>] sprintf+0x0/0x24
[<00002600>] ret_from_kernel_thread+0x0/0x14
RCU Tasks: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
RCU Tasks Trace: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
--
BUG: spinlock recursion on CPU#0, swapper/2
lock: 0x447600, .magic: dead4ead, .owner: swapper/2, .owner_cpu: 0
CPU: 0 PID: 2 Comm: swapper Not tainted 6.8.0-rc7-atari-fpuemu-spinlocktest+ #1775
Stack from 00835e98:
00835e98 003e766e 003e766e 00000000 0000000d 00335630 003e766e 0003aac6
00447600 003dc464 00834000 000321a6 00447600 0083c610 00835ee0 000321cc
00447600 00000000 00835eec 000335be 00814080 0003fdea 00055464 00002604
00006e16 00000000 00000000 0003fe5e 0000000d 00000000 00000000 00831f10
00000102 0032c472 0047aa4c 0047aaa8 00000000 00000000 0003fef6 0047aa4c
00000000 0047aa4c 0003ff4e 0047aa4c 0047aaa8 0047aa4c 0047aaa8 0047aa4c
Call Trace: [<00335630>] dump_stack+0xc/0x10
[<0003aac6>] do_raw_spin_lock+0x34/0x58
[<000321a6>] raw_spin_rq_lock_nested+0x24/0x38
[<000321cc>] raw_spin_rq_lock.constprop.135+0x12/0x18
[<000335be>] scheduler_tick+0x10/0x66
[<0003fdea>] __irq_wake_thread+0x0/0x40
[<00055464>] update_process_times+0x5e/0x66
[<00002604>] ret_from_kernel_thread+0x4/0x14
[<00006e16>] mfp_timer_c_handler+0x5a/0x70
[<0003fe5e>] __handle_irq_event_percpu+0x34/0xbc
[<0032c472>] sprintf+0x0/0x24
[<0003fef6>] handle_irq_event_percpu+0x10/0x3a
[<0003ff4e>] handle_irq_event+0x2e/0x54
[<000424f6>] handle_simple_irq+0x56/0x66
[<0002dfd2>] kthreadd+0x0/0x12a
[<0003fa00>] handle_irq_desc+0x1e/0x28
[<000028c0>] do_IRQ+0x20/0x32
[<000027f4>] user_irqvec_fixup+0xc/0x14
[<0032c472>] sprintf+0x0/0x24
[<00002600>] ret_from_kernel_thread+0x0/0x14
RCU Tasks: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
RCU Tasks Trace: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
--
BUG: spinlock recursion on CPU#0, pool_workqueue_/3
lock: 0x447600, .magic: dead4ead, .owner: pool_workqueue_/3, .owner_cpu: 0
CPU: 0 PID: 3 Comm: pool_workqueue_ Not tainted 6.8.0-rc7-atari-fpuemu-spinlocktest+ #1775
Stack from 00837e78:
00837e78 003e766e 003e766e 00000000 0000000d 00335630 003e766e 0003aac6
00447600 003dc464 00836000 000321a6 00447600 0083cc20 00837ec0 000321cc
00447600 00000000 00837ecc 000335be 00814080 0003fdea 00055464 00002604
00006e16 00000000 00000000 0003fe5e 0000000d 00000000 00000000 00339ee0
0033a016 000183f2 0047aa4c 0047aaa8 00000000 00837fb4 0003fef6 0047aa4c
00000000 0047aa4c 0003ff4e 0047aa4c 0047aaa8 0047aa4c 0047aaa8 0047aa4c
Call Trace: [<00335630>] dump_stack+0xc/0x10
[<0003aac6>] do_raw_spin_lock+0x34/0x58
[<000321a6>] raw_spin_rq_lock_nested+0x24/0x38
[<000321cc>] raw_spin_rq_lock.constprop.135+0x12/0x18
[<000335be>] scheduler_tick+0x10/0x66
[<0003fdea>] __irq_wake_thread+0x0/0x40
[<00055464>] update_process_times+0x5e/0x66
[<00002604>] ret_from_kernel_thread+0x4/0x14
[<00006e16>] mfp_timer_c_handler+0x5a/0x70
[<0003fe5e>] __handle_irq_event_percpu+0x34/0xbc
[<00339ee0>] _raw_spin_lock+0x0/0x22
[<0033a016>] _raw_spin_unlock+0x0/0x32
[<000183f2>] kernel_thread+0x0/0x6c
[<0003fef6>] handle_irq_event_percpu+0x10/0x3a
[<0003ff4e>] handle_irq_event+0x2e/0x54
[<000424f6>] handle_simple_irq+0x56/0x66
[<0003fa00>] handle_irq_desc+0x1e/0x28
[<000028c0>] do_IRQ+0x20/0x32
[<000027f4>] user_irqvec_fixup+0xc/0x14
[<00339ee0>] _raw_spin_lock+0x0/0x22
[<0033a016>] _raw_spin_unlock+0x0/0x32
[<000183f2>] kernel_thread+0x0/0x6c
[<0002de6e>] kthread+0x0/0xd4
--
BUG: spinlock recursion on CPU#0, swapper/1
lock: 0x447600, .magic: dead4ead, .owner: swapper/1, .owner_cpu: 0
CPU: 0 PID: 1 Comm: swapper Not tainted 6.8.0-rc7-atari-fpuemu-spinlocktest+ #1775
Stack from 00831e98:
00831e98 003e766e 003e766e 00000000 0000000d 00335630 003e766e 0003aac6
00447600 003dc464 00830000 000321a6 00447600 0083c000 00831ee0 000321cc
00447600 00000000 00831eec 000335be 00814080 0003fdea 00055464 00002604
00006e16 00000000 00000000 0003fe5e 0000000d 00000000 00000000 00000000
00443048 0032c472 0047aa4c 0047aaa8 00000000 00000000 0003fef6 0047aa4c
00000000 0047aa4c 0003ff4e 0047aa4c 0047aaa8 0047aa4c 0047aaa8 0047aa4c
Call Trace: [<00335630>] dump_stack+0xc/0x10
[<0003aac6>] do_raw_spin_lock+0x34/0x58
[<000321a6>] raw_spin_rq_lock_nested+0x24/0x38
[<000321cc>] raw_spin_rq_lock.constprop.135+0x12/0x18
[<000335be>] scheduler_tick+0x10/0x66
[<0003fdea>] __irq_wake_thread+0x0/0x40
[<00055464>] update_process_times+0x5e/0x66
[<00002604>] ret_from_kernel_thread+0x4/0x14
[<00006e16>] mfp_timer_c_handler+0x5a/0x70
[<0003fe5e>] __handle_irq_event_percpu+0x34/0xbc
[<0032c472>] sprintf+0x0/0x24
[<0003fef6>] handle_irq_event_percpu+0x10/0x3a
[<0003ff4e>] handle_irq_event+0x2e/0x54
[<000424f6>] handle_simple_irq+0x56/0x66
[<00335976>] kernel_init+0x0/0xf2
[<0003fa00>] handle_irq_desc+0x1e/0x28
[<000028c0>] do_IRQ+0x20/0x32
[<000027f4>] user_irqvec_fixup+0xc/0x14
[<0032c472>] sprintf+0x0/0x24
[<00002600>] ret_from_kernel_thread+0x0/0x14
RCU Tasks: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
RCU Tasks Trace: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
--
BUG: spinlock recursion on CPU#0, swapper/2
lock: 0x447600, .magic: dead4ead, .owner: swapper/2, .owner_cpu: 0
CPU: 0 PID: 2 Comm: swapper Not tainted 6.8.0-rc7-atari-fpuemu-spinlocktest+ #1775
Stack from 00835e98:
00835e98 003e766e 003e766e 00000000 0000000d 00335630 003e766e 0003aac6
00447600 003dc464 00834000 000321a6 00447600 0083c610 00835ee0 000321cc
00447600 00000000 00835eec 000335be 00814080 0003fdea 00055464 00002604
00006e16 00000000 00000000 0003fe5e 0000000d 00000000 00000000 00831f10
00000102 0032c472 0047aa4c 0047aaa8 00000000 00000000 0003fef6 0047aa4c
00000000 0047aa4c 0003ff4e 0047aa4c 0047aaa8 0047aa4c 0047aaa8 0047aa4c
Call Trace: [<00335630>] dump_stack+0xc/0x10
[<0003aac6>] do_raw_spin_lock+0x34/0x58
[<000321a6>] raw_spin_rq_lock_nested+0x24/0x38
[<000321cc>] raw_spin_rq_lock.constprop.135+0x12/0x18
[<000335be>] scheduler_tick+0x10/0x66
[<0003fdea>] __irq_wake_thread+0x0/0x40
[<00055464>] update_process_times+0x5e/0x66
[<00002604>] ret_from_kernel_thread+0x4/0x14
[<00006e16>] mfp_timer_c_handler+0x5a/0x70
[<0003fe5e>] __handle_irq_event_percpu+0x34/0xbc
[<0032c472>] sprintf+0x0/0x24
[<0003fef6>] handle_irq_event_percpu+0x10/0x3a
[<0003ff4e>] handle_irq_event+0x2e/0x54
[<000424f6>] handle_simple_irq+0x56/0x66
[<0002dfd2>] kthreadd+0x0/0x12a
[<0003fa00>] handle_irq_desc+0x1e/0x28
[<000028c0>] do_IRQ+0x20/0x32
[<000027f4>] user_irqvec_fixup+0xc/0x14
[<0032c472>] sprintf+0x0/0x24
[<00002600>] ret_from_kernel_thread+0x0/0x14
RCU Tasks: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
RCU Tasks Trace: Setting shift to 0 and lim to 1 rcu_task_cb_adjust=1.
