Re: Mainline kernel crashes, was Re: RFC: remove set_fs for m68k

[Finn Thain <fthain@linux-m68k.org>]

Hi All,

While running stress-ng on my Quadra 630, I observed a reproducible panic 
in do_exit():

        if (unlikely(in_interrupt()))
                panic("Aiee, killing interrupt handler!");

The console log says,

running --mmap -1 --mmap-odirect --mmap-bytes 100% -t 60 --timestamp --no-rand-seed --times
stress-ng: 22:22:17.70 info:  [19803] setting to a 60 second run per stressor
stress-ng: 22:22:17.70 info:  [19803] dispatching hogs: 1 mmap
[12634.030000] Kernel panic - not syncing: Aiee, killing interrupt handler!
[12634.030000] CPU: 0 PID: 19805 Comm: stress-ng Not tainted 5.14.0-mac #2
[12634.030000] Stack from 00b27de4:
[12634.030000]         00b27de4 0045b8ea 0045b8ea 00020000 00b27e00 003cb320 0045b8ea 00b27e20
[12634.030000]         003ca326 00020000 418004fc 00b26000 060324c0 00b26000 00ae9680 00b27e5c
[12634.030000]         0001dcc2 00453506 00000009 418004fc 00b26000 00000000 0741b000 00000009
[12634.030000]         00000008 00b27f38 00ae9680 00000006 00000000 00000001 00b27e6c 0001de78
[12634.030000]         00000009 06034510 00b27eb8 000271bc 00000009 0000000f 0000000e c043c000
[12634.030000]         00000000 0741b000 00000003 00b27f98 efe91934 efe90898 00025fc6 00b26000
[12634.030000] Call Trace: [<00020000>] resource_list_free+0x36/0x52
[12634.030000]  [<003cb320>] dump_stack+0x10/0x16
[12634.030000]  [<003ca326>] panic+0xba/0x2bc
[12634.030000]  [<00020000>] resource_list_free+0x36/0x52
[12634.030000]  [<0001dcc2>] do_exit+0x87e/0x9d6
[12634.030000]  [<0001de78>] do_group_exit+0x28/0xb6
[12634.030000]  [<000271bc>] get_signal+0x126/0x720
[12634.030000]  [<00025fc6>] send_signal+0xde/0x16e
[12634.030000]  [<00004bfa>] do_notify_resume+0x38/0x60a
[12634.030000]  [<00027076>] force_sig_fault_to_task+0x36/0x3a
[12634.030000]  [<00027092>] force_sig_fault+0x18/0x1c
[12634.030000]  [<00006e68>] send_fault_sig+0x44/0xc6
[12634.030000]  [<00006204>] buserr_c+0x260/0x5ca
[12634.030000]  [<00002cd8>] do_signal_return+0x10/0x1a
[12634.030000]  [<0018800e>] ext4_fill_super+0x1da0/0x3842
[12634.030000]  [<0010800a>] fsnotify_flush_notify+0x3c/0x72
[12634.030000] 
[12634.030000] ---[ end Kernel panic - not syncing: Aiee, killing interrupt handler! ]---


I haven't found the cause yet. While investigating I tried enabling 
various debug options including CONFIG_DEBUG_SPINLOCK. I then got 
backtrace below from the same machine.

