[RFC] MIPS: smp: Sleeping func called from start_secondary()

[RFC] MIPS: smp: Sleeping func called from start_secondary()

[Serge Semin]

Hi folks,

To debug some another problem I recently enabled the
CONFIG_DEBUG_ATOMIC_SLEEP config for my SoC based on the 2xP5600 cores
with MIPS GIC as IRQ-controller. That caused the next BUG backtrace
started being printed to the system log during the device boot-up:

[    0.118053] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:283
[    0.118062] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 0, name: swapper/1
[    0.118069] preempt_count: 1, expected: 0
[    0.118074] RCU nest depth: 0, expected: 0
[    0.118078] Preemption disabled at:
[    0.118082] [<80105040>] arch_dup_task_struct+0x20/0x118
[    0.118116] CPU: 1 UID: 0 PID: 0 Comm: swapper/1 Not tainted 6.11.0-rc1-bt1-00312-gca6f9469050c-dirty #2460
[    0.118134] Stack : 816d0000 801b89bc 81870000 00000004 a02d0c08 00000000 84ae7dcc 801b84c0
[    0.118167]         00000000 00000002 00000000 00000000 00000000 00000001 84ae7d70 84aaf200
[    0.118195]         00000000 00000000 81115acc 00000000 00000059 84ae7bec 00000000 00000000
[    0.118222]         00000000 ffffffff ffffffea 00000020 816d0000 00000000 81115acc 00000002
[    0.118250]         00000000 04240021 a02d0c08 00000000 00000000 00000000 30400000 ac24242a
[    0.118277]         ...
[    0.118286] Call Trace:
[    0.118289] [<8010af2c>] show_stack+0x88/0x120
[    0.118309] [<80f09dfc>] dump_stack_lvl+0x78/0xb0
[    0.118323] [<801778d0>] __might_resched+0x190/0x1f0
[    0.118349] [<80f10f80>] mutex_lock+0x20/0x74
[    0.118365] [<801c8590>] irq_create_mapping_affinity+0x48/0x104
[    0.118390] [<801121ec>] r4k_clockevent_init+0x58/0x38c
[    0.118402] [<80116658>] start_secondary+0x34/0x134
[    0.118411] [<80f0b1e4>] smp_bootstrap+0x68/0x98
[    0.118424] 

I managed to investigate the problem a bit and the reason turned out to be
in the irq_create_mapping() method eventually invoked in the framework of the
secondary CPU start-up procedure. The more detailed calls chain is:
start_secondary()
+-> mips_clockevent_init()
    +-> r4k_clockevent_init()
        +-> get_c0_compare_int()
            +-> gic_get_c0_compare_int()
                +-> irq_create_mapping()
                    +-> irq_create_mapping_affinity()
                        +-> mutex_lock()
                            +-> might_sleep()
                                +-> might_resched()
                                    +-> __might_resched()
                                        +-> Print the log above

I currently lack of free time for further investigation in an attempt to
find a reasonable solution. So here is just a report and a short summary
of the problem. Should you have any idea of how to fix the problem I'll be
very glad to test it out on a short notice.

-Serge(y)

Re: [RFC] MIPS: smp: Sleeping func called from start_secondary()

[Jiaxun Yang]

在2024年8月2日八月 下午4:45，Serge Semin写道：
> Hi folks,
>
> To debug some another problem I recently enabled the
> CONFIG_DEBUG_ATOMIC_SLEEP config for my SoC based on the 2xP5600 cores
> with MIPS GIC as IRQ-controller. That caused the next BUG backtrace
> started being printed to the system log during the device boot-up:

Hi Serge,

Thanks for reporting the problem!

I actually have a patch lying around somewhere to convert cevt-r4k to use CPUHP
interface and avoid requesting interrupt on secondary CPUs.

Will post after getting more platform tests.

Thanks
- Jiaxun

