search

linuxppc / issues

Issues repository for linuxppc
5 stars 0 forks source link

IMC PMU uses mutex with IRQs disabled #425

Open mpe opened 2 years ago

mpe commented 2 years ago

The IMC PMU code uses a mutex lock in interrupt disabled sections.

With PROVE_LOCKING and DEBUG_ATOMIC_SLEEP we see:

[51761.098408] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:580
[51761.098458] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 513827, name: perf-exec
[51761.098498] preempt_count: 2, expected: 0
[51761.098528] INFO: lockdep is turned off.
[51761.098566] irq event stamp: 0
[51761.098592] hardirqs last  enabled at (0): [<0000000000000000>] 0x0
[51761.098648] hardirqs last disabled at (0): [<c00000000013673c>] copy_process+0xebc/0x31c0
[51761.098701] softirqs last  enabled at (0): [<c00000000013673c>] copy_process+0xebc/0x31c0
[51761.098752] softirqs last disabled at (0): [<0000000000000000>] 0x0
[51761.098791] CPU: 32 PID: 513827 Comm: perf-exec Tainted: G   M               6.0.0-rc1-02077-g47c7fcd4f28e #1
[51761.098863] Call Trace:
[51761.098890] [c0000003b2a472a0] [c000000000c386a0] dump_stack_lvl+0xb4/0x100 (unreliable)
[51761.098960] [c0000003b2a472f0] [c0000000001a85f4] __might_resched+0x3c4/0x3f0
[51761.099003] [c0000003b2a47380] [c00000000202d528] __mutex_lock+0x78/0x700
[51761.099054] [c0000003b2a47490] [c000000000124eb0] thread_imc_event_add+0x120/0x2c0
[51761.099108] [c0000003b2a47530] [c0000000004d89ec] event_sched_in+0x1ac/0x5e0
[51761.099160] [c0000003b2a475b0] [c0000000004e0924] merge_sched_in+0x484/0x7b0
[51761.099212] [c0000003b2a47620] [c0000000004e0f98] visit_groups_merge.constprop.0.isra.0+0x348/0x800
[51761.099262] [c0000003b2a47720] [c0000000004e17ac] ctx_sched_in+0x35c/0x400
[51761.099314] [c0000003b2a477b0] [c0000000004e1a14] ctx_resched+0x104/0x1f0
[51761.099366] [c0000003b2a47810] [c0000000004eea44] perf_event_exec+0x714/0x960
[51761.099435] [c0000003b2a478e0] [c0000000006b24f8] begin_new_exec+0xd28/0x1950
[51761.099489] [c0000003b2a47a00] [c000000000779ed8] load_elf_binary+0xc48/0x27e0
[51761.099558] [c0000003b2a47b50] [c0000000006b021c] bprm_execve+0x52c/0xeb0
[51761.099639] [c0000003b2a47c70] [c0000000006b0e3c] do_execveat_common+0x29c/0x410
[51761.099707] [c0000003b2a47d30] [c0000000006b0ff8] sys_execve+0x48/0x60
[51761.099757] [c0000003b2a47d70] [c000000000037c8c] system_call_exception+0x23c/0x580
[51761.099809] [c0000003b2a47e10] [c00000000000c168] system_call_vectored_common+0xe8/0x278
[51761.099875] --- interrupt: 3000 at 0x7ffff751d50c
[51761.099915] NIP:  00007ffff751d50c LR: 0000000000000000 CTR: 0000000000000000
[51761.099968] REGS: c0000003b2a47e80 TRAP: 3000   Tainted: G   M                (6.0.0-rc1-02077-g47c7fcd4f28e)
[51761.100028] MSR:  900000000280f033 <SF,HV,VEC,VSX,EE,PR,FP,ME,IR,DR,RI,LE>  CR: 48824486  XER: 00000000
[51761.100133] IRQMASK: 0 
               GPR00: 000000000000000b 00007fffffff9b30 00007ffff7666f00 00007fffffff9b80 
               GPR04: 00007ffffffff570 00000000104729d0 0000000065656c73 0000000000000070 
               GPR08: 0000000010472db0 0000000000000000 0000000000000000 0000000000000000 
               GPR12: 0000000000000000 00007ffff7ffcb40 00000000103f1010 0000000000000000 
               GPR16: 00000000100366e0 000000001029d588 0000000010477c90 000000000000002f 
               GPR20: 00007fffffff9b80 0000000000000000 00007ffff7ff5b80 0000000000000008 
               GPR24: 0000000000000006 0000000000000096 00007ffffffff570 00000000104729d0 
               GPR28: 0000000010472db7 fffffffffffffff8 00007ffffffff89a 0000000000100000 