# /root/stress-ng --mmap -1 --mmap-odirect --mmap-bytes=100% -t 1800
stress-ng: info:  [49] setting to a 1800 second (30 mins, 0.00 secs) run per stressor
stress-ng: info:  [49] dispatching hogs: 1 mmap
[  248.710000] BUG: spinlock trylock failure on UP on CPU#0, stress-ng/51
[  248.710000]  lock: 0x53d4a0, .magic: dead4ead, .owner: stress-ng/51, .owner_cpu: 0
[  248.710000] CPU: 0 PID: 51 Comm: stress-ng Not tainted 5.14.0-multi-debug #2
[  248.710000] Stack from 00b159ac:
[  248.710000]         00b159ac 004da40f 004da40f 00000000 00b159c8 0043e88e 004da40f 00b159f4
[  248.710000]         0006316c 004d240e 0053d4a0 dead4ead 0095ebba 00000033 00000000 0053d4a0
[  248.710000]         00b15ae4 0055e6ac 00b15a0c 000632b2 0053d4a0 004d2488 ffffebf7 0053d458
[  248.710000]         00b15a18 0044780e 0053d4a0 00b15a3c 002b8694 0053d4a0 00000001 00000040
[  248.710000]         4bfffffe 0000001a 00528200 00528260 00b15a60 00069f6a 0000000e 00014200
[  248.710000]         00528200 00b15a5c 00b12600 00528200 00014200 00b15a7c 00069ff0 00528200
[  248.710000] Call Trace: [<0043e88e>] dump_stack+0x10/0x16
[  248.710000]  [<0006316c>] spin_dump+0x6c/0xc0
[  248.710000]  [<000632b2>] do_raw_spin_trylock+0x32/0x80
[  248.710000]  [<0044780e>] _raw_spin_trylock+0xe/0x40
[  248.710000]  [<002b8694>] add_interrupt_randomness+0x154/0x1c0
[  248.710000]  [<00069f6a>] handle_irq_event_percpu+0x2a/0x80
[  248.710000]  [<00014200>] INV_L2+0x8/0x10
[  248.710000]  [<00014200>] INV_L2+0x8/0x10
[  248.710000]  [<00069ff0>] handle_irq_event+0x30/0x80
[  248.710000]  [<0006d9e4>] handle_simple_irq+0x64/0x80
[  248.710000]  [<000695fe>] generic_handle_irq+0x3e/0x80
[  248.710000]  [<0000b944>] via1_irq+0x44/0xc0
[  248.710000]  [<000695fe>] generic_handle_irq+0x3e/0x80
[  248.710000]  [<00002ea4>] do_IRQ+0x24/0x40
[  248.710000]  [<00002d74>] auto_irqhandler_fixup+0x4/0xc
[  248.710000]  [<0000129b>] kernel_pg_dir+0x29b/0x1000
[  248.710000]  [<002b86b0>] add_interrupt_randomness+0x170/0x1c0
[  248.710000]  [<00069f6a>] handle_irq_event_percpu+0x2a/0x80
[  248.710000]  [<00069ff0>] handle_irq_event+0x30/0x80
[  248.710000]  [<0006d9e4>] handle_simple_irq+0x64/0x80
[  248.710000]  [<000695c0>] generic_handle_irq+0x0/0x80
[  248.710000]  [<000695fe>] generic_handle_irq+0x3e/0x80
[  248.710000]  [<0000bad4>] via2_irq+0x54/0x80
[  248.710000]  [<000695fe>] generic_handle_irq+0x3e/0x80
[  248.710000]  [<00002ea4>] do_IRQ+0x24/0x40
[  248.710000]  [<00002d74>] auto_irqhandler_fixup+0x4/0xc
[  248.710000]  [<00001000>] kernel_pg_dir+0x0/0x1000
[  248.710000]  [<0000129b>] kernel_pg_dir+0x29b/0x1000
[  248.710000]  [<00404040>] rtm_dump_nexthop+0x80/0x180
[  248.710000]  [<00033f20>] irq_exit+0x60/0x80
[  248.710000]  [<00002eaa>] do_IRQ+0x2a/0x40
[  248.710000]  [<00002d74>] auto_irqhandler_fixup+0x4/0xc
[  248.710000]  [<00025a9b>] _FP_CALL_TOP+0xcc9d/0xd512
[  248.710000]  [<00001000>] kernel_pg_dir+0x0/0x1000
[  248.710000]  [<00001000>] kernel_pg_dir+0x0/0x1000
[  248.710000]  [<00025a9b>] _FP_CALL_TOP+0xcc9d/0xd512
[  248.710000]  [<0000129b>] kernel_pg_dir+0x29b/0x1000
[  248.710000]  [<0019e3e4>] ext4_get_block+0x24/0x40
[  248.710000]  [<0000129b>] kernel_pg_dir+0x29b/0x1000
[  248.710000]  [<0013a8f6>] __block_write_begin_int+0x1b6/0x700
[  248.710000]  [<0000129b>] kernel_pg_dir+0x29b/0x1000
[  248.710000]  [<00001000>] kernel_pg_dir+0x0/0x1000
[  248.710000]  [<00001000>] kernel_pg_dir+0x0/0x1000
[  248.710000]  [<00001000>] kernel_pg_dir+0x0/0x1000
[  248.710000]  [<0011b176>] update_time+0x36/0x40
[  248.710000]  [<0013b3ee>] block_page_mkwrite+0xae/0x100
[  248.710000]  [<00001000>] kernel_pg_dir+0x0/0x1000
[  248.710000]  [<0019e3c0>] ext4_get_block+0x0/0x40
[  248.710000]  [<00005526>] sys_cacheflush+0x2a6/0x500
[  248.710000]  [<001a5676>] ext4_page_mkwrite+0x2f6/0x6c0
[  248.710000]  [<0019e3c0>] ext4_get_block+0x0/0x40
[  248.710000]  [<000d51c0>] find_vma+0x0/0x80
[  248.710000]  [<00444500>] down_read+0x0/0x200
[  248.710000]  [<0000129b>] kernel_pg_dir+0x29b/0x1000
[  248.710000]  [<0019e3c0>] ext4_get_block+0x0/0x40
[  248.710000]  [<000ff292>] fput+0x12/0x40
[  248.710000]  [<000cbbc0>] do_page_mkwrite+0x40/0x140
[  248.710000]  [<004478ce>] _raw_spin_unlock+0xe/0x40
[  248.710000]  [<000cd516>] do_wp_page+0x296/0x4c0
[  248.710000]  [<000cfedc>] handle_mm_fault+0x79c/0x900
[  248.710000]  [<0000129b>] kernel_pg_dir+0x29b/0x1000
[  248.710000]  [<00007402>] do_page_fault+0x102/0x240
[  248.710000]  [<0000653c>] buserr_c+0x17c/0x600
[  248.710000]  [<00002ba8>] buserr+0x20/0x28
[  248.710000]  [<0008800d>] get_next_modinfo+0xcd/0x100
[  248.710000]  [<0009800d>] cgroup1_pidlist_destroy_all+0x8d/0xc0


