On Wed, Jan 02, 2019 at 01:58:17PM +0300, Anatoly Pugachev wrote:
> Hello!
>
> Latest git kernels does not boot for me. Bisect log is the end of this email.
>
> v4.20.0-rc1-00088-gea2c18e1044e boots ok.
> v4.20.0-rc1-00089-gfa182a1fa97d does not boot.
>
> Can someone look please? Thanks.
>
> Boot log:
>
> NOTICE: Entering OpenBoot.
> NOTICE: Fetching Guest MD from HV.
> NOTICE: Starting additional cpus.
> NOTICE: Initializing LDC services.
> NOTICE: Probing PCI devices.
> NOTICE: Finished PCI probing.
>
> SPARC T5-2, No Keyboard
> Copyright (c) 1998, 2018, Oracle and/or its affiliates. All rights reserved.
> OpenBoot 4.38.12, 34.0000 GB memory available, Serial #83494642.
> Ethernet address 0:14:4f:fa:6:f2, Host ID: 84fa06f2.
>
>
>
> Boot device: vdisk1 File and args:
> WARNING: Unsupported bootblk image, can not extract fcode
>
> WARNING: Bootblk fcode extraction failed
> GRUB Loading kernel....
>
> GNU GRUB version 2.02-2+sparc64.3
>
> +----------------------------------------------------------------------------+
> | Debian GNU/Linux, with Linux 4.20.0-06428-g00c569b567c7 |
> | Debian GNU/Linux, with Linux 4.20.0 |
> | Debian GNU/Linux, with Linux 4.20.0-rc7-00274-g23203e3f34c9 |
> | Debian GNU/Linux, with Linux 4.20.0-rc7 |
> |*Debian GNU/Linux, with Linux 4.20.0-rc1-00089-gfa182a1fa97d |
> | Debian GNU/Linux, with Linux 4.20.0-rc1-00088-gea2c18e1044e |
> | Debian GNU/Linux, with Linux 4.19.0-1-sparc64-smp |
> | Debian GNU/Linux, with Linux 4.18.0-rc4 |
> | Debian GNU/Linux, with Linux 4.16.0 |
> | |
> | |
> | |
> +----------------------------------------------------------------------------+
>
> Use the ^ and v keys to select which entry is highlighted.
> Press enter to boot the selected OS, `e' to edit the commands
> before booting or `c' for a command-line.
>
>
> Loading Linux 4.20.0-rc1-00089-gfa182a1fa97d ...
> Loading initial ramdisk ...
>
> [ 0.000018] PROMLIB: Sun IEEE Boot Prom 'OBP 4.38.12 2018/03/28 14:54'
> [ 0.000028] PROMLIB: Root node compatible: sun4v
> [ 0.000073] Linux version 4.20.0-rc1-00089-gfa182a1fa97d
> (mator@ttip) (gcc version 7.4.0 (Debian 7.4.0-2)) #812 SMP Tue Jan 1
> 23:04:57 MSK 2019
> [ 0.000381] printk: bootconsole [earlyprom0] enabled
> [ 0.000432] ARCH: SUN4V
> [ 0.000482] Ethernet address: 00:14:4f:fa:06:f2
> [ 0.000533] MM: PAGE_OFFSET is 0xfff8000000000000 (max_phys_bits == 47)
> [ 0.000596] MM: VMALLOC [0x0000000100000000 --> 0x0006000000000000]
> [ 0.000657] MM: VMEMMAP [0x0006000000000000 --> 0x000c000000000000]
> [ 0.011416] Kernel: Using 5 locked TLB entries for main kernel image.
> [ 0.011497] Remapping the kernel...
> [ 0.011523] done.
> [ 0.040937] OF stdout device is: /virtual-devices@100/console@1
> [ 0.041004] PROM: Built device tree with 74449 bytes of memory.
> [ 0.041064] MDESC: Size is 30768 bytes.
> [ 0.041172] PLATFORM: banner-name [SPARC T5-2]
> [ 0.041220] PLATFORM: name [ORCL,SPARC-T5-2]
> [ 0.041267] PLATFORM: hostid [84fa06f2]
> [ 0.041310] PLATFORM: serial# [0035260e]
> [ 0.041352] PLATFORM: stick-frequency [3b9aca00]
> [ 0.041400] PLATFORM: mac-address [144ffa06f2]
> [ 0.041446] PLATFORM: watchdog-resolution [1000 ms]
> [ 0.041497] PLATFORM: watchdog-max-timeout [31536000000 ms]
> [ 0.041552] PLATFORM: max-cpus [1024]
> [ 0.041641] Top of RAM: 0x24af948000, Total RAM: 0x87f388000
> [ 0.041701] Memory hole size: 115461MB
> [ 0.045904] Allocated 40960 bytes for kernel page tables.
> [ 0.045991] Zone ranges:
> [ 0.046030] Normal [mem 0x0000000030400000-0x00000024af947fff]
> [ 0.046094] Movable zone start for each node
> [ 0.046138] Early memory node ranges
> [ 0.046180] node 0: [mem 0x0000000030400000-0x000000006febffff]
> [ 0.046239] node 0: [mem 0x000000006ff40000-0x000000006ff47fff]
> [ 0.046300] node 0: [mem 0x0000000070000000-0x000000042fffffff]
> [ 0.046360] node 0: [mem 0x0000002030000000-0x00000024af8b7fff]
> [ 0.046421] node 0: [mem 0x00000024af940000-0x00000024af947fff]
> [ 0.053769] Zeroed struct page in unavailable ranges: 230112 pages
> [ 0.053777] Initmem setup node 0 [mem 0x0000000030400000-0x00000024af947fff]
> [ 0.251173] Booting Linux...
> [ 0.251257] CPU CAPS: [flush,stbar,swap,muldiv,v9,blkinit,n2,mul32]
> [ 0.251339] CPU CAPS: [div32,v8plus,popc,vis,vis2,ASIBlkInit,fmaf,vis3]
> [ 0.251416] CPU CAPS: [hpc,ima,pause,cbcond,aes,des,kasumi,camellia]
> [ 0.252492] CPU CAPS: [md5,sha1,sha256,sha512,mpmul,montmul,montsqr,crc32c]
> [ 0.303600] percpu: Embedded 20 pages/cpu @(____ptrval____) s122824
> r8192 d32824 u262144
> [ 0.304684] SUN4V: Mondo queue sizes [cpu(131072) dev(16384) r(8192) nr(256)]
> [ 0.304994] Built 1 zonelists, mobility grouping on. Total pages: 4415698
> [ 0.305082] Kernel command line:
> BOOT_IMAGE=/vmlinuz-4.20.0-rc1-00089-gfa182a1fa97d root=/dev/vdiska2
> ro zswap.enabled=1 elevator=deadline
> [ 0.307420] printk: log_buf_len individual max cpu contribution: 4096 bytes
> [ 0.307491] printk: log_buf_len total cpu_extra contributions: 1044480 bytes
> [ 0.307558] printk: log_buf_len min size: 131072 bytes
> [ 0.307929] printk: log_buf_len: 2097152 bytes
> [ 0.307981] printk: early log buf free: 125920(96%)
> [ 0.314307] Dentry cache hash table entries: 8388608 (order: 13,
> 67108864 bytes)
> [ 0.317544] Inode-cache hash table entries: 4194304 (order: 12,
> 33554432 bytes)
> [ 0.317615] Sorting __ex_table...
> [ 0.396371] Memory: 35119672K/35638816K available (6200K kernel
> code, 831K rwdata, 1848K rodata, 888K init, 7997K bss, 519144K
> reserved, 0K cma-reserved)
> [ 0.396690] kmemleak: Kernel memory leak detector disabled
> [ 0.398175] ftrace: allocating 18918 entries in 37 pages
> [ 0.411784] Running RCU self tests
> [ 0.411829] rcu: Hierarchical RCU implementation.
> [ 0.411877] rcu: RCU event tracing is enabled.
> [ 0.411926] rcu: RCU lockdep checking is enabled.
> [ 0.411975] Tasks RCU enabled.
> [ 0.412013] rcu: RCU calculated value of scheduler-enlistment delay
> is 11 jiffies.
> [ 0.417162] NR_IRQS: 2048, nr_irqs: 2048, preallocated irqs: 1
> [ 0.417246] SUN4V: Using IRQ API major 3, cookie only virqs enabled
> [ 0.421376] clocksource: stick: mask: 0xffffffffffffffff
> max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
> [ 0.421511] clocksource: mult[800000] shift[23]
> [ 0.421560] clockevent: mult[80000000] shift[31]
> [ 0.425949] Console: colour dummy device 80x25
> [ 0.426014] printk: console [tty0] enabled
> [ 0.426088] printk: bootconsole [earlyprom0] disabled
> [ 0.000018] PROMLIB: Sun IEEE Boot Prom 'OBP 4.38.12 2018/03/28 14:54'
> [ 0.000028] PROMLIB: Root node compatible: sun4v
> [ 0.000073] Linux version 4.20.0-rc1-00089-gfa182a1fa97d
> (mator@ttip) (gcc version 7.4.0 (Debian 7.4.0-2)) #812 SMP Tue Jan 1
> 23:04:57 MSK 2019
> [ 0.000381] printk: bootconsole [earlyprom0] enabled
> [ 0.000432] ARCH: SUN4V
> [ 0.000482] Ethernet address: 00:14:4f:fa:06:f2
> [ 0.000533] MM: PAGE_OFFSET is 0xfff8000000000000 (max_phys_bits == 47)
> [ 0.000596] MM: VMALLOC [0x0000000100000000 --> 0x0006000000000000]
> [ 0.000657] MM: VMEMMAP [0x0006000000000000 --> 0x000c000000000000]
> [ 0.011416] Kernel: Using 5 locked TLB entries for main kernel image.
> [ 0.011497] Remapping the kernel...
> [ 0.011523] done.
> [ 0.040937] OF stdout device is: /virtual-devices@100/console@1
> [ 0.041004] PROM: Built device tree with 74449 bytes of memory.
> [ 0.041064] MDESC: Size is 30768 bytes.
> [ 0.041172] PLATFORM: banner-name [SPARC T5-2]
> [ 0.041220] PLATFORM: name [ORCL,SPARC-T5-2]
> [ 0.041267] PLATFORM: hostid [84fa06f2]
> [ 0.041310] PLATFORM: serial# [0035260e]
> [ 0.041352] PLATFORM: stick-frequency [3b9aca00]
> [ 0.041400] PLATFORM: mac-address [144ffa06f2]
> [ 0.041446] PLATFORM: watchdog-resolution [1000 ms]
> [ 0.041497] PLATFORM: watchdog-max-timeout [31536000000 ms]
> [ 0.041552] PLATFORM: max-cpus [1024]
> [ 0.041641] Top of RAM: 0x24af948000, Total RAM: 0x87f388000
> [ 0.041701] Memory hole size: 115461MB
> [ 0.045904] Allocated 40960 bytes for kernel page tables.
> [ 0.045991] Zone ranges:
> [ 0.046030] Normal [mem 0x0000000030400000-0x00000024af947fff]
> [ 0.046094] Movable zone start for each node
> [ 0.046138] Early memory node ranges
> [ 0.046180] node 0: [mem 0x0000000030400000-0x000000006febffff]
> [ 0.046239] node 0: [mem 0x000000006ff40000-0x000000006ff47fff]
> [ 0.046300] node 0: [mem 0x0000000070000000-0x000000042fffffff]
> [ 0.046360] node 0: [mem 0x0000002030000000-0x00000024af8b7fff]
> [ 0.046421] node 0: [mem 0x00000024af940000-0x00000024af947fff]
> [ 0.053769] Zeroed struct page in unavailable ranges: 230112 pages
> [ 0.053777] Initmem setup node 0 [mem 0x0000000030400000-0x00000024af947fff]
> [ 0.251173] Booting Linux...
> [ 0.251257] CPU CAPS: [flush,stbar,swap,muldiv,v9,blkinit,n2,mul32]
> [ 0.251339] CPU CAPS: [div32,v8plus,popc,vis,vis2,ASIBlkInit,fmaf,vis3]
> [ 0.251416] CPU CAPS: [hpc,ima,pause,cbcond,aes,des,kasumi,camellia]
> [ 0.252492] CPU CAPS: [md5,sha1,sha256,sha512,mpmul,montmul,montsqr,crc32c]
> [ 0.303600] percpu: Embedded 20 pages/cpu @(____ptrval____) s122824
> r8192 d32824 u262144
> [ 0.304684] SUN4V: Mondo queue sizes [cpu(131072) dev(16384) r(8192) nr(256)]
> [ 0.304994] Built 1 zonelists, mobility grouping on. Total pages: 4415698
> [ 0.305082] Kernel command line:
> BOOT_IMAGE=/vmlinuz-4.20.0-rc1-00089-gfa182a1fa97d root=/dev/vdiska2
> ro zswap.enabled=1 elevator=deadline
> [ 0.307420] printk: log_buf_len individual max cpu contribution: 4096 bytes
> [ 0.307491] printk: log_buf_len total cpu_extra contributions: 1044480 bytes
> [ 0.307558] printk: log_buf_len min size: 131072 bytes
> [ 0.307929] printk: log_buf_len: 2097152 bytes
> [ 0.307981] printk: early log buf free: 125920(96%)
> [ 0.314307] Dentry cache hash table entries: 8388608 (order: 13,
> 67108864 bytes)
> [ 0.317544] Inode-cache hash table entries: 4194304 (order: 12,
> 33554432 bytes)
> [ 0.317615] Sorting __ex_table...
> [ 0.396371] Memory: 35119672K/35638816K available (6200K kernel
> code, 831K rwdata, 1848K rodata, 888K init, 7997K bss, 519144K
> reserved, 0K cma-reserved)
> [ 0.396690] kmemleak: Kernel memory leak detector disabled
> [ 0.398175] ftrace: allocating 18918 entries in 37 pages
> [ 0.411784] Running RCU self tests
> [ 0.411829] rcu: Hierarchical RCU implementation.
> [ 0.411877] rcu: RCU event tracing is enabled.
> [ 0.411926] rcu: RCU lockdep checking is enabled.
> [ 0.411975] Tasks RCU enabled.
> [ 0.412013] rcu: RCU calculated value of scheduler-enlistment delay
> is 11 jiffies.
> [ 0.417162] NR_IRQS: 2048, nr_irqs: 2048, preallocated irqs: 1
> [ 0.417246] SUN4V: Using IRQ API major 3, cookie only virqs enabled
> [ 0.421376] clocksource: stick: mask: 0xffffffffffffffff
> max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
> [ 0.421511] clocksource: mult[800000] shift[23]
> [ 0.421560] clockevent: mult[80000000] shift[31]
> [ 0.425949] Console: colour dummy device 80x25
> [ 0.426014] printk: console [tty0] enabled
> [ 0.426088] printk: bootconsole [earlyprom0] disabled
> [ 0.426170] Lock dependency validator: Copyright (c) 2006 Red Hat,
> Inc., Ingo Molnar
> [ 0.426216] ... MAX_LOCKDEP_SUBCLASSES: 8
> [ 0.426244] ... MAX_LOCK_DEPTH: 48
> [ 0.426273] ... MAX_LOCKDEP_KEYS: 8191
> [ 0.426302] ... CLASSHASH_SIZE: 4096
> [ 0.426331] ... MAX_LOCKDEP_ENTRIES: 16384
> [ 0.426360] ... MAX_LOCKDEP_CHAINS: 32768
> [ 0.426390] ... CHAINHASH_SIZE: 16384
> [ 0.426419] memory used by lock dependency info: 4959 kB
> [ 0.426453] per task-struct memory footprint: 1920 bytes
> [ 0.426684] kmemleak: Early log buffer exceeded (36609), please
> increase DEBUG_KMEMLEAK_EARLY_LOG_SIZE
> [ 0.571798] Calibrating delay using timer specific routine..
> 2004.20 BogoMIPS (lpj=10021012)
> [ 0.571859] pid_max: default: 262144 minimum: 2048
> [ 0.573036] LSM: Security Framework initializing
> [ 0.573077] AppArmor: AppArmor disabled by boot time parameter
> [ 0.573741] Mount-cache hash table entries: 131072 (order: 7, 1048576 bytes)
> [ 0.573898] Mountpoint-cache hash table entries: 131072 (order: 7,
> 1048576 bytes)
> [ 0.578665] rcu: Hierarchical SRCU implementation.
> [ 0.601054] smp: Bringing up secondary CPUs ...
> [ 0.661314] smp: Brought up 1 node, 24 CPUs
> [ 0.665369] devtmpfs: initialized
> [ 0.670917] Performance events:
> [ 0.670949] Testing NMI watchdog ...
> [ 0.871044] OK.
> [ 0.871175] Supported PMU type is 'niagara5'
> [ 0.871470] random: get_random_u32 called from
> bucket_table_alloc.isra.4+0x144/0x1c0 with crng_init=0
> [ 0.872211] ldc.c:v1.1 (July 22, 2008)
> [ 0.874973] clocksource: jiffies: mask: 0xffffffff max_cycles:
> 0xffffffff, max_idle_ns: 19112604462750000 ns
> [ 0.875061] futex hash table entries: 65536 (order: 10, 8388608 bytes)
> [ 0.884956] NET: Registered protocol family 16
> [ 0.894034] VIO: Adding device channel-devices (tx_ino =
> ffffffffffffffff, rx_ino = ffffffffffffffff)
> [ 0.894257] VIO: Adding device vnet-port-0-0 (tx_ino = 0, rx_ino = 1)
> [ 0.894478] VIO: Adding device vnet-port-0-1 (tx_ino = 2, rx_ino = 3)
> [ 0.894671] VIO: Adding device vnet-port-0-2 (tx_ino = 4, rx_ino = 5)
> [ 0.894857] VIO: Adding device vnet-port-0-3 (tx_ino = 6, rx_ino = 7)
> [ 0.895049] VIO: Adding device vnet-port-0-4 (tx_ino = 8, rx_ino = 9)
> [ 0.895233] VIO: Adding device vdc-port-3-0 (tx_ino = a, rx_ino = b)
> [ 0.895424] VIO: Adding device vdc-port-2-0 (tx_ino = c, rx_ino = d)
> [ 0.895614] VIO: Adding device vdc-port-1-0 (tx_ino = e, rx_ino = f)
> [ 0.895800] VIO: Adding device vdc-port-0-0 (tx_ino = 10, rx_ino = 11)
> [ 0.895992] VIO: Adding device vlds-port-0-0 (tx_ino = 12, rx_ino = 13)
> [ 0.896185] VIO: Adding device domain-services-port-0 (tx_ino = 12,
> rx_ino = 13)
> [ 0.896569] audit: initializing netlink subsys (disabled)
> [ 0.896887] audit: type=2000 audit(0.470:1): state=initialized
> audit_enabled=0 res=1
> [ 0.942080] HugeTLB registered 64.0 KiB page size, pre-allocated 0 pages
> [ 0.942127] HugeTLB registered 8.00 MiB page size, pre-allocated 0 pages
> [ 0.942171] HugeTLB registered 256 MiB page size, pre-allocated 0 pages
> [ 0.942213] HugeTLB registered 2.00 GiB page size, pre-allocated 0 pages
> [ 0.954563] SUN4V: Reboot data supported (maj=1,min=0).
> [ 0.955003] ds.c:v1.0 (Jul 11, 2007)
> [ 0.955411] ds-0: ds_conn_reset() from send_events.isra.3
> [ 0.956852] clocksource: Switched to clocksource stick
> [ 1.136579] VFS: Disk quotas dquot_6.6.0
> [ 1.137098] VFS: Dquot-cache hash table entries: 1024 (order 0, 8192 bytes)
> [ 1.156618] NET: Registered protocol family 2
> [ 1.161709] tcp_listen_portaddr_hash hash table entries: 32768
> (order: 8, 2359296 bytes)
> [ 1.164926] TCP established hash table entries: 524288 (order: 9,
> 4194304 bytes)
> [ 1.166999] TCP bind hash table entries: 65536 (order: 9, 4194304 bytes)
> [ 1.173136] TCP: Hash tables configured (established 524288 bind 65536)
> [ 1.179706] UDP hash table entries: 32768 (order: 9, 5242880 bytes)
> [ 1.186409] UDP-Lite hash table entries: 32768 (order: 9, 5242880 bytes)
> [ 1.199965] NET: Registered protocol family 1
> [ 1.200694] Unpacking initramfs...
> [ 1.431272] Freeing initrd memory: 7336K
> [ 1.473220] Kprobe smoke test: started
> [ 1.482012] Kprobe smoke test: passed successfully
> [ 1.483104] workingset: timestamp_bits=46 max_order=23 bucket_order=0
> [ 1.484411] zbud: loaded
> [ 1.636008] Block layer SCSI generic (bsg) driver version 0.4
> loaded (major 252)
> [ 1.637688] io scheduler noop registered
> [ 1.637721] io scheduler deadline registered (default)
> [ 1.638388] io scheduler cfq registered
> [ 1.638420] io scheduler mq-deadline registered (default)
> [ 1.638458] io scheduler kyber registered
> [ 1.641791] f029b788: ttyS0 at I/O 0x0 (irq = 1, base_baud =
> 115200) is a SUN4V HCONS
> [ 1.647813] printk: console [ttyHV0] enabled
> [ 1.651247] sunvdc.c:v1.2 (November 24, 2014)
> [ 1.657878] sunvdc: Virtual CDROM vdiskd
> [ 1.657929] sunvdc: vdiskd: 403160 sectors (196 MB) protocol 1.2
> [ 1.659309] vdiskd: vdiskd1 vdiskd2 vdiskd3 vdiskd4 vdiskd5 vdiskd6 vdiskd7
> [ 1.702561] sunvdc: Virtual Hard disk vdiskc
> [ 1.702600] sunvdc: vdiskc: 104857600 sectors (51200 MB) protocol 1.2
> [ 1.741930] sunvdc: Virtual Hard disk vdiskb
> [ 1.741969] sunvdc: vdiskb: 62914560 sectors (30720 MB) protocol 1.2
> [ 1.765637] vdiskb: vdiskb1
> [ 1.805186] sunvdc: Virtual Hard disk vdiska
> [ 1.805223] sunvdc: vdiska: 31457280 sectors (15360 MB) protocol 1.2
> [ 1.805960] vdiska: vdiska1 vdiska2 vdiska3 vdiska4
> [ 1.839927] sunvnet: sunvnet 2.0 (February 3, 2017)
> [ 1.843366] vnet_port vnet-port-0-0 eth0: Sun LDOM vnet 00:14:4f:f8:12:a3
> [ 1.843918] sunvnet: eth0: PORT ( remote-mac 00:14:4f:fa:f3:f0 switch-port )
> [ 1.845211] sunvnet: eth0: PORT ( remote-mac 00:14:4f:f8:e5:f3 )
> [ 1.846483] sunvnet: eth0: PORT ( remote-mac 00:14:4f:f9:b4:97 )
> [ 1.847807] sunvnet: eth0: PORT ( remote-mac 00:14:4f:f9:8b:83 )
> [ 1.849082] sunvnet: eth0: PORT ( remote-mac 00:14:4f:f8:fe:47 )
> [ 1.850070] mousedev: PS/2 mouse device common for all mice
> [ 1.851199] rtc-sun4v rtc-sun4v: rtc core: registered sun4v as rtc0
> [ 1.852305] device-mapper: uevent: version 1.0.3
> [ 1.853383] device-mapper: ioctl: 4.39.0-ioctl (2018-04-03)
> initialised: dm-devel@xxxxxxxxxx
> [ 1.854915] NET: Registered protocol family 17
> [ 1.856124] registered taskstats version 1
> [ 1.859098] zswap: loaded using pool lzo/zbud
> [ 1.888560] Key type big_key registered
> [ 1.889406] rtc-sun4v rtc-sun4v: setting system clock to 2019-01-02
> 10:39:17 UTC (1546425557)
> [ 1.893904] This architecture does not have kernel memory protection.
> [ 1.893950] Run /init as init process
> Loading, please wait...
> starting version 240
> [ 2.736997] ------------[ cut here ]------------
> [ 2.737128] WARNING: CPU: 19 PID: 0 at block/blk-mq.c:1309
> __blk_mq_run_hw_queue+0xe0/0x140
> [ 2.737208] Modules linked in:
> [ 2.737248] CPU: 19 PID: 0 Comm: swapper/19 Not tainted
> 4.20.0-rc1-00089-gfa182a1fa97d #812
> [ 2.737315] Call Trace:
> [ 2.737356] [00000000004641c0] __warn+0xc0/0x100
> [ 2.737397] [000000000046428c] warn_slowpath_null+0x2c/0x40
> [ 2.737445] [00000000007c36c0] __blk_mq_run_hw_queue+0xe0/0x140
> [ 2.737500] [00000000007c3784] __blk_mq_delay_run_hw_queue+0x64/0x1a0
> [ 2.737553] [00000000007c5628] blk_mq_run_hw_queue+0xc8/0x100
> [ 2.737605] [00000000007c69c0] blk_mq_start_hw_queues+0x40/0x60
> [ 2.737656] [00000000008604fc] vdc_blk_queue_start+0x5c/0x80
> [ 2.737696] [00000000008619fc] vdc_event+0x1fc/0x2c0
> [ 2.737737] [0000000000446aac] send_events.isra.3+0x4c/0x60
> [ 2.737777] [00000000004487d4] ldc_rx+0x234/0x260
> [ 2.737815] [00000000004dd470] __handle_irq_event_percpu+0x170/0x380
> [ 2.737858] [00000000004dd694] handle_irq_event_percpu+0x14/0x60
> [ 2.737899] [00000000004dd718] handle_irq_event+0x38/0x80
> [ 2.737941] [00000000004e17a4] handle_fasteoi_irq+0x124/0x220
> [ 2.737987] [00000000004dca0c] generic_handle_irq+0x2c/0x40
> [ 2.738048] [0000000000a11b40] handler_irq+0xc0/0x100
> [ 2.738094] irq event stamp: 2860
> [ 2.738136] hardirqs last enabled at (2857): [<000000000042d644>]
> arch_cpu_idle+0x44/0xc0
> [ 2.738207] hardirqs last disabled at (2858): [<00000000004271dc>]
> sys_call_table+0x5f0/0x854
> [ 2.738279] softirqs last enabled at (2860): [<000000000046b884>]
> _local_bh_enable+0x44/0x60
> [ 2.738348] softirqs last disabled at (2859): [<000000000046bb5c>]
> irq_enter+0x3c/0x80
> [ 2.738413] ---[ end trace 58887c4073a09c83 ]---
> [ 2.740036] crc32c_sparc64: Using sparc64 crc32c opcode optimized
> CRC32C implementation
> [ 2.770351]
> [ 2.770377] ================================
> [ 2.770389] WARNING: inconsistent lock state
> [ 2.770404] 4.20.0-rc1-00089-gfa182a1fa97d #812 Tainted: G W
> [ 2.770417] --------------------------------
> [ 2.770427] inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
> [ 2.770441] swapper/17/0 [HC1[1]:SC0[0]:HE0:SE1] takes:
> [ 2.770454] (____ptrval____) (&(&dd->lock)->rlock){?.+.}, at:
> dd_dispatch_request+0x1c/0x200
> [ 2.770488] {HARDIRQ-ON-W} state was registered at:
> [ 2.770507] lock_acquire+0x198/0x1c0
> [ 2.770527] _raw_spin_lock+0x30/0x60
> [ 2.770541] dd_bio_merge+0x20/0x60
> [ 2.770565] __blk_mq_sched_bio_merge+0x84/0x160
> [ 2.770581] blk_mq_make_request+0xc0/0x7c0
> [ 2.770599] generic_make_request+0x2e0/0x460
> [ 2.770613] submit_bio+0x158/0x180
> [ 2.770629] submit_bh_wbc+0x1cc/0x1e0
> [ 2.770643] block_read_full_page+0x340/0x380
> [ 2.770658] blkdev_readpage+0x14/0x40
> [ 2.770675] do_read_cache_page+0xac/0x360
> [ 2.770689] read_cache_page+0x1c/0x40
> [ 2.770704] read_dev_sector+0x20/0xa0
> [ 2.770719] read_lba.isra.0+0xb8/0x160
> [ 2.770733] efi_partition+0xc8/0xac0
> [ 2.770745] check_partition+0x124/0x240
> [ 2.770759] rescan_partitions+0x90/0x3a0
> [ 2.770774] __blkdev_get+0x1e8/0x500
> [ 2.770788] blkdev_get+0x1c0/0x3c0
> [ 2.770800] __device_add_disk+0x36c/0x520
> [ 2.770814] device_add_disk+0x18/0x40
> [ 2.770830] vdc_port_probe+0x60c/0x6c0
> [ 2.770851] vio_device_probe+0xac/0xc0
> [ 2.770871] really_probe+0x1e8/0x400
> [ 2.770885] driver_probe_device+0xfc/0x140
> [ 2.770900] __driver_attach+0xf8/0x140
> [ 2.770915] bus_for_each_dev+0x40/0xa0
> [ 2.770928] driver_attach+0x1c/0x40
> [ 2.770941] bus_add_driver+0x154/0x280
> [ 2.770954] driver_register+0xc4/0x120
> [ 2.770966] __vio_register_driver+0x28/0x40
> [ 2.770981] vdc_init+0x70/0xa4
> [ 2.770995] do_one_initcall+0x150/0x340
> [ 2.771012] kernel_init_freeable+0x440/0x4fc
> [ 2.771025] kernel_init+0xc/0x120
> [ 2.771043] ret_from_fork+0x1c/0x2c
> [ 2.771053] (null)
> [ 2.771063] irq event stamp: 2634
> [ 2.771080] hardirqs last enabled at (2631): [<000000000042d644>]
> arch_cpu_idle+0x44/0xc0
> [ 2.771097] hardirqs last disabled at (2632): [<00000000004271dc>]
> sys_call_table+0x5f0/0x854
> [ 2.771117] softirqs last enabled at (2634): [<000000000046b884>]
> _local_bh_enable+0x44/0x60
> [ 2.771134] softirqs last disabled at (2633): [<000000000046bb5c>]
> irq_enter+0x3c/0x80
> [ 2.771148]
> [ 2.771148] other info that might help us debug this:
> [ 2.771162] Possible unsafe locking scenario:
> [ 2.771162]
> [ 2.771174] CPU0
> [ 2.771182] ----
> [ 2.771190] lock(&(&dd->lock)->rlock);
> [ 2.771202] <Interrupt>
> [ 2.771209] lock(&(&dd->lock)->rlock);
> [ 2.771222]
> [ 2.771222] *** DEADLOCK ***
> [ 2.771222]
> [ 2.771240] 2 locks held by swapper/17/0:
> [ 2.771252] #0: (____ptrval____) (&(&vio->lock)->rlock){-...}, at:
> vdc_event+0xc/0x2c0
> [ 2.771279] #1: (____ptrval____) (rcu_read_lock){....}, at:
> hctx_lock+0x1c/0x100
> [ 2.771308]
> [ 2.771308] stack backtrace:
> [ 2.771329] CPU: 17 PID: 0 Comm: swapper/17 Tainted: G W
> 4.20.0-rc1-00089-gfa182a1fa97d #812
> [ 2.771353] Call Trace:
> [ 2.771368] [00000000004d18ec] print_usage_bug+0x2d4/0x2e8
> [ 2.771387] [00000000004cd168] mark_lock+0x4c8/0x880
> [ 2.771406] [00000000004cec08] __lock_acquire+0x348/0x1fa0
> [ 2.771424] [00000000004d12d8] lock_acquire+0x198/0x1c0
> [ 2.771444] [0000000000a0f670] _raw_spin_lock+0x30/0x60
> [ 2.771463] [00000000007e839c] dd_dispatch_request+0x1c/0x200
> [ 2.771484] [00000000007cae68] blk_mq_do_dispatch_sched+0x68/0x100
> [ 2.771504] [00000000007cb31c] blk_mq_sched_dispatch_requests+0x11c/0x180
> [ 2.771524] [00000000007c36f8] __blk_mq_run_hw_queue+0x118/0x140
> [ 2.771545] [00000000007c3784] __blk_mq_delay_run_hw_queue+0x64/0x1a0
> [ 2.771564] [00000000007c5628] blk_mq_run_hw_queue+0xc8/0x100
> [ 2.771583] [00000000007c69c0] blk_mq_start_hw_queues+0x40/0x60
> [ 2.771602] [00000000008604fc] vdc_blk_queue_start+0x5c/0x80
> [ 2.771620] [00000000008619fc] vdc_event+0x1fc/0x2c0
> [ 2.771640] [0000000000446aac] send_events.isra.3+0x4c/0x60
> [ 2.771659] [00000000004487d4] ldc_rx+0x234/0x260
> [ 28.756775] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 28.756823] rcu: 23-...!: (0 ticks this GP)
> idle=282/1/0x4000000000000000 softirq=29/29 fqs=1
> [ 28.756859] rcu: (detected by 9, t=2602 jiffies, g=-1023, q=6280)
> [ 28.756915] CPU[ 23]: TSTATE[0000004411001603]
> TPC[00000000004d2f28] TNPC[00000000004d2f2c] TASK[(worker):273]
> [ 28.756963] TPC[queued_spin_lock_slowpath+0x1e8/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 28.757013] rcu: rcu_sched kthread starved for 2599 jiffies! g-1023
> f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=17
> [ 28.757044] rcu: RCU grace-period kthread stack dump:
> [ 28.757063] rcu_sched I 0 10 2 0x06000000
> [ 28.757086] Call Trace:
> [ 28.757104] [0000000000a093bc] schedule+0x7c/0xc0
> [ 28.757124] [0000000000a0ea98] schedule_timeout+0x478/0x4a0
> [ 28.757148] [00000000004eec64] rcu_gp_kthread+0xe44/0x1a00
> [ 28.757172] [000000000048d2d4] kthread+0x114/0x140
> [ 28.757194] [00000000004060e4] ret_from_fork+0x1c/0x2c
> [ 28.757213] [0000000000000000] (null)
> [ 54.776775] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 54.776824] rcu: 16-...0: (1 GPs behind)
> idle=4ea/1/0x4000000000000000 softirq=32/33 fqs=696
> [ 54.776855] rcu: 17-...0: (1 GPs behind)
> idle=456/1/0x4000000000000002 softirq=48/49 fqs=696
> [ 54.776886] rcu: 18-...0: (1 GPs behind)
> idle=382/1/0x4000000000000000 softirq=35/36 fqs=696
> [ 54.776916] rcu: 21-...0: (1 GPs behind)
> idle=396/1/0x4000000000000000 softirq=48/48 fqs=696
> [ 54.776946] rcu: 23-...0: (1 GPs behind)
> idle=282/1/0x4000000000000000 softirq=29/29 fqs=696
> [ 54.776978] rcu: (detected by 0, t=2602 jiffies, g=-1019, q=5511)
> [ 54.777034] CPU[ 16]: TSTATE[0000004411001607]
> TPC[00000000004d2f24] TNPC[00000000004d2f28] TASK[(worker):277]
> [ 54.777083] TPC[queued_spin_lock_slowpath+0x1e4/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 54.777131] CPU[ 17]: TSTATE[0000000080001600]
> TPC[00000000004d2f68] TNPC[00000000004d2f6c] TASK[(worker):275]
> [ 54.777167] TPC[queued_spin_lock_slowpath+0x228/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 54.777215] CPU[ 18]: TSTATE[0000000011001602]
> TPC[00000000004d2dcc] TNPC[00000000004d2dd0] TASK[(worker):259]
> [ 54.777250] TPC[queued_spin_lock_slowpath+0x8c/0x2e0]
> O7[queued_spin_lock_slowpath+0x48/0x2e0]
> I7[do_raw_spin_lock+0xe0/0x100] RPC[printk+0x28/0x38]
> [ 54.777303] CPU[ 21]: TSTATE[0000004411001607]
> TPC[00000000004d2f24] TNPC[00000000004d2f28] TASK[(worker):278]
> [ 54.777338] TPC[queued_spin_lock_slowpath+0x1e4/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 54.777385] CPU[ 23]: TSTATE[0000004411001603]
> TPC[00000000004d2f34] TNPC[00000000004d2f38] TASK[(worker):273]
> [ 54.777420] TPC[queued_spin_lock_slowpath+0x1f4/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> Begin: Loading essential drivers ... [ 123.216802] raid6: int64x1
> gen() 2851 MB/s
> [ 123.386799] raid6: int64x1 xor() 1628 MB/s
> [ 123.556800] raid6: int64x2 gen() 2873 MB/s
> [ 123.726802] raid6: int64x2 xor() 1993 MB/s
> [ 123.896794] raid6: int64x4 gen() 3469 MB/s
> [ 124.066809] raid6: int64x4 xor() 1997 MB/s
> [ 124.236818] raid6: int64x8 gen() 2211 MB/s
> [ 124.406796] raid6: int64x8 xor() 1588 MB/s
> [ 124.406820] raid6: using algorithm int64x4 gen() 3469 MB/s
> [ 124.406842] raid6: .... xor() 1997 MB/s, rmw enabled
> [ 124.406861] raid6: using intx1 recovery algorithm
> [ 124.407581] async_tx: api initialized (async)
> [ 124.408008] xor: automatically using best checksumming function Niagara
> done.
> Begin: Running /scripts/init-premount ... done.
> Begin: Mounting root file system ... Begin: Running /scripts/local-top ... done.
> Begin: Running /scripts/local-premount ... done.
> [ 132.826776] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 132.826824] rcu: 16-...0: (1 GPs behind)
> idle=4ea/1/0x4000000000000000 softirq=32/33 fqs=2955
> [ 132.826856] rcu: 17-...0: (1 GPs behind)
> idle=456/1/0x4000000000000002 softirq=48/49 fqs=2955
> [ 132.826886] rcu: 18-...0: (1 GPs behind)
> idle=382/1/0x4000000000000000 softirq=35/36 fqs=2955
> [ 132.826916] rcu: 21-...0: (1 GPs behind)
> idle=396/1/0x4000000000000000 softirq=48/48 fqs=2955
> [ 132.826946] rcu: 23-...0: (1 GPs behind)
> idle=282/1/0x4000000000000000 softirq=29/29 fqs=2955
> [ 132.826979] rcu: (detected by 10, t=10407 jiffies, g=-1019, q=6474)
> [ 132.827034] CPU[ 16]: TSTATE[0000004411001607]
> TPC[00000000004d2f28] TNPC[00000000004d2f2c] TASK[(worker):277]
> [ 132.827082] TPC[queued_spin_lock_slowpath+0x1e8/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 132.827129] CPU[ 17]: TSTATE[0000000080001600]
> TPC[00000000004d2f74] TNPC[00000000004d2f78] TASK[(worker):275]
> [ 132.827165] TPC[queued_spin_lock_slowpath+0x234/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 132.827211] CPU[ 18]: TSTATE[0000000011001602]
> TPC[00000000004d2dcc] TNPC[00000000004d2dd0] TASK[(worker):259]
> [ 132.827246] TPC[queued_spin_lock_slowpath+0x8c/0x2e0]
> O7[queued_spin_lock_slowpath+0x48/0x2e0]
> I7[do_raw_spin_lock+0xe0/0x100] RPC[printk+0x28/0x38]
> [ 132.827297] CPU[ 21]: TSTATE[0000004411001607]
> TPC[00000000004d2f28] TNPC[00000000004d2f2c] TASK[(worker):278]
> [ 132.827331] TPC[queued_spin_lock_slowpath+0x1e8/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 132.827379] CPU[ 23]: TSTATE[0000004411001603]
> TPC[00000000004d2f28] TNPC[00000000004d2f2c] TASK[(worker):273]
> [ 132.827413] TPC[queued_spin_lock_slowpath+0x1e8/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> Begin: Will now check root file system ... fsck from util-linux 2.32.1
> [/sbin/fsck.ext4 (1) -- /dev/vdiska2] fsck.ext4 -a -C0 /dev/vdiska2
> /dev/vdiska2: clean, 189379/912128 files, 3325357/3662820 blocks
> done.
> [ 134.608390] EXT4-fs (vdiska2): mounted filesystem with ordered data
> mode. Opts: (null)
> done.
> [ 134.609911] random: fast init done
> Begin: Running /scripts/local-bottom ... done.
> Begin: Running /scripts/init-bottom ... [ 156.606777] watchdog: BUG:
> soft lockup - CPU#1 stuck for 22s! [(worker):283]
> [ 156.606824] Modules linked in: ext4 crc16 mbcache jbd2 raid10
> raid456 libcrc32c crc32c_generic async_raid6_recov async_memcpy
> async_pq async_xor xor async_tx raid6_pq raid1 raid0 multipath linear
> md_mod crc32c_sparc64
> [ 156.606906] irq event stamp: 0
> [ 156.606922] hardirqs last enabled at (0): [<0000000000000000>]
> (null)
> [ 156.606955] hardirqs last disabled at (0): [<0000000000461774>]
> copy_process.isra.3+0x474/0x1a60
> [ 156.606985] softirqs last enabled at (0): [<0000000000461774>]
> copy_process.isra.3+0x474/0x1a60
> [ 156.607014] softirqs last disabled at (0): [<0000000000000000>]
> (null)
> [ 156.607042] CPU: 1 PID: 283 Comm: (worker) Tainted: G W
> 4.20.0-rc1-00089-gfa182a1fa97d #812
> [ 156.607073] TSTATE: 0000000011001604 TPC: 00000000005140e8 TNPC:
> 00000000005140ec Y: 00000000 Tainted: G W
> [ 156.607111] TPC: <smp_call_function_single+0x108/0x180>
> [ 156.607130] g0: 000000000000000e g1: 0000000000000003 g2:
> 000000000000000e g3: 0000000000000001
> [ 156.607158] g4: fff800249aa316e0 g5: fff80024aa2c8000 g6:
> fff800249b990000 g7: 0000000000000100
> [ 156.607185] o0: 0000000000000000 o1: fff800249b9934e0 o2:
> 000000000043ffe0 o3: fff800249b993688
> [ 156.607213] o4: 00000000014db000 o5: 0000000000000000 sp:
> fff800249b992c31 ret_pc: 000000000051410c
> [ 156.607242] RPC: <smp_call_function_single+0x12c/0x180>
> [ 156.607261] l0: 0000000000ca4000 l1: ffffffffffffffe0 l2:
> 000000000000000e l3: 000000000044fad4
> [ 156.607289] l4: 0000000000000000 l5: 0000000000000000 l6:
> 0000000000000000 l7: fff80001003c0000
> [ 156.607316] i0: 0000000000000012 i1: 000000000043ffe0 i2:
> fff800249b993688 i3: 0000000000000001
> [ 156.607344] i4: 0000000000000001 i5: fff800249b9934e0 i6:
> fff800249b992d21 i7: 00000000005145b8
> [ 156.607372] I7: <smp_call_function_many+0x118/0x320>
> [ 156.607390] Call Trace:
> [ 156.607404] [00000000005145b8] smp_call_function_many+0x118/0x320
> [ 156.607427] [0000000000441198] smp_flush_tlb_pending+0x98/0xe0
> [ 156.607449] [000000000044f2c0] flush_tlb_pending+0x80/0xa0
> [ 156.607470] [000000000044f624] arch_leave_lazy_mmu_mode+0x24/0x40
> [ 156.607499] [00000000006211f4] unmap_page_range+0x754/0x900
> [ 156.607520] [0000000000621444] unmap_single_vma+0xa4/0xc0
> [ 156.607540] [0000000000621530] unmap_vmas+0x30/0x60
> [ 156.607560] [000000000062ab7c] exit_mmap+0xdc/0x160
> [ 156.607579] [0000000000460ff8] mmput+0x78/0x120
> [ 156.607598] [000000000046a0d0] do_exit+0x3f0/0xbe0
> [ 156.607617] [000000000046a9e8] do_group_exit+0xa8/0xc0
> [ 156.607637] [000000000046aa18] sys_exit_group+0x18/0x40
> [ 156.607659] [0000000000406294] linux_sparc_syscall+0x34/0x44
> done.
> [ 181.386785] BUG: workqueue lockup - pool cpus=1 node=0 flags=0x0
> nice=0 stuck for 45s!
> [ 181.386955] Showing busy workqueues and worker pools:
> [ 181.387020] workqueue events: flags=0x0
> [ 181.387354] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 181.387383] pending: cache_reap
> [ 181.387755] workqueue mm_percpu_wq: flags=0x8
> [ 181.388073] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 181.388099] pending: vmstat_update
> [ 181.388631] workqueue kblockd: flags=0x18
> [ 181.389095] pwq 21: cpus=10 node=0 flags=0x0 nice=-20 active=1/256
> [ 181.389123] in-flight: 346:blk_mq_run_work_fn
> [ 181.390238] pool 21: cpus=10 node=0 flags=0x0 nice=-20 hung=15s
> workers=2 idle: 63
> [ 210.876775] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 210.876824] rcu: 16-...0: (1 GPs behind)
> idle=4ea/1/0x4000000000000000 softirq=32/33 fqs=4979
> [ 210.876857] rcu: 17-...0: (1 GPs behind)
> idle=456/1/0x4000000000000002 softirq=48/49 fqs=4979
> [ 210.876888] rcu: 18-...0: (1 GPs behind)
> idle=382/1/0x4000000000000000 softirq=35/36 fqs=4979
> [ 210.876919] rcu: 21-...0: (1 GPs behind)
> idle=396/1/0x4000000000000000 softirq=48/48 fqs=4979
> [ 210.876949] rcu: 23-...0: (1 GPs behind)
> idle=282/1/0x4000000000000000 softirq=29/29 fqs=4979
> [ 210.876983] rcu: (detected by 11, t=18212 jiffies, g=-1019, q=8345)
> [ 210.877044] CPU[ 16]: TSTATE[0000004411001607]
> TPC[00000000004d2f28] TNPC[00000000004d2f2c] TASK[(worker):277]
> [ 210.877096] TPC[queued_spin_lock_slowpath+0x1e8/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 210.877145] CPU[ 17]: TSTATE[0000000080001600]
> TPC[00000000004d2f68] TNPC[00000000004d2f6c] TASK[(worker):275]
> [ 210.877181] TPC[queued_spin_lock_slowpath+0x228/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 210.877229] CPU[ 18]: TSTATE[0000000011001602]
> TPC[00000000004d2dd0] TNPC[00000000004d2dd4] TASK[(worker):259]
> [ 210.877264] TPC[queued_spin_lock_slowpath+0x90/0x2e0]
> O7[queued_spin_lock_slowpath+0x48/0x2e0]
> I7[do_raw_spin_lock+0xe0/0x100] RPC[printk+0x28/0x38]
> [ 210.877317] CPU[ 21]: TSTATE[0000004411001607]
> TPC[00000000004d2f24] TNPC[00000000004d2f28] TASK[(worker):278]
> [ 210.877353] TPC[queued_spin_lock_slowpath+0x1e4/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 210.877402] CPU[ 23]: TSTATE[0000004411001603]
> TPC[00000000004d2f24] TNPC[00000000004d2f28] TASK[(worker):273]
> [ 210.877438] TPC[queued_spin_lock_slowpath+0x1e4/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 211.466782] BUG: workqueue lockup - pool cpus=1 node=0 flags=0x0
> nice=0 stuck for 76s!
> [ 211.466945] Showing busy workqueues and worker pools:
> [ 211.467011] workqueue events: flags=0x0
> [ 211.467363] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 211.467390] pending: cache_reap
> [ 211.467765] workqueue mm_percpu_wq: flags=0x8
> [ 211.468083] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 211.468109] pending: vmstat_update
> [ 211.468666] workqueue kblockd: flags=0x18
> [ 211.469149] pwq 21: cpus=10 node=0 flags=0x0 nice=-20 active=1/256
> [ 211.469177] in-flight: 346:blk_mq_run_work_fn
> [ 211.470339] pool 21: cpus=10 node=0 flags=0x0 nice=-20 hung=45s
> workers=2 idle: 63
> [ 241.536782] BUG: workqueue lockup - pool cpus=1 node=0 flags=0x0
> nice=0 stuck for 106s!
> [ 241.536941] Showing busy workqueues and worker pools:
> [ 241.537005] workqueue events: flags=0x0
> [ 241.537355] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 241.537382] pending: cache_reap
> [ 241.537757] workqueue mm_percpu_wq: flags=0x8
> [ 241.538075] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 241.538101] pending: vmstat_update
> [ 241.538659] workqueue kblockd: flags=0x18
> [ 241.539144] pwq 21: cpus=10 node=0 flags=0x0 nice=-20 active=1/256
> [ 241.539172] in-flight: 346:blk_mq_run_work_fn
> [ 241.540333] pool 21: cpus=10 node=0 flags=0x0 nice=-20 hung=75s
> workers=2 idle: 63
> [ 271.616790] BUG: workqueue lockup - pool cpus=1 node=0 flags=0x0
> nice=0 stuck for 136s!
> [ 271.616954] Showing busy workqueues and worker pools:
> [ 271.617019] workqueue events: flags=0x0
> [ 271.617374] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 271.617402] pending: cache_reap
> [ 271.617775] workqueue mm_percpu_wq: flags=0x8
> [ 271.618094] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 271.618120] pending: vmstat_update
> [ 271.618675] workqueue kblockd: flags=0x18
> [ 271.619157] pwq 21: cpus=10 node=0 flags=0x0 nice=-20 active=1/256
> [ 271.619185] in-flight: 346:blk_mq_run_work_fn
> [ 271.620347] pool 21: cpus=10 node=0 flags=0x0 nice=-20 hung=105s
> workers=2 idle: 63
> [ 288.926774] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 288.926825] rcu: 16-...0: (1 GPs behind)
> idle=4ea/1/0x4000000000000000 softirq=32/33 fqs=7017
> [ 288.926857] rcu: 17-...0: (1 GPs behind)
> idle=456/1/0x4000000000000002 softirq=48/49 fqs=7017
> [ 288.926888] rcu: 18-...0: (1 GPs behind)
> idle=382/1/0x4000000000000000 softirq=35/36 fqs=7017
> [ 288.926918] rcu: 21-...0: (1 GPs behind)
> idle=396/1/0x4000000000000000 softirq=48/48 fqs=7017
> [ 288.926947] rcu: 23-...0: (1 GPs behind)
> idle=282/1/0x4000000000000000 softirq=29/29 fqs=7017
> [ 288.926980] rcu: (detected by 1, t=26017 jiffies, g=-1019, q=8351)
> [ 288.927036] CPU[ 16]: TSTATE[0000004411001607]
> TPC[00000000004d2f28] TNPC[00000000004d2f2c] TASK[(worker):277]
> [ 288.927084] TPC[queued_spin_lock_slowpath+0x1e8/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 288.927131] CPU[ 17]: TSTATE[0000000080001600]
> TPC[00000000004d2f6c] TNPC[00000000004d2f70] TASK[(worker):275]
> [ 288.927167] TPC[queued_spin_lock_slowpath+0x22c/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 288.927214] CPU[ 18]: TSTATE[0000000011001602]
> TPC[00000000004d2dd0] TNPC[00000000004d2dd4] TASK[(worker):259]
> [ 288.927250] TPC[queued_spin_lock_slowpath+0x90/0x2e0]
> O7[queued_spin_lock_slowpath+0x48/0x2e0]
> I7[do_raw_spin_lock+0xe0/0x100] RPC[printk+0x28/0x38]
> [ 288.927302] CPU[ 21]: TSTATE[0000004411001607]
> TPC[00000000004d2f28] TNPC[00000000004d2f2c] TASK[(worker):278]
> [ 288.927337] TPC[queued_spin_lock_slowpath+0x1e8/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 288.927385] CPU[ 23]: TSTATE[0000004411001603]
> TPC[00000000004d2f24] TNPC[00000000004d2f28] TASK[(worker):273]
> [ 288.927420] TPC[queued_spin_lock_slowpath+0x1e4/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 316.606777] watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [(worker):283]
> [ 316.606823] Modules linked in: ext4 crc16 mbcache jbd2 raid10
> raid456 libcrc32c crc32c_generic async_raid6_recov async_memcpy
> async_pq async_xor xor async_tx raid6_pq raid1 raid0 multipath linear
> md_mod crc32c_sparc64
> [ 316.606910] irq event stamp: 0
> [ 316.606926] hardirqs last enabled at (0): [<0000000000000000>]
> (null)
> [ 316.606959] hardirqs last disabled at (0): [<0000000000461774>]
> copy_process.isra.3+0x474/0x1a60
> [ 316.606988] softirqs last enabled at (0): [<0000000000461774>]
> copy_process.isra.3+0x474/0x1a60
> [ 316.607016] softirqs last disabled at (0): [<0000000000000000>]
> (null)
> [ 316.607044] CPU: 1 PID: 283 Comm: (worker) Tainted: G W L
> 4.20.0-rc1-00089-gfa182a1fa97d #812
> [ 316.607075] TSTATE: 0000000011001604 TPC: 00000000005140e4 TNPC:
> 00000000005140e8 Y: 00000000 Tainted: G W L
> [ 316.607112] TPC: <smp_call_function_single+0x104/0x180>
> [ 316.607131] g0: 000000000000000e g1: 0000000000000003 g2:
> 000000000000000e g3: 0000000000000001
> [ 316.607159] g4: fff800249aa316e0 g5: fff80024aa2c8000 g6:
> fff800249b990000 g7: 0000000000000100
> [ 316.607187] o0: 0000000000000000 o1: fff800249b9934e0 o2:
> 000000000043ffe0 o3: fff800249b993688
> [ 316.607214] o4: 00000000014db000 o5: 0000000000000000 sp:
> fff800249b992c31 ret_pc: 000000000051410c
> [ 316.607243] RPC: <smp_call_function_single+0x12c/0x180>
> [ 316.607263] l0: 0000000000ca4000 l1: ffffffffffffffe0 l2:
> 000000000000000e l3: 000000000044fad4
> [ 316.607290] l4: 0000000000000000 l5: 0000000000000000 l6:
> 0000000000000000 l7: fff80001003c0000
> [ 316.607318] i0: 0000000000000012 i1: 000000000043ffe0 i2:
> fff800249b993688 i3: 0000000000000001
> [ 316.607345] i4: 0000000000000001 i5: fff800249b9934e0 i6:
> fff800249b992d21 i7: 00000000005145b8
> [ 316.607374] I7: <smp_call_function_many+0x118/0x320>
> [ 316.607392] Call Trace:
> [ 316.607405] [00000000005145b8] smp_call_function_many+0x118/0x320
> [ 316.607429] [0000000000441198] smp_flush_tlb_pending+0x98/0xe0
> [ 316.607450] [000000000044f2c0] flush_tlb_pending+0x80/0xa0
> [ 316.607471] [000000000044f624] arch_leave_lazy_mmu_mode+0x24/0x40
> [ 316.607500] [00000000006211f4] unmap_page_range+0x754/0x900
> [ 316.607521] [0000000000621444] unmap_single_vma+0xa4/0xc0
> [ 316.607541] [0000000000621530] unmap_vmas+0x30/0x60
> [ 316.607561] [000000000062ab7c] exit_mmap+0xdc/0x160
> [ 316.607580] [0000000000460ff8] mmput+0x78/0x120
> [ 316.607600] [000000000046a0d0] do_exit+0x3f0/0xbe0
> [ 316.607618] [000000000046a9e8] do_group_exit+0xa8/0xc0
> [ 316.607638] [000000000046aa18] sys_exit_group+0x18/0x40
> [ 316.607660] [0000000000406294] linux_sparc_syscall+0x34/0x44
> [ 331.776787] BUG: workqueue lockup - pool cpus=1 node=0 flags=0x0
> nice=0 stuck for 196s!
> [ 331.776945] Showing busy workqueues and worker pools:
> [ 331.777009] workqueue events: flags=0x0
> [ 331.777361] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 331.777389] pending: cache_reap
> [ 331.777764] workqueue mm_percpu_wq: flags=0x8
> [ 331.778082] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 331.778108] pending: vmstat_update
> [ 331.778668] workqueue kblockd: flags=0x18
> [ 331.779146] pwq 21: cpus=10 node=0 flags=0x0 nice=-20 active=1/256
> [ 331.779174] in-flight: 346:blk_mq_run_work_fn
> [ 331.780335] pool 21: cpus=10 node=0 flags=0x0 nice=-20 hung=166s
> workers=2 idle: 63
> [ 361.866781] BUG: workqueue lockup - pool cpus=1 node=0 flags=0x0
> nice=0 stuck for 226s!
> [ 361.866941] Showing busy workqueues and worker pools:
> [ 361.867005] workqueue events: flags=0x0
> [ 361.867357] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 361.867386] pending: cache_reap
> [ 361.867761] workqueue mm_percpu_wq: flags=0x8
> [ 361.868079] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 361.868104] pending: vmstat_update
> [ 361.868662] workqueue kblockd: flags=0x18
> [ 361.869151] pwq 21: cpus=10 node=0 flags=0x0 nice=-20 active=1/256
> [ 361.869179] in-flight: 346:blk_mq_run_work_fn
> [ 361.870338] pool 21: cpus=10 node=0 flags=0x0 nice=-20 hung=196s
> workers=2 idle: 63
> [ 366.976775] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 366.976826] rcu: 16-...0: (1 GPs behind)
> idle=4ea/1/0x4000000000000000 softirq=32/33 fqs=9072
> [ 366.976858] rcu: 17-...0: (1 GPs behind)
> idle=456/1/0x4000000000000002 softirq=48/49 fqs=9072
> [ 366.976889] rcu: 18-...0: (1 GPs behind)
> idle=382/1/0x4000000000000000 softirq=35/36 fqs=9072
> [ 366.976919] rcu: 21-...0: (1 GPs behind)
> idle=396/1/0x4000000000000000 softirq=48/48 fqs=9072
> [ 366.976950] rcu: 23-...0: (1 GPs behind)
> idle=282/1/0x4000000000000000 softirq=29/29 fqs=9072
> [ 366.976983] rcu: (detected by 6, t=33822 jiffies, g=-1019, q=8375)
> [ 366.977050] CPU[ 16]: TSTATE[0000004411001607]
> TPC[00000000004d2f24] TNPC[00000000004d2f28] TASK[(worker):277]
> [ 366.977103] TPC[queued_spin_lock_slowpath+0x1e4/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 366.977152] CPU[ 17]: TSTATE[0000000080001600]
> TPC[00000000004d2f68] TNPC[00000000004d2f6c] TASK[(worker):275]
> [ 366.977188] TPC[queued_spin_lock_slowpath+0x228/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 366.977236] CPU[ 18]: TSTATE[0000000011001602]
> TPC[00000000004d2dcc] TNPC[00000000004d2dd0] TASK[(worker):259]
> [ 366.977272] TPC[queued_spin_lock_slowpath+0x8c/0x2e0]
> O7[queued_spin_lock_slowpath+0x48/0x2e0]
> I7[do_raw_spin_lock+0xe0/0x100] RPC[printk+0x28/0x38]
> [ 366.977326] CPU[ 21]: TSTATE[0000004411001607]
> TPC[00000000004d2f30] TNPC[00000000004d2f34] TASK[(worker):278]
> [ 366.977362] TPC[queued_spin_lock_slowpath+0x1f0/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 366.977411] CPU[ 23]: TSTATE[0000004411001603]
> TPC[00000000004d2f24] TNPC[00000000004d2f28] TASK[(worker):273]
> [ 366.977446] TPC[queued_spin_lock_slowpath+0x1e4/0x2e0]
> O7[0xfff800249f6ea000] I7[do_raw_spin_lock+0xe0/0x100]
> RPC[printk+0x28/0x38]
> [ 391.946784] BUG: workqueue lockup - pool cpus=1 node=0 flags=0x0
> nice=0 stuck for 256s!
> [ 391.946946] Showing busy workqueues and worker pools:
> [ 391.947011] workqueue events: flags=0x0
> [ 391.947365] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 391.947393] pending: cache_reap
> [ 391.947768] workqueue mm_percpu_wq: flags=0x8
> [ 391.948086] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 391.948111] pending: vmstat_update
> [ 391.948669] workqueue kblockd: flags=0x18
> [ 391.949152] pwq 21: cpus=10 node=0 flags=0x0 nice=-20 active=1/256
> [ 391.949180] in-flight: 346:blk_mq_run_work_fn
> [ 391.950340] pool 21: cpus=10 node=0 flags=0x0 nice=-20 hung=226s
> workers=2 idle: 63
> [ 422.016789] BUG: workqueue lockup - pool cpus=1 node=0 flags=0x0
> nice=0 stuck for 286s!
> [ 422.016950] Showing busy workqueues and worker pools:
> [ 422.017015] workqueue events: flags=0x0
> [ 422.017371] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 422.017398] pending: cache_reap
> [ 422.017771] workqueue mm_percpu_wq: flags=0x8
> [ 422.018089] pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256
> [ 422.018114] pending: vmstat_update
> [ 422.018672] workqueue kblockd: flags=0x18
> [ 422.019155] pwq 21: cpus=10 node=0 flags=0x0 nice=-20 active=1/256
> [ 422.019183] in-flight: 346:blk_mq_run_work_fn
> [ 422.020344] pool 21: cpus=10 node=0 flags=0x0 nice=-20 hung=256s
> workers=2 idle: 63
>
>
>
>
>
> bisected kernel to the following commit:
>
>
> mator@ttip:~$ cd linux-2.6
> mator@ttip:~/linux-2.6$ git desc
> v4.20-rc1-88-gea2c18e1044e
>
> mator@ttip:~/linux-2.6$ git bisect good
> fa182a1fa97dff56cda742f22d17d666420cd27f is the first bad commit
> commit fa182a1fa97dff56cda742f22d17d666420cd27f
> Author: Jens Axboe <axboe@xxxxxxxxx>
> Date: Mon Oct 15 08:54:23 2018 -0600
>
> sunvdc: convert to blk-mq
>
> Convert from the old request_fn style driver to blk-mq.
>
> Cc: David Miller <davem@xxxxxxxxxxxxx>
> Reviewed-by: Hannes Reinecke <hare@xxxxxxxx>
> Tested-by: Ming Lei <ming.lei@xxxxxxxxxx>
> Reviewed-by: Omar Sandoval <osandov@xxxxxx>
> Signed-off-by: Jens Axboe <axboe@xxxxxxxxx>
>
> :040000 040000 2860baedf9e55349500dbc7ae738562f1e2ee05b
> dfe5d1704ab9598a654aa4e4700487c33bd43039 M drivers
>
> mator@ttip:~/linux-2.6$ git bisect log
> git bisect start
> # good: [00c569b567c7f1f0da6162868fd02a9f29411805] Merge tag
> 'locks-v4.21-1' of
> git://git.kernel.org/pub/scm/linux/kernel/git/jlayton/linux
> git bisect good 00c569b567c7f1f0da6162868fd02a9f29411805
> # bad: [903b77c631673eeec9e9114e9524171cdf9a2646] Merge tag
> 'linux-kselftest-4.21-rc1' of
> git://git.kernel.org/pub/scm/linux/kernel/git/shuah/linux-kselftest
> git bisect bad 903b77c631673eeec9e9114e9524171cdf9a2646
> # bad: [1984f65c2fbc0d2b557d6e89ece9b39267e215c6] Merge tag
> 'vfio-v4.21-rc1' of git://github.com/awilliam/linux-vfio
> git bisect bad 1984f65c2fbc0d2b557d6e89ece9b39267e215c6
> # bad: [938edb8a31b976c9a92eb0cd4ff481e93f76c1f1] Merge tag
> 'scsi-misc' of git://git.kernel.org/pub/scm/linux/kernel/git/jejb/scsi
> git bisect bad 938edb8a31b976c9a92eb0cd4ff481e93f76c1f1
> # bad: [00203ba40d40d7f33857416adfb18adaf0e40123] kyber: use sbitmap
> add_wait_queue/list_del wait helpers
> git bisect bad 00203ba40d40d7f33857416adfb18adaf0e40123
> # bad: [c6d962aebaf8ec5d867aac09ee33e3f528c2539d] nvme-pci: only allow
> polling with separate poll queues
> git bisect bad c6d962aebaf8ec5d867aac09ee33e3f528c2539d
> # bad: [511c49fe1804671800947b69281e07719fad25e2] fnic: fix
> fnic_scsi_host_{start,end}_tag
> git bisect bad 511c49fe1804671800947b69281e07719fad25e2
> # bad: [3110fc79606fb6003949246c6fb325dd43445273] blk-mq: improve plug
> list sorting
> git bisect bad 3110fc79606fb6003949246c6fb325dd43445273
> # bad: [a1ce35fa49852db60fc6e268038530be533c5b15] block: remove dead
> elevator code
> git bisect bad a1ce35fa49852db60fc6e268038530be533c5b15
> # bad: [c6f2882691e8fd128083abdcc3c5aa5b410c2367] block: remove q->lld_busy_fn()
> git bisect bad c6f2882691e8fd128083abdcc3c5aa5b410c2367
> # bad: [600335205b8d162891b5ef2e32343f5b8020efd8] ide: convert to blk-mq
> git bisect bad 600335205b8d162891b5ef2e32343f5b8020efd8
> # bad: [fa182a1fa97dff56cda742f22d17d666420cd27f] sunvdc: convert to blk-mq
> git bisect bad fa182a1fa97dff56cda742f22d17d666420cd27f
> # good: [ea2c18e1044e9ed8f780c965c50432060ab0e355] null_blk: Add
> conventional zone configuration for zoned support
> git bisect good ea2c18e1044e9ed8f780c965c50432060ab0e355
> # first bad commit: [fa182a1fa97dff56cda742f22d17d666420cd27f] sunvdc:
> convert to blk-mq
> mator@ttip:~/linux-2.6$
Could you try the following patch and see if it makes a difference?
diff --git a/drivers/block/sunvdc.c b/drivers/block/sunvdc.c
index 9c0553dd13e7..6eddd17a864a 100644
--- a/drivers/block/sunvdc.c
+++ b/drivers/block/sunvdc.c
@@ -181,7 +181,7 @@ static void vdc_blk_queue_start(struct vdc_port *port)
* allocated a disk.
*/
if (port->disk && vdc_tx_dring_avail(dr) * 100 / VDC_TX_RING_SIZE >= 50)
- blk_mq_start_hw_queues(port->disk->queue);
+ blk_mq_start_stopped_hw_queue(port->disk->queue, true);
}
static void vdc_finish(struct vio_driver_state *vio, int err, int waiting_for)
Thanks,
Ming