[51761.100572] NIP [00007ffff751d50c] 0x7ffff751d50c
[51761.100612] LR [0000000000000000] 0x0
[51761.100651] --- interrupt: 3000
[51761.102270] ------------[ cut here ]------------
[51761.102302] do not call blocking ops when !TASK_RUNNING; state=1 set at [<00000000ae1ed2e5>] do_nanosleep+0xa0/0x440
[51761.102360] WARNING: CPU: 32 PID: 513827 at kernel/sched/core.c:9815 __might_sleep+0xf8/0x100
[51761.102414] Modules linked in: input_leds evdev led_class usbhid
[51761.102482] CPU: 32 PID: 513827 Comm: sleep Tainted: G   M    W          6.0.0-rc1-02077-g47c7fcd4f28e #1
[51761.102526] NIP:  c0000000001a8718 LR: c0000000001a8714 CTR: 0000000000000000
[51761.102580] REGS: c0000003b2a472a0 TRAP: 0700   Tainted: G   M    W           (6.0.0-rc1-02077-g47c7fcd4f28e)
[51761.102649] MSR:  9000000000021033 <SF,HV,ME,IR,DR,RI,LE>  CR: 28004280  XER: 20040006
[51761.102726] CFAR: c00000000013b0cc IRQMASK: 1 
               GPR00: c0000000001a8714 c0000003b2a47540 c000000003c3ee00 0000000000000068 
               GPR04: 0000000000000004 0000000000000001 c00000000022b688 0000000000000001 
               GPR08: a80e000000000000 0000000000000003 0000000000000003 a80e000000000000 
               GPR12: c00e0001ffdb6644 c000000ffffbc000 0000000000000000 0000000000000000 
               GPR16: 0000000000000000 0000000ffbc20000 c0000000d79d6008 0000000000000001 
               GPR20: c000000014b9f040 c000000014b9f000 c00000000322cb10 c00000039e9b6b00 
               GPR24: 0000000ffbc20000 c0000000020d60e0 0000000000000000 c000000000124bd0 
               GPR28: 0000000000000001 0000000000000244 c0000000020d6480 c00000039e9b6b00 