Apparently add_interrupt_randomness() got re-entered, causing 
spin_trylock() to contest input_pool.lock. But I don't see anything wrong 
there -- false positive?

I was able to reproduce that on both QEMU and Aranym:

[    0.000000] Linux version 5.14.0-multi-debug (fthain@nippy) (m68k-linux-gnu-gcc (btc) 6.4.0, GNU ld (btc) 2.28) #2 Sat Sep 4 15:58:43 AEST 2021
[    0.000000] Saving 202 bytes of bootinfo
[    0.000000] printk: console [debug0] enabled
[    0.000000] printk: debug: ignoring loglevel setting.
Blitter tried to read byte from register ff8a00 at 00816a
[    0.000000] Atari hardware found: VIDEL STDMA-SCSI ST_MFP YM2149 PCM CODEC DSP56K SCC ANALOG_JOY BLITTER IDE TT_CLK FDC_SPEED
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000000000-0x00000081ffffffff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x0000000000dfffff]
[    0.000000]   node   0: [mem 0x0000000001000000-0x00000000081fffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x00000000081fffff]
[    0.000000] NatFeats found (ARAnyM, 1.0)
[    0.000000] initrd: 07f3ea00 - 08200000
[    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 32475
[    0.000000] Kernel command line: debug=par console=tty0 ignore_loglevel initcall_blacklist=ide_falcon_driver_init,nfhd_init BOOT_IMAGE=vmlinux
[    0.000000] blacklisting initcall ide_falcon_driver_init
[    0.000000] blacklisting initcall nfhd_init
[    0.000000] Unknown command line parameters: initcall_blacklist=ide_falcon_driver_init BOOT_IMAGE=vmlinux
[    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes, linear)
[    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes, linear)
[    0.000000] Sorting __ex_table...
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory: 120072K/131072K available (4385K kernel code, 357K rwdata, 772K rodata, 148K init, 121K bss, 11000K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=16, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS: 200
[    0.000000] clocksource: mfp: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 77769386670404 ns
[    0.010000] Console: colour dummy device 80x25
[    0.010000] printk: console [tty0] enabled
[    0.010000] Calibrating delay loop... 132.50 BogoMIPS (lpj=662528)
[    0.090000] pid_max: default: 32768 minimum: 301
[    0.090000] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
[    0.090000] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
[    0.110000] devtmpfs: initialized
[    0.120000] random: get_random_u32 called from bucket_table_alloc+0x13e/0x180 with crng_init=0
[    0.120000] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.130000] futex hash table entries: 256 (order: 0, 7168 bytes, linear)
[    0.130000] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[    0.130000] DMA: preallocated 128 KiB GFP_KERNEL pool for atomic allocations
[    0.140000] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.190000] wait_for_initramfs() called before rootfs_initcalls
[    0.200000] SCSI subsystem initialized
[    0.200000] libata version 3.00 loaded.
[    0.210000] clocksource: Switched to clocksource mfp
[    0.280000] NET: Registered PF_INET protocol family
[    0.280000] IP idents hash table entries: 2048 (order: 2, 16384 bytes, linear)
[    0.280000] tcp_listen_portaddr_hash hash table entries: 256 (order: 0, 6144 bytes, linear)
[    0.290000] TCP established hash table entries: 1024 (order: 0, 4096 bytes, linear)
[    0.290000] TCP bind hash table entries: 1024 (order: 2, 20480 bytes, linear)
[    0.290000] TCP: Hash tables configured (established 1024 bind 1024)
[    0.290000] UDP hash table entries: 256 (order: 1, 12288 bytes, linear)
[    0.290000] UDP-Lite hash table entries: 256 (order: 1, 12288 bytes, linear)
[    0.300000] NET: Registered PF_UNIX/PF_LOCAL protocol family
[    0.300000] RPC: Registered named UNIX socket transport module.
[    0.300000] RPC: Registered udp transport module.
[    0.300000] RPC: Registered tcp transport module.
[    0.310000] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.310000] initcall nfhd_init blacklisted
[    0.310000] Trying to unpack rootfs image as initramfs...
[    0.330000] nfeth: API 5
[    0.330000] workingset: timestamp_bits=30 max_order=15 bucket_order=0
[    0.700000] Freeing initrd memory: 2820K
[    0.710000] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[    0.720000] io scheduler mq-deadline registered
[    0.720000] atafb atafb: phys_screen_base 6dc000 screen_len 311296
[    0.730000] atafb atafb: Determined 640x480, depth 4
[    0.730000] atafb atafb:    virtual 640x972
[    0.740000] Console: switching to colour frame buffer device 80x30
[    0.750000] fb0: frame buffer device, using 304K of video memory
[    0.750000] pmac_zilog: 0.6 (Benjamin Herrenschmidt <benh@kernel.crashing.org>)
[    0.750000] Non-volatile memory driver v1.3
[    0.780000] brd: module loaded
[    1.080000] scsi host0: Atari native SCSI, irq 15, io_port 0x0, base 0x0, can_queue 1, cmd_per_lun 2, sg_tablesize 1, this_id 7, flags { }
[    1.960000] random: fast init done
[    2.890000] atari-falcon-ide atari-falcon-ide: Atari Falcon and Q40/Q60 PATA controller
[    2.950000] scsi host1: pata_falcon
[    2.970000] ata1: PATA max PIO4 cmd 0xfff00000 ctl 0xfff00038 no IRQ, using PIO polling
[    3.020000] aoe: AoE v85 initialised.
[    3.050000] mousedev: PS/2 mouse device common for all mice
[    3.330000] input: Atari Keyboard as /devices/virtual/input/input0
[    3.350000] ata1.00: NODEV after polling detection
[    3.370000] ata1.01: ATA-2: slave, , max PIO2
[    3.390000] ata1.01: 322560 sectors, multi 0: LBA 
[    3.400000] ata1.01: configured for PIO
[    3.430000] scsi 1:0:1:0: Direct-Access     ATA      slave            n/a  PQ: 0 ANSI: 5
[    3.490000] scsi 1:0:1:0: Attached scsi generic sg0 type 0
[    3.520000] sd 1:0:1:0: [sda] 322560 512-byte logical blocks: (165 MB/158 MiB)
[    3.570000] sd 1:0:1:0: [sda] Write Protect is off
[    3.590000] sd 1:0:1:0: [sda] Mode Sense: 00 3a 00 00
[    3.620000] sd 1:0:1:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[    3.670000] rtc-generic rtc-generic: registered as rtc0
[    3.690000] NET: Registered PF_PACKET protocol family
[    3.730000] sd 1:0:1:0: [sda] Attached SCSI disk
[    3.760000] Freeing unused kernel image (initmem) memory: 148K
[    3.790000] This architecture does not have kernel memory protection.
[    3.810000] Run /init as init process
[    3.840000]   with arguments:
[    3.870000]     /init
[    3.880000]   with environment:
[    3.910000]     HOME=/
[    3.920000]     TERM=linux
[    3.940000]     initcall_blacklist=ide_falcon_driver_init
[    3.970000]     BOOT_IMAGE=vmlinux
[   85.240000] random: crng init done
[  139.730000] EXT4-fs (sda): mounting ext2 file system using the ext4 subsystem
[  139.770000] EXT4-fs (sda): mounted filesystem without journal. Opts: (null). Quota mode: disabled.
[ 4089.070000] BUG: spinlock trylock failure on UP on CPU#0, stress-ng/1341
[ 4089.070000]  lock: 0x53d4a0, .magic: dead4ead, .owner: stress-ng/1341, .owner_cpu: 0
[ 4089.070000] CPU: 0 PID: 1341 Comm: stress-ng Not tainted 5.14.0-multi-debug #2
[ 4089.070000] Stack from 00a7dcc8:
[ 4089.070000]         00a7dcc8 004da40f 004da40f 00000000 00a7dce4 0043e88e 004da40f 00a7dd10
[ 4089.070000]         0006316c 004d240e 0053d4a0 dead4ead 00956bba 0000053d 00000000 0053d4a0
[ 4089.070000]         00a7ddd8 0055e6ac 00a7dd28 000632b2 0053d4a0 004d2488 0005c81b 0053d458
[ 4089.070000]         00a7dd34 0044780e 0053d4a0 00a7dd58 002b8694 0053d4a0 00000001 0000007f
[ 4089.070000]         00860000 00000011 00528138 00528198 00a7dd7c 00069f6a 0000000d 00014200
[ 4089.070000]         00528138 00a7dd78 00a7def0 00528138 00014200 00a7dd98 00069ff0 00528138
[ 4089.070000] Call Trace: [<0043e88e>] dump_stack+0x10/0x16
[ 4089.070000]  [<0006316c>] spin_dump+0x6c/0xc0
[ 4089.070000]  [<000632b2>] do_raw_spin_trylock+0x32/0x80
[ 4089.070000]  [<0005c81b>] init_dl_bandwidth+0x1b/0x80
[ 4089.070000]  [<0044780e>] _raw_spin_trylock+0xe/0x40
[ 4089.070000]  [<002b8694>] add_interrupt_randomness+0x154/0x1c0
[ 4089.070000]  [<00069f6a>] handle_irq_event_percpu+0x2a/0x80
[ 4089.070000]  [<00014200>] INV_L2+0x8/0x10
[ 4089.070000]  [<00014200>] INV_L2+0x8/0x10
[ 4089.070000]  [<00069ff0>] handle_irq_event+0x30/0x80
[ 4089.070000]  [<0006d9e4>] handle_simple_irq+0x64/0x80
[ 4089.070000]  [<000695fe>] generic_handle_irq+0x3e/0x80
[ 4089.070000]  [<00002ea4>] do_IRQ+0x24/0x40
[ 4089.070000]  [<00002da8>] user_irqvec_fixup+0xc/0x14
[ 4089.070000]  [<0005c81a>] init_dl_bandwidth+0x1a/0x80
[ 4089.070000]  [<000d51c0>] find_vma+0x0/0x80
[ 4089.070000]  [<00444500>] down_read+0x0/0x200
[ 4089.070000]  [<002b86b0>] add_interrupt_randomness+0x170/0x1c0
[ 4089.070000]  [<00069f6a>] handle_irq_event_percpu+0x2a/0x80
[ 4089.070000]  [<00069ff0>] handle_irq_event+0x30/0x80
[ 4089.070000]  [<0006d9e4>] handle_simple_irq+0x64/0x80
[ 4089.070000]  [<000695fe>] generic_handle_irq+0x3e/0x80
[ 4089.070000]  [<00002ea4>] do_IRQ+0x24/0x40
[ 4089.070000]  [<00002d74>] auto_irqhandler_fixup+0x4/0xc
[ 4089.070000]  [<0000653c>] buserr_c+0x17c/0x600
[ 4089.070000]  [<00002ba8>] buserr+0x20/0x28
[ 4089.070000]  [<0008800d>] get_next_modinfo+0xcd/0x100
[ 4089.070000] 

Does anyone know what causes this?