>
> [    0.118053] BUG: sleeping function called from invalid context at 
> kernel/locking/mutex.c:283
> [    0.118062] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 
> 0, name: swapper/1
> [    0.118069] preempt_count: 1, expected: 0
> [    0.118074] RCU nest depth: 0, expected: 0
> [    0.118078] Preemption disabled at:
> [    0.118082] [<80105040>] arch_dup_task_struct+0x20/0x118
> [    0.118116] CPU: 1 UID: 0 PID: 0 Comm: swapper/1 Not tainted 
> 6.11.0-rc1-bt1-00312-gca6f9469050c-dirty #2460
> [    0.118134] Stack : 816d0000 801b89bc 81870000 00000004 a02d0c08 
> 00000000 84ae7dcc 801b84c0
> [    0.118167]         00000000 00000002 00000000 00000000 00000000 
> 00000001 84ae7d70 84aaf200
> [    0.118195]         00000000 00000000 81115acc 00000000 00000059 
> 84ae7bec 00000000 00000000
> [    0.118222]         00000000 ffffffff ffffffea 00000020 816d0000 
> 00000000 81115acc 00000002
> [    0.118250]         00000000 04240021 a02d0c08 00000000 00000000 
> 00000000 30400000 ac24242a
> [    0.118277]         ...
> [    0.118286] Call Trace:
> [    0.118289] [<8010af2c>] show_stack+0x88/0x120
> [    0.118309] [<80f09dfc>] dump_stack_lvl+0x78/0xb0
> [    0.118323] [<801778d0>] __might_resched+0x190/0x1f0
> [    0.118349] [<80f10f80>] mutex_lock+0x20/0x74
> [    0.118365] [<801c8590>] irq_create_mapping_affinity+0x48/0x104
> [    0.118390] [<801121ec>] r4k_clockevent_init+0x58/0x38c
> [    0.118402] [<80116658>] start_secondary+0x34/0x134
> [    0.118411] [<80f0b1e4>] smp_bootstrap+0x68/0x98
> [    0.118424] 
>
> I managed to investigate the problem a bit and the reason turned out to be
> in the irq_create_mapping() method eventually invoked in the framework of the
> secondary CPU start-up procedure. The more detailed calls chain is:
> start_secondary()
> +-> mips_clockevent_init()
>     +-> r4k_clockevent_init()
>         +-> get_c0_compare_int()
>             +-> gic_get_c0_compare_int()
>                 +-> irq_create_mapping()
>                     +-> irq_create_mapping_affinity()
>                         +-> mutex_lock()
>                             +-> might_sleep()
>                                 +-> might_resched()
>                                     +-> __might_resched()
>                                         +-> Print the log above
>
> I currently lack of free time for further investigation in an attempt to
> find a reasonable solution. So here is just a report and a short summary
> of the problem. Should you have any idea of how to fix the problem I'll be
> very glad to test it out on a short notice.
>
> -Serge(y)

-- 
- Jiaxun

Re: [RFC] MIPS: smp: Sleeping func called from start_secondary()

[Serge Semin]

Hi Jiaxun

On Fri, Aug 02, 2024 at 05:43:45PM +0800, Jiaxun Yang wrote:
> 
> 
> 在2024年8月2日八月 下午4:45，Serge Semin写道：
> > Hi folks,
> >
> > To debug some another problem I recently enabled the
> > CONFIG_DEBUG_ATOMIC_SLEEP config for my SoC based on the 2xP5600 cores
> > with MIPS GIC as IRQ-controller. That caused the next BUG backtrace
> > started being printed to the system log during the device boot-up:
> 
> Hi Serge,
> 
> Thanks for reporting the problem!
> 
> I actually have a patch lying around somewhere to convert cevt-r4k to use CPUHP
> interface and avoid requesting interrupt on secondary CPUs.
> 
> Will post after getting more platform tests.

Great! Thanks. I'll test it out upon submission.

* Although I doubt that such (presumably) complicated change might be
considered as a backportable fix. But at least it shall fix the problem for the
mainline kernel.

Thanks,
-Serge(y)

> 
> Thanks
> - Jiaxun
> 
> >
> > [    0.118053] BUG: sleeping function called from invalid context at 
> > kernel/locking/mutex.c:283
> > [    0.118062] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 
> > 0, name: swapper/1
> > [    0.118069] preempt_count: 1, expected: 0
> > [    0.118074] RCU nest depth: 0, expected: 0
> > [    0.118078] Preemption disabled at:
> > [    0.118082] [<80105040>] arch_dup_task_struct+0x20/0x118
> > [    0.118116] CPU: 1 UID: 0 PID: 0 Comm: swapper/1 Not tainted 
> > 6.11.0-rc1-bt1-00312-gca6f9469050c-dirty #2460
> > [    0.118134] Stack : 816d0000 801b89bc 81870000 00000004 a02d0c08 
> > 00000000 84ae7dcc 801b84c0
> > [    0.118167]         00000000 00000002 00000000 00000000 00000000 
> > 00000001 84ae7d70 84aaf200
> > [    0.118195]         00000000 00000000 81115acc 00000000 00000059 
> > 84ae7bec 00000000 00000000
> > [    0.118222]         00000000 ffffffff ffffffea 00000020 816d0000 
> > 00000000 81115acc 00000002
> > [    0.118250]         00000000 04240021 a02d0c08 00000000 00000000 
> > 00000000 30400000 ac24242a
> > [    0.118277]         ...
> > [    0.118286] Call Trace:
> > [    0.118289] [<8010af2c>] show_stack+0x88/0x120
> > [    0.118309] [<80f09dfc>] dump_stack_lvl+0x78/0xb0
> > [    0.118323] [<801778d0>] __might_resched+0x190/0x1f0
> > [    0.118349] [<80f10f80>] mutex_lock+0x20/0x74
> > [    0.118365] [<801c8590>] irq_create_mapping_affinity+0x48/0x104
> > [    0.118390] [<801121ec>] r4k_clockevent_init+0x58/0x38c
> > [    0.118402] [<80116658>] start_secondary+0x34/0x134
> > [    0.118411] [<80f0b1e4>] smp_bootstrap+0x68/0x98
> > [    0.118424] 
> >
> > I managed to investigate the problem a bit and the reason turned out to be
> > in the irq_create_mapping() method eventually invoked in the framework of the
> > secondary CPU start-up procedure. The more detailed calls chain is:
> > start_secondary()
> > +-> mips_clockevent_init()
> >     +-> r4k_clockevent_init()
> >         +-> get_c0_compare_int()
> >             +-> gic_get_c0_compare_int()
> >                 +-> irq_create_mapping()
> >                     +-> irq_create_mapping_affinity()
> >                         +-> mutex_lock()
> >                             +-> might_sleep()
> >                                 +-> might_resched()
> >                                     +-> __might_resched()
> >                                         +-> Print the log above
> >
> > I currently lack of free time for further investigation in an attempt to
> > find a reasonable solution. So here is just a report and a short summary
> > of the problem. Should you have any idea of how to fix the problem I'll be
> > very glad to test it out on a short notice.
> >
> > -Serge(y)
> 
> -- 
> - Jiaxun

Re: [RFC] MIPS: smp: Sleeping func called from start_secondary()

[Jiaxun Yang]

在2024年8月2日八月 上午10:53，Serge Semin写道：
> Hi Jiaxun
>
> On Fri, Aug 02, 2024 at 05:43:45PM +0800, Jiaxun Yang wrote:
>> 
>> 
>> 在2024年8月2日八月 下午4:45，Serge Semin写道：
>> > Hi folks,
>> >
>> > To debug some another problem I recently enabled the
>> > CONFIG_DEBUG_ATOMIC_SLEEP config for my SoC based on the 2xP5600 cores
>> > with MIPS GIC as IRQ-controller. That caused the next BUG backtrace
>> > started being printed to the system log during the device boot-up:
>> 
>> Hi Serge,
>> 
>> Thanks for reporting the problem!
>> 
>> I actually have a patch lying around somewhere to convert cevt-r4k to use CPUHP
>> interface and avoid requesting interrupt on secondary CPUs.
>> 
>> Will post after getting more platform tests.
>
> Great! Thanks. I'll test it out upon submission.
>
> * Although I doubt that such (presumably) complicated change might be
> considered as a backportable fix. But at least it shall fix the problem for the
> mainline kernel.