[51761.103174] NIP [c0000000001a8718] __might_sleep+0xf8/0x100
[51761.103229] LR [c0000000001a8714] __might_sleep+0xf4/0x100
[51761.103283] Call Trace:
[51761.103318] [c0000003b2a47540] [c0000000001a8714] __might_sleep+0xf4/0x100 (unreliable)
[51761.103383] [c0000003b2a475d0] [c00000000202d528] __mutex_lock+0x78/0x700
[51761.103434] [c0000003b2a476e0] [c000000000124bd0] thread_imc_event_del+0x80/0x220
[51761.103486] [c0000003b2a47770] [c0000000004d9e1c] event_sched_out+0x1dc/0x640
[51761.103538] [c0000003b2a477d0] [c0000000004da348] group_sched_out.part.0+0xc8/0x1d0
[51761.103592] [c0000003b2a47820] [c0000000004dc34c] ctx_sched_out+0x4fc/0x5b0
[51761.103644] [c0000003b2a478a0] [c0000000004e3cdc] __perf_event_task_sched_out+0x3fc/0xef0
[51761.103700] [c0000003b2a479a0] [c000000002028d8c] __schedule+0xc1c/0x1600
[51761.103753] [c0000003b2a47aa0] [c00000000202983c] schedule+0xcc/0x1e0
[51761.103804] [c0000003b2a47b20] [c000000002035170] do_nanosleep+0x130/0x440
[51761.103898] [c0000003b2a47be0] [c0000000002adff0] hrtimer_nanosleep+0x140/0x3c0
[51761.104007] [c0000003b2a47ca0] [c0000000002bcfdc] common_nsleep+0x8c/0xf0
[51761.104096] [c0000003b2a47cf0] [c0000000002bf8d0] sys_clock_nanosleep+0x150/0x200
[51761.104195] [c0000003b2a47d70] [c000000000037c8c] system_call_exception+0x23c/0x580
[51761.104301] [c0000003b2a47e10] [c00000000000c168] system_call_vectored_common+0xe8/0x278
[51761.104431] --- interrupt: 3000 at 0x7ffff7d14954
[51761.104495] NIP:  00007ffff7d14954 LR: 0000000000000000 CTR: 0000000000000000
[51761.104686] REGS: c0000003b2a47e80 TRAP: 3000   Tainted: G   M    W           (6.0.0-rc1-02077-g47c7fcd4f28e)
[51761.104826] MSR:  900000000280f033 <SF,HV,VEC,VSX,EE,PR,FP,ME,IR,DR,RI,LE>  CR: 48002284  XER: 00000000
[51761.105011] IRQMASK: 0 
               GPR00: 00000000000000f8 00007fffffffeef0 00007ffff7e66f00 0000000000000000 
               GPR04: 0000000000000000 00007fffffffef88 00007fffffffefe8 0000000000000000 
               GPR08: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
               GPR12: 0000000000000000 00007ffff7ffa460 0000000000000000 0000000000000000 
               GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
               GPR20: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
               GPR24: 0000000100001c50 00007ffffffff550 000000010001fa70 00007ffff7fef6d8 
               GPR28: 00007fffffffef88 00007fffffffefe8 00000000001fa400 0000000000000000 
[51761.106083] NIP [00007ffff7d14954] 0x7ffff7d14954
[51761.106151] LR [0000000000000000] 0x0
[51761.106194] --- interrupt: 3000
[51761.106256] Instruction dump:
[51761.106316] e8bf1620 e8610068 f8a10068 4849ee65 60000000 3c62fe49 e8df1620 7b840020 
[51761.106508] e8a10068 3863da40 4bf92955 60000000 <0fe00000> 60420000 3c4c03a9 384266e0 
[51761.106682] irq event stamp: 0
[51761.106723] hardirqs last  enabled at (0): [<0000000000000000>] 0x0
[51761.106822] hardirqs last disabled at (0): [<c00000000013673c>] copy_process+0xebc/0x31c0
[51761.106942] softirqs last  enabled at (0): [<c00000000013673c>] copy_process+0xebc/0x31c0
[51761.107059] softirqs last disabled at (0): [<0000000000000000>] 0x0
[51761.107168] ---[ end trace 0000000000000000 ]---
[51766.103541] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:580
[51766.103582] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 513827, name: sleep
[51766.103614] preempt_count: 4, expected: 0
[51766.103645] INFO: lockdep is turned off.
[51766.103674] irq event stamp: 0
[51766.103692] hardirqs last  enabled at (0): [<0000000000000000>] 0x0
[51766.103729] hardirqs last disabled at (0): [<c00000000013673c>] copy_process+0xebc/0x31c0
[51766.103799] softirqs last  enabled at (0): [<c00000000013673c>] copy_process+0xebc/0x31c0
[51766.103861] softirqs last disabled at (0): [<0000000000000000>] 0x0
[51766.103907] CPU: 32 PID: 513827 Comm: sleep Tainted: G   M    W          6.0.0-rc1-02077-g47c7fcd4f28e #1
[51766.103979] Call Trace:
[51766.104005] [c0000003b2a47310] [c000000000c386a0] dump_stack_lvl+0xb4/0x100 (unreliable)
[51766.104064] [c0000003b2a47360] [c0000000001a85f4] __might_resched+0x3c4/0x3f0
[51766.104109] [c0000003b2a473f0] [c00000000202d528] __mutex_lock+0x78/0x700
[51766.104160] [c0000003b2a47500] [c000000000124eb0] thread_imc_event_add+0x120/0x2c0
[51766.104214] [c0000003b2a475a0] [c0000000004d89ec] event_sched_in+0x1ac/0x5e0
[51766.104266] [c0000003b2a47620] [c0000000004e0924] merge_sched_in+0x484/0x7b0
[51766.104310] [c0000003b2a47690] [c0000000004e0f98] visit_groups_merge.constprop.0.isra.0+0x348/0x800
[51766.104370] [c0000003b2a47790] [c0000000004e17ac] ctx_sched_in+0x35c/0x400
[51766.104423] [c0000003b2a47820] [c0000000004e2b7c] __perf_event_task_sched_in+0x31c/0x4a0
[51766.104479] [c0000003b2a478e0] [c0000000001ab62c] finish_task_switch.isra.0+0x3bc/0x5a0
[51766.104542] [c0000003b2a479a0] [c0000000020287b4] __schedule+0x644/0x1600
[51766.104586] [c0000003b2a47aa0] [c00000000202983c] schedule+0xcc/0x1e0
[51766.104630] [c0000003b2a47b20] [c000000002035170] do_nanosleep+0x130/0x440
[51766.104710] [c0000003b2a47be0] [c0000000002adff0] hrtimer_nanosleep+0x140/0x3c0
[51766.104749] [c0000003b2a47ca0] [c0000000002bcfdc] common_nsleep+0x8c/0xf0
[51766.104782] [c0000003b2a47cf0] [c0000000002bf8d0] sys_clock_nanosleep+0x150/0x200
[51766.104816] [c0000003b2a47d70] [c000000000037c8c] system_call_exception+0x23c/0x580
[51766.104903] [c0000003b2a47e10] [c00000000000c168] system_call_vectored_common+0xe8/0x278
[51766.104959] --- interrupt: 3000 at 0x7ffff7d14954
[51766.105000] NIP:  00007ffff7d14954 LR: 0000000000000000 CTR: 0000000000000000
[51766.105045] REGS: c0000003b2a47e80 TRAP: 3000   Tainted: G   M    W           (6.0.0-rc1-02077-g47c7fcd4f28e)
[51766.105114] MSR:  900000000280f033 <SF,HV,VEC,VSX,EE,PR,FP,ME,IR,DR,RI,LE>  CR: 48002284  XER: 00000000
[51766.105211] IRQMASK: 0 
               GPR00: 00000000000000f8 00007fffffffeef0 00007ffff7e66f00 0000000000000000 
               GPR04: 0000000000000000 00007fffffffef88 00007fffffffefe8 0000000000000000 
               GPR08: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
               GPR12: 0000000000000000 00007ffff7ffa460 0000000000000000 0000000000000000 
               GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
               GPR20: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
               GPR24: 0000000100001c50 00007ffffffff550 000000010001fa70 00007ffff7fef6d8 
               GPR28: 00007fffffffef88 00007fffffffefe8 00000000001fa400 0000000000000000 
[51766.105677] NIP [00007ffff7d14954] 0x7ffff7d14954
[51766.105717] LR [0000000000000000] 0x0
[51766.105747] --- interrupt: 3000

Triggered by:

$ sudo ./perf stat -e thread_imc/CPM_TLBIE/ sleep 5

It may be as simple as turning ref->lock into a spinlock, but it will need testing.

kjain101 commented 2 years ago

I am able to recreate and understand how we are getting this issue incase PROVE_LOCKING and DEBUG_ATOMIC_SLEEP config options are enabled, as mentioned in the issue summary. When DEBUG_ATOMIC_SLEEP is enabled, mutex_lock internally calls "__might_resched" function, which will check if irq is disabled or not. Incase irq is disabled, it will trigger the warning pointed in the issue summary. Current IMC PMU code uses a mutex_lock in irq disabled section, hence we are getting this warning. I am working on changing mutex lock to spinlock as suggested by Michael Ellerman and also checking on adding testcases to test these scenarios for 24x7/imc.