From: Ming Lei <ming.lei@redhat.com>
To: sparclinux@vger.kernel.org
Subject: Re: [sparc64] unable to boot git kernel / deadlock / cpu stall
Date: Wed, 02 Jan 2019 12:08:43 +0000 [thread overview]
Message-ID: <20190102120842.GA30385@ming.t460p> (raw)
In-Reply-To: <CADxRZqwwE5wu6KSvydtEggpdb+5XjNpk+uCeE8vJYp72TCJY=w@mail.gmail.com>
[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="windows-1254", Size: 53398 bytes --]
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Þadline
> [ 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Þadline
> [ 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\x10021012)
> [ 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 00 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_bitsF max_order# 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@redhat.com
> [ 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(2/1/0x4000000000000000 softirq)/29 fqs=1
> [ 28.756859] rcu: (detected by 9, t&02 jiffies, g=-1023, qb80)
> [ 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\x17
> [ 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)
> idleNa/1/0x4000000000000000 softirq2/33 fqsi6
> [ 54.776855] rcu: 17-...0: (1 GPs behind)
> idleE6/1/0x4000000000000002 softirqH/49 fqsi6
> [ 54.776886] rcu: 18-...0: (1 GPs behind)
> idle82/1/0x4000000000000000 softirq5/36 fqsi6
> [ 54.776916] rcu: 21-...0: (1 GPs behind)
> idle96/1/0x4000000000000000 softirqH/48 fqsi6
> [ 54.776946] rcu: 23-...0: (1 GPs behind)
> idle(2/1/0x4000000000000000 softirq)/29 fqsi6
> [ 54.776978] rcu: (detected by 0, t&02 jiffies, g=-1019, qU11)
> [ 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)
> idleNa/1/0x4000000000000000 softirq2/33 fqs)55
> [ 132.826856] rcu: 17-...0: (1 GPs behind)
> idleE6/1/0x4000000000000002 softirqH/49 fqs)55
> [ 132.826886] rcu: 18-...0: (1 GPs behind)
> idle82/1/0x4000000000000000 softirq5/36 fqs)55
> [ 132.826916] rcu: 21-...0: (1 GPs behind)
> idle96/1/0x4000000000000000 softirqH/48 fqs)55
> [ 132.826946] rcu: 23-...0: (1 GPs behind)
> idle(2/1/0x4000000000000000 softirq)/29 fqs)55
> [ 132.826979] rcu: (detected by 10, t\x10407 jiffies, g=-1019, qd74)
> [ 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\x10 node=0 flags=0x0 nice=-20 active=1/256
> [ 181.389123] in-flight: 346:blk_mq_run_work_fn
> [ 181.390238] pool 21: cpus\x10 node=0 flags=0x0 nice=-20 hung\x15s
> workers=2 idle: 63
> [ 210.876775] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 210.876824] rcu: 16-...0: (1 GPs behind)
> idleNa/1/0x4000000000000000 softirq2/33 fqsI79
> [ 210.876857] rcu: 17-...0: (1 GPs behind)
> idleE6/1/0x4000000000000002 softirqH/49 fqsI79
> [ 210.876888] rcu: 18-...0: (1 GPs behind)
> idle82/1/0x4000000000000000 softirq5/36 fqsI79
> [ 210.876919] rcu: 21-...0: (1 GPs behind)
> idle96/1/0x4000000000000000 softirqH/48 fqsI79
> [ 210.876949] rcu: 23-...0: (1 GPs behind)
> idle(2/1/0x4000000000000000 softirq)/29 fqsI79
> [ 210.876983] rcu: (detected by 11, t\x18212 jiffies, g=-1019, qƒ45)
> [ 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\x10 node=0 flags=0x0 nice=-20 active=1/256
> [ 211.469177] in-flight: 346:blk_mq_run_work_fn
> [ 211.470339] pool 21: cpus\x10 node=0 flags=0x0 nice=-20 hungEs
> 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\x10 node=0 flags=0x0 nice=-20 active=1/256
> [ 241.539172] in-flight: 346:blk_mq_run_work_fn
> [ 241.540333] pool 21: cpus\x10 node=0 flags=0x0 nice=-20 hungus
> 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\x10 node=0 flags=0x0 nice=-20 active=1/256
> [ 271.619185] in-flight: 346:blk_mq_run_work_fn
> [ 271.620347] pool 21: cpus\x10 node=0 flags=0x0 nice=-20 hung\x105s
> workers=2 idle: 63
> [ 288.926774] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 288.926825] rcu: 16-...0: (1 GPs behind)
> idleNa/1/0x4000000000000000 softirq2/33 fqsp17
> [ 288.926857] rcu: 17-...0: (1 GPs behind)
> idleE6/1/0x4000000000000002 softirqH/49 fqsp17
> [ 288.926888] rcu: 18-...0: (1 GPs behind)
> idle82/1/0x4000000000000000 softirq5/36 fqsp17
> [ 288.926918] rcu: 21-...0: (1 GPs behind)
> idle96/1/0x4000000000000000 softirqH/48 fqsp17
> [ 288.926947] rcu: 23-...0: (1 GPs behind)
> idle(2/1/0x4000000000000000 softirq)/29 fqsp17
> [ 288.926980] rcu: (detected by 1, t&017 jiffies, g=-1019, qƒ51)
> [ 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\x10 node=0 flags=0x0 nice=-20 active=1/256
> [ 331.779174] in-flight: 346:blk_mq_run_work_fn
> [ 331.780335] pool 21: cpus\x10 node=0 flags=0x0 nice=-20 hung\x166s
> 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\x10 node=0 flags=0x0 nice=-20 active=1/256
> [ 361.869179] in-flight: 346:blk_mq_run_work_fn
> [ 361.870338] pool 21: cpus\x10 node=0 flags=0x0 nice=-20 hung\x196s
> workers=2 idle: 63
> [ 366.976775] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 366.976826] rcu: 16-...0: (1 GPs behind)
> idleNa/1/0x4000000000000000 softirq2/33 fqs72
> [ 366.976858] rcu: 17-...0: (1 GPs behind)
> idleE6/1/0x4000000000000002 softirqH/49 fqs72
> [ 366.976889] rcu: 18-...0: (1 GPs behind)
> idle82/1/0x4000000000000000 softirq5/36 fqs72
> [ 366.976919] rcu: 21-...0: (1 GPs behind)
> idle96/1/0x4000000000000000 softirqH/48 fqs72
> [ 366.976950] rcu: 23-...0: (1 GPs behind)
> idle(2/1/0x4000000000000000 softirq)/29 fqs72
> [ 366.976983] rcu: (detected by 6, t3822 jiffies, g=-1019, qƒ75)
> [ 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\x10 node=0 flags=0x0 nice=-20 active=1/256
> [ 391.949180] in-flight: 346:blk_mq_run_work_fn
> [ 391.950340] pool 21: cpus\x10 node=0 flags=0x0 nice=-20 hung"6s
> 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\x10 node=0 flags=0x0 nice=-20 active=1/256
> [ 422.019183] in-flight: 346:blk_mq_run_work_fn
> [ 422.020344] pool 21: cpus\x10 node=0 flags=0x0 nice=-20 hung%6s
> 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@kernel.dk>
> 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@davemloft.net>
> Reviewed-by: Hannes Reinecke <hare@suse.com>
> Tested-by: Ming Lei <ming.lei@redhat.com>
> Reviewed-by: Omar Sandoval <osandov@fb.com>
> Signed-off-by: Jens Axboe <axboe@kernel.dk>
>
> :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
next prev parent reply other threads:[~2019-01-02 12:08 UTC|newest]
Thread overview: 5+ messages / expand[flat|nested] mbox.gz Atom feed top
2019-01-02 10:58 [sparc64] unable to boot git kernel / deadlock / cpu stall Anatoly Pugachev
2019-01-02 12:08 ` Ming Lei [this message]
2019-01-02 12:11 ` Ming Lei
2019-01-02 14:34 ` Anatoly Pugachev
2019-01-02 15:44 ` Jens Axboe
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20190102120842.GA30385@ming.t460p \
--to=ming.lei@redhat.com \
--cc=sparclinux@vger.kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.