It's actually harder than I expected, as managing it with percpu interrupt API would
break system sharing PCI with TI.

Maybe we need to come up a driver handle IRQ MUX.

Avoid calling get_c0_compare_int on secondary CPU init is easy, will post a patch.

Thanks

>
> Thanks,
> -Serge(y)
>
>> 
>> Thanks
>> - Jiaxun
>> 
>> >
>> > [    0.118053] BUG: sleeping function called from invalid context at 
>> > kernel/locking/mutex.c:283
>> > [    0.118062] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 
>> > 0, name: swapper/1
>> > [    0.118069] preempt_count: 1, expected: 0
>> > [    0.118074] RCU nest depth: 0, expected: 0
>> > [    0.118078] Preemption disabled at:
>> > [    0.118082] [<80105040>] arch_dup_task_struct+0x20/0x118
>> > [    0.118116] CPU: 1 UID: 0 PID: 0 Comm: swapper/1 Not tainted 
>> > 6.11.0-rc1-bt1-00312-gca6f9469050c-dirty #2460
>> > [    0.118134] Stack : 816d0000 801b89bc 81870000 00000004 a02d0c08 
>> > 00000000 84ae7dcc 801b84c0
>> > [    0.118167]         00000000 00000002 00000000 00000000 00000000 
>> > 00000001 84ae7d70 84aaf200
>> > [    0.118195]         00000000 00000000 81115acc 00000000 00000059 
>> > 84ae7bec 00000000 00000000
>> > [    0.118222]         00000000 ffffffff ffffffea 00000020 816d0000 
>> > 00000000 81115acc 00000002
>> > [    0.118250]         00000000 04240021 a02d0c08 00000000 00000000 
>> > 00000000 30400000 ac24242a
>> > [    0.118277]         ...
>> > [    0.118286] Call Trace:
>> > [    0.118289] [<8010af2c>] show_stack+0x88/0x120
>> > [    0.118309] [<80f09dfc>] dump_stack_lvl+0x78/0xb0
>> > [    0.118323] [<801778d0>] __might_resched+0x190/0x1f0
>> > [    0.118349] [<80f10f80>] mutex_lock+0x20/0x74
>> > [    0.118365] [<801c8590>] irq_create_mapping_affinity+0x48/0x104
>> > [    0.118390] [<801121ec>] r4k_clockevent_init+0x58/0x38c
>> > [    0.118402] [<80116658>] start_secondary+0x34/0x134
>> > [    0.118411] [<80f0b1e4>] smp_bootstrap+0x68/0x98
>> > [    0.118424] 
>> >
>> > I managed to investigate the problem a bit and the reason turned out to be
>> > in the irq_create_mapping() method eventually invoked in the framework of the
>> > secondary CPU start-up procedure. The more detailed calls chain is:
>> > start_secondary()
>> > +-> mips_clockevent_init()
>> >     +-> r4k_clockevent_init()
>> >         +-> get_c0_compare_int()
>> >             +-> gic_get_c0_compare_int()
>> >                 +-> irq_create_mapping()
>> >                     +-> irq_create_mapping_affinity()
>> >                         +-> mutex_lock()
>> >                             +-> might_sleep()
>> >                                 +-> might_resched()
>> >                                     +-> __might_resched()
>> >                                         +-> Print the log above
>> >
>> > I currently lack of free time for further investigation in an attempt to
>> > find a reasonable solution. So here is just a report and a short summary
>> > of the problem. Should you have any idea of how to fix the problem I'll be
>> > very glad to test it out on a short notice.
>> >
>> > -Serge(y)
>> 
>> -- 
>> - Jiaxun

-- 
- Jiaxun