Re: spinlock recursion when running q800 emulation in qemu

[Michael Schmitz <schmitzmic@gmail.com>]

Hi Finn,

Am 15.03.2024 um 20:24 schrieb Finn Thain:
>
> On Fri, 15 Mar 2024, Michael Schmitz wrote:
>
>>
>> No luck with whatever I tried around signals, cache maintenance and mm.
>>
>> The 'BUG: Bad rss-counter state' message suggests we're freeing the same
>> page ranges twice, sometimes in many cases. I cannot quite see how
>> preempting the kernel on interupt return would cause this. Signal
>> forcing process exit but process exiting before signal is received due
>> to preemption? But skipping preemption when a signal is pending did not
>> change anything in my tests...
>>
>> Running out of ideas here, sorry.
>>
>
> FWIW, I found that the failure mode (with CONFIG_PREEMPT) changed
> significantly after I disabled hard irqs in do_IRQ() using the patch I
> sent on the 8th. In three stress-ng test runs, I got a soft lockup, a WARN
> from set_fc() and some CONFIG_DEBUG_LIST failures...

Yes, I do see that with your patch, too. I still see the old 'table 
already free' bug, though.

As far as I can see, the set_fc warning is from access_error040 and is 
part of the access error exception that is taken in interrupt context.

The question is basically - why is __free_one_page() called from 
interrupt context? Did that also happen before Geert's preemption patch?

preempt_schedule_irq() is currently called in both the interrupt and 
exception return code path. Maybe it should only be called on exception 
(i.e. syscall) return?

Cheers,

	Michael

> # /root/stress-ng -t 60 --zombie -1
> stress-ng: info:  [46] setting to a 60 second run per stressor
> stress-ng: info:  [46] dispatching hogs: 1 zombie
> [   29.670000] ------------[ cut here ]------------
> [   29.670000] WARNING: CPU: 0 PID: 0 at arch/m68k/include/asm/processor.h:92 buserr_c+0x486/0x5ba
> [   29.670000] Modules linked in:
> [   29.670000] CPU: 0 PID: 0 Comm: swapper Not tainted 6.8.0-rc7-mac-00234-g138ba0024ff0 #9
> [   29.670000] Stack from 00583c20:
> [   29.670000]         00583c20 0054af2c 0054af2c 00000000 006e0100 00583c40 004980b6 0054af2c
> [   29.670000]         00583c54 00492ff6 00000505 0059ff94 0b46005f 00583c84 0001c73e 0053a3bc
> [   29.670000]         0000005c 000061b6 00000009 00000000 00000000 00000505 00583cc8 00696ef0
> [   29.670000]         008dc490 00583cbc 000061b6 0053a3bc 0000005c 00000009 00000000 00000000
> [   29.670000]         006eee78 00002ff5 00000008 00000001 005b0b4c 006eee74 02d61260 00583d34
> [   29.670000]         000026b4 00583cc8 006eee78 00000000 006eee78 00002ff5 00000008 005b0b4c
> [   29.670000] Call Trace: [<004980b6>] dump_stack+0x10/0x16
> [   29.670000]  [<00492ff6>] __warn+0x90/0xb6
> [   29.670000]  [<0001c73e>] warn_slowpath_fmt+0x10e/0x1a4
> [   29.670000]  [<000061b6>] buserr_c+0x486/0x5ba
> [   29.670000]  [<000061b6>] buserr_c+0x486/0x5ba
> [   29.670000]  [<00002ff5>] __get_wchan+0x4d/0x58
> [   29.670000]  [<000026b4>] buserr+0x20/0x28
> [   29.670000]  [<00002ff5>] __get_wchan+0x4d/0x58
> [   29.670000]  [<000ea558>] __free_one_page+0x2ec/0x532
> [   29.670000]  [<000ea8bc>] free_pcppages_bulk+0x11e/0x18a
> [   29.670000]  [<00002ff5>] __get_wchan+0x4d/0x58
> [   29.670000]  [<00002700>] ret_from_kernel_thread+0xc/0x14
> [   29.670000]  [<000eaa86>] free_unref_page_commit+0x15e/0x314
> [   29.670000]  [<00002ce0>] show_regs+0x48/0xb8
> [   29.670000]  [<00002004>] _start+0x4/0x8
> [   29.670000]  [<000ed452>] free_unref_page+0x12a/0x190
> [   29.670000]  [<00065be4>] rcu_cblist_dequeue+0x0/0x28
> [   29.670000]  [<000ed648>] __free_pages+0xb4/0x10c
> [   29.670000]  [<00018340>] thread_stack_free_rcu+0x3a/0x44
> [   29.670000]  [<0006436c>] rcu_core+0x2c2/0x79e
> [   29.670000]  [<00054fda>] handle_irq_event+0x7a/0x90
> [   29.670000]  [<00064928>] rcu_core_si+0x8/0xc
> [   29.670000]  [<0049952c>] __do_softirq+0xa4/0x1f8
> [   29.670000]  [<00492600>] memmove+0x8c/0xe0
> [   29.670000]  [<00038196>] parse_args+0x0/0x3a6
> [   29.670000]  [<000485f8>] arch_cpu_idle_exit+0x0/0x8
> [   29.670000]  [<000485f0>] arch_cpu_idle_enter+0x0/0x8
> [   29.670000]  [<0001fee6>] irq_exit+0x44/0x4e
> [   29.670000]  [<00002986>] do_IRQ+0x32/0x6c
> [   29.670000]  [<00498cf8>] cpu_idle_poll.isra.0+0x0/0x6e
> [   29.670000]  [<00498d66>] default_idle_call+0x0/0x46
> [   29.670000]  [<00002874>] auto_irqhandler_fixup+0x4/0xc
> [   29.670000]  [<00498cf8>] cpu_idle_poll.isra.0+0x0/0x6e
> [   29.670000]  [<00498d66>] default_idle_call+0x0/0x46
> [   29.670000]  [<00498d88>] default_idle_call+0x22/0x46
> [   29.670000]  [<00048680>] do_idle+0x6a/0xf0
> [   29.670000]  [<00048616>] do_idle+0x0/0xf0
> [   29.670000]  [<00036742>] find_task_by_pid_ns+0x0/0x2a
> [   29.670000]  [<0005cfd4>] __rcu_read_lock+0x0/0x12
> [   29.670000]  [<000489cc>] cpu_startup_entry+0x1a/0x1c
> [   29.670000]  [<00063976>] __rcu_read_unlock+0x0/0x26
> [   29.670000]  [<00498e4a>] kernel_init+0x0/0xfa
> [   29.670000]  [<004897c0>] strcpy+0x0/0x1e
> [   29.670000]  [<0049379c>] _printk+0x0/0x16
> [   29.670000]  [<00489942>] strlen+0x0/0x22
> [   29.670000]  [<0062d2c6>] memblock_alloc_try_nid+0x0/0x82
> [   29.670000]  [<0062139a>] arch_post_acpi_subsys_init+0x0/0x8
> [   29.670000]  [<00621918>] console_on_rootfs+0x0/0x60
> [   29.670000]  [<00620410>] _sinittext+0x410/0xadc
> [   29.670000]
> [   29.670000] ---[ end trace 0000000000000000 ]---
> [   29.670000] Unable to handle kernel access at virtual address 0b46005f
> [   29.670000] Oops: 00000000
> [   29.670000] Modules linked in:
> [   29.670000] PC: [<002951de>] __list_add_valid_or_report+0x1a/0x102
> [   29.670000] SR: 2700  SP: 00583cc8  a2: 00587590
> [   29.670000] d0: 000007e0    d1: 006eee78    d2: 00000000    d3: 006eee78
> [   29.670000] d4: 00002ff5    d5: 00000008    a0: 005b0b4c    a1: 0b46005b
> [   29.670000] Process swapper (pid: 0, task=00587590)
> [   29.670000] Frame format=7 eff addr=0b46005f ssw=0505 faddr=0b46005f
> [   29.670000] wb 1 stat/addr/data: 0000 00000000 00000000
> [   29.670000] wb 2 stat/addr/data: 0000 00000000 00000000
> [   29.670000] wb 3 stat/addr/data: 0000 0b46005f 00000000
> [   29.670000] push data: 00000000 00000000 00000000 00000000
> [   29.670000] Stack from 00583d30:
> [   29.670000]         00000000 00583d6c 000ea558 006eee78 005b0b4c 0b46005b 007a5380 00000000
> [   29.670000]         0000000f 0000000c 00000005 00000001 006eee78 007a5358 005b2090 00583dc8
> [   29.670000]         000ea8bc 006eee74 00002ff5 005b0314 00000000 000000fc 00000000 00000f07
> [   29.670000]         00000003 000001ca 000000e0 00000001 006e307c 007a5358 005b0314 00000011
> [   29.670000]         006eee74 00000039 00002700 005b04fc 00000000 000000aa 00583e08 000eaa86
> [   29.670000]         005b0314 0000004e 007a5358 00000003 00000001 00002ce0 00000000 00000000
> [   29.670000] Call Trace: [<000ea558>] __free_one_page+0x2ec/0x532
> [   29.670000]  [<000ea8bc>] free_pcppages_bulk+0x11e/0x18a
> [   29.670000]  [<00002ff5>] __get_wchan+0x4d/0x58
> [   29.670000]  [<00002700>] ret_from_kernel_thread+0xc/0x14
> [   29.670000]  [<000eaa86>] free_unref_page_commit+0x15e/0x314
> [   29.670000]  [<00002ce0>] show_regs+0x48/0xb8
> [   29.670000]  [<00002004>] _start+0x4/0x8
> [   29.670000]  [<000ed452>] free_unref_page+0x12a/0x190
> [   29.670000]  [<00065be4>] rcu_cblist_dequeue+0x0/0x28
> [   29.670000]  [<000ed648>] __free_pages+0xb4/0x10c
> [   29.670000]  [<00018340>] thread_stack_free_rcu+0x3a/0x44
> [   29.670000]  [<0006436c>] rcu_core+0x2c2/0x79e
> [   29.670000]  [<00054fda>] handle_irq_event+0x7a/0x90
> [   29.670000]  [<00064928>] rcu_core_si+0x8/0xc
> [   29.670000]  [<0049952c>] __do_softirq+0xa4/0x1f8
> [   29.670000]  [<00492600>] memmove+0x8c/0xe0
> [   29.670000]  [<00038196>] parse_args+0x0/0x3a6
> [   29.670000]  [<000485f8>] arch_cpu_idle_exit+0x0/0x8
> [   29.670000]  [<000485f0>] arch_cpu_idle_enter+0x0/0x8
> [   29.670000]  [<0001fee6>] irq_exit+0x44/0x4e
> [   29.670000]  [<00002986>] do_IRQ+0x32/0x6c
> [   29.670000]  [<00498cf8>] cpu_idle_poll.isra.0+0x0/0x6e
> [   29.670000]  [<00498d66>] default_idle_call+0x0/0x46
> [   29.670000]  [<00002874>] auto_irqhandler_fixup+0x4/0xc
> [   29.670000]  [<00498cf8>] cpu_idle_poll.isra.0+0x0/0x6e
> [   29.670000]  [<00498d66>] default_idle_call+0x0/0x46
> [   29.670000]  [<00498d88>] default_idle_call+0x22/0x46
> [   29.670000]  [<00048680>] do_idle+0x6a/0xf0
> [   29.670000]  [<00048616>] do_idle+0x0/0xf0
> [   29.670000]  [<00036742>] find_task_by_pid_ns+0x0/0x2a
> [   29.670000]  [<0005cfd4>] __rcu_read_lock+0x0/0x12
> [   29.670000]  [<000489cc>] cpu_startup_entry+0x1a/0x1c
> [   29.670000]  [<00063976>] __rcu_read_unlock+0x0/0x26
> [   29.670000]  [<00498e4a>] kernel_init+0x0/0xfa
> [   29.670000]  [<004897c0>] strcpy+0x0/0x1e
> [   29.670000]  [<0049379c>] _printk+0x0/0x16
> [   29.670000]  [<00489942>] strlen+0x0/0x22
> [   29.670000]  [<0062d2c6>] memblock_alloc_try_nid+0x0/0x82
> [   29.670000]  [<0062139a>] arch_post_acpi_subsys_init+0x0/0x8
> [   29.670000]  [<00621918>] console_on_rootfs+0x0/0x60
> [   29.670000]  [<00620410>] _sinittext+0x410/0xadc
> [   29.670000]
> [   29.670000] Code: 206e 000c 226e 0010 4a88 6756 4a89 6774 <2029> 0004 b1c0 6600 008e 2410 b3c2 6600 00ae b288 670e 7001 b289 6708 242e fffc
> [   29.670000] Disabling lock debugging due to kernel taint
> [   29.670000] Kernel panic - not syncing: Aiee, killing interrupt handler!
> [   29.670000] ---[ end Kernel panic - not syncing: Aiee, killing interrupt handler! ]---
>