early console in setup code
[    0.000000] Linux version 4.17.0-rc1-00048-g21560e1 (kbuild@lkp-ib03) (gcc version 7.3.0 (Debian 7.3.0-16)) #1 SMP Fri May 4 15:18:19 CST 2018
[    0.000000] Command line: ip=::::vm-lkp-wsx03-1G-18::dhcp root=/dev/ram0 user=lkp job=/lkp/scheduled/vm-lkp-wsx03-1G-18/ebizzy-200%-100x-10s-debian-x86_64-2016-08-31.cgz-21560e10077bf9f7baf69aa82527850271173862-20180504-55061-1kweryu-0.yaml ARCH=x86_64 kconfig=x86_64-randconfig-h0-05021444 branch=linux-devel/devel-spot-201805021321 commit=21560e10077bf9f7baf69aa82527850271173862 BOOT_IMAGE=/pkg/linux/x86_64-randconfig-h0-05021444/gcc-7/21560e10077bf9f7baf69aa82527850271173862/vmlinuz-4.17.0-rc1-00048-g21560e1 max_uptime=3600 RESULT_ROOT=/result/ebizzy/200%-100x-10s/vm-lkp-wsx03-1G/debian-x86_64-2016-08-31.cgz/x86_64-randconfig-h0-05021444/gcc-7/21560e10077bf9f7baf69aa82527850271173862/0 LKP_SERVER=inn debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 net.ifnames=0 printk.devkmsg=on panic=-1 softlockup_panic=1 nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0 drbd.minor_count=8 systemd.log_level=err ignore_loglevel console=tty0 earlyprintk=ttyS0,115200 
[    0.000000] KERNEL supported cpus:
[    0.000000] CPU: vendor_id 'GenuineIntel' unknown, using generic init.
[    0.000000] CPU: Your system may be unstable.
[    0.000000] x86/fpu: x87 FPU will use FXSAVE
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000003ffdbfff] usable
[    0.000000] BIOS-e820: [mem 0x000000003ffdc000-0x000000003fffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[    0.000000] debug: ignoring loglevel setting.
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] Hypervisor detected: KVM
[    0.000000] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.000000] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.000000] e820: last_pfn = 0x3ffdc max_arch_pfn = 0x400000000
[    0.000000] MTRR default type: write-back
[    0.000000] MTRR fixed ranges enabled:
[    0.000000]   00000-9FFFF write-back
[    0.000000]   A0000-BFFFF uncachable
[    0.000000]   C0000-FFFFF write-protect
[    0.000000] MTRR variable ranges enabled:
[    0.000000]   0 base 0080000000 mask FF80000000 uncachable
[    0.000000]   1 disabled
[    0.000000]   2 disabled
[    0.000000]   3 disabled
[    0.000000]   4 disabled
[    0.000000]   5 disabled
[    0.000000]   6 disabled
[    0.000000]   7 disabled
[    0.000000] x86/PAT: Configuration [0-7]: WB  WT  UC- UC  WB  WT  UC- UC  
[    0.000000] Base memory trampoline at [        (ptrval)] 99000 size 24576
[    0.000000] BRK [0x07c53000, 0x07c53fff] PGTABLE
[    0.000000] BRK [0x07c54000, 0x07c54fff] PGTABLE
[    0.000000] BRK [0x07c55000, 0x07c55fff] PGTABLE
[    0.000000] BRK [0x07c56000, 0x07c56fff] PGTABLE
[    0.000000] BRK [0x07c57000, 0x07c57fff] PGTABLE
[    0.000000] BRK [0x07c58000, 0x07c58fff] PGTABLE
[    0.000000] RAMDISK: [mem 0x351b9000-0x3ffcffff]
[    0.000000] ACPI: Early table checksum verification disabled
[    0.000000] ACPI: RSDP 0x00000000000F68C0 000014 (v00 BOCHS )
[    0.000000] ACPI: RSDT 0x000000003FFE15CE 000030 (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
[    0.000000] ACPI: FACP 0x000000003FFE142A 000074 (v01 BOCHS  BXPCFACP 00000001 BXPC 00000001)
[    0.000000] ACPI: DSDT 0x000000003FFE0040 0013EA (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
[    0.000000] ACPI: FACS 0x000000003FFE0000 000040
[    0.000000] ACPI: APIC 0x000000003FFE151E 000078 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
[    0.000000] ACPI: HPET 0x000000003FFE1596 000038 (v01 BOCHS  BXPCHPET 00000001 BXPC 00000001)
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] mapped APIC to ffffffffff5fc000 (        fee00000)
[    0.000000] No NUMA configuration found
[    0.000000] Faking a node at [mem 0x0000000000000000-0x000000003ffdbfff]
[    0.000000] NODE_DATA(0) allocated [mem 0x3ffd8000-0x3ffdbfff]
[    0.000000] kvm-clock: cpu 0, msr 0:3ffd6001, primary cpu clock
[    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000000] kvm-clock: using sched offset of 2605405595 cycles
[    0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.000000]   DMA32    [mem 0x0000000001000000-0x000000003ffdbfff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000001000-0x000000000009efff]
[    0.000000]   node   0: [mem 0x0000000000100000-0x000000003ffdbfff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x000000003ffdbfff]
[    0.000000] On node 0 totalpages: 262010
[    0.000000]   DMA zone: 64 pages used for memmap
[    0.000000]   DMA zone: 21 pages reserved
[    0.000000]   DMA zone: 3998 pages, LIFO batch:0
[    0.000000]   DMA32 zone: 4032 pages used for memmap
[    0.000000]   DMA32 zone: 258012 pages, LIFO batch:31
[    0.000000] Reserved but unavailable: 98 pages
[    0.000000] ACPI: PM-Timer IO Port: 0x608
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[    0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.000000] Int: type 0, pol 0, trig 0, bus 00, IRQ 00, APIC ID 0, APIC INT 02
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[    0.000000] Int: type 0, pol 1, trig 3, bus 00, IRQ 05, APIC ID 0, APIC INT 05
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.000000] Int: type 0, pol 1, trig 3, bus 00, IRQ 09, APIC ID 0, APIC INT 09
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[    0.000000] Int: type 0, pol 1, trig 3, bus 00, IRQ 0a, APIC ID 0, APIC INT 0a
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[    0.000000] Int: type 0, pol 1, trig 3, bus 00, IRQ 0b, APIC ID 0, APIC INT 0b
[    0.000000] ACPI: IRQ0 used by override.
[    0.000000] Int: type 0, pol 0, trig 0, bus 00, IRQ 01, APIC ID 0, APIC INT 01
[    0.000000] Int: type 0, pol 0, trig 0, bus 00, IRQ 03, APIC ID 0, APIC INT 03
[    0.000000] Int: type 0, pol 0, trig 0, bus 00, IRQ 04, APIC ID 0, APIC INT 04
[    0.000000] ACPI: IRQ5 used by override.
[    0.000000] Int: type 0, pol 0, trig 0, bus 00, IRQ 06, APIC ID 0, APIC INT 06
[    0.000000] Int: type 0, pol 0, trig 0, bus 00, IRQ 07, APIC ID 0, APIC INT 07
[    0.000000] Int: type 0, pol 0, trig 0, bus 00, IRQ 08, APIC ID 0, APIC INT 08
[    0.000000] ACPI: IRQ9 used by override.
[    0.000000] ACPI: IRQ10 used by override.
[    0.000000] ACPI: IRQ11 used by override.
[    0.000000] Int: type 0, pol 0, trig 0, bus 00, IRQ 0c, APIC ID 0, APIC INT 0c
[    0.000000] Int: type 0, pol 0, trig 0, bus 00, IRQ 0d, APIC ID 0, APIC INT 0d
[    0.000000] Int: type 0, pol 0, trig 0, bus 00, IRQ 0e, APIC ID 0, APIC INT 0e
[    0.000000] Int: type 0, pol 0, trig 0, bus 00, IRQ 0f, APIC ID 0, APIC INT 0f
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000
[    0.000000] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
[    0.000000] mapped IOAPIC to ffffffffff5fb000 (fec00000)
[    0.000000] e820: [mem 0x40000000-0xfeffbfff] available for PCI devices
[    0.000000] Booting paravirtualized kernel on KVM
[    0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.000000] random: fast init done
[    0.000000] setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:1 nr_node_ids:1
[    0.000000] percpu: Embedded 37 pages/cpu @        (ptrval) s119048 r0 d32504 u2097152
[    0.000000] pcpu-alloc: s119048 r0 d32504 u2097152 alloc=1*2097152
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] KVM setup async PF for cpu 0
[    0.000000] kvm-stealtime: cpu 0, msr 34c10880
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 257893
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: ip=::::vm-lkp-wsx03-1G-18::dhcp root=/dev/ram0 user=lkp job=/lkp/scheduled/vm-lkp-wsx03-1G-18/ebizzy-200%-100x-10s-debian-x86_64-2016-08-31.cgz-21560e10077bf9f7baf69aa82527850271173862-20180504-55061-1kweryu-0.yaml ARCH=x86_64 kconfig=x86_64-randconfig-h0-05021444 branch=linux-devel/devel-spot-201805021321 commit=21560e10077bf9f7baf69aa82527850271173862 BOOT_IMAGE=/pkg/linux/x86_64-randconfig-h0-05021444/gcc-7/21560e10077bf9f7baf69aa82527850271173862/vmlinuz-4.17.0-rc1-00048-g21560e1 max_uptime=3600 RESULT_ROOT=/result/ebizzy/200%-100x-10s/vm-lkp-wsx03-1G/debian-x86_64-2016-08-31.cgz/x86_64-randconfig-h0-05021444/gcc-7/21560e10077bf9f7baf69aa82527850271173862/0 LKP_SERVER=inn debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 net.ifnames=0 printk.devkmsg=on panic=-1 softlockup_panic=1 nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0 drbd.minor_count=8 systemd.log_level=err ignore_loglevel console=tty0 earlyprintk=ttyS0,
[    0.000000] sysrq: sysrq always enabled.
[    0.000000] Calgary: detecting Calgary via BIOS EBDA area
[    0.000000] Calgary: Unable to locate Rio Grande table in EBDA - bailing!
[    0.000000] Memory: 150720K/1048040K available (32780K kernel code, 15086K rwdata, 15588K rodata, 1448K init, 36832K bss, 307948K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.010000] Running RCU self tests
[    0.010000] Hierarchical RCU implementation.
[    0.010000] 	RCU lockdep checking is enabled.
[    0.010000] 	RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=1.
[    0.010000] 	RCU CPU stall warnings timeout set to 100 (rcu_cpu_stall_timeout).
[    0.010000] 	Tasks RCU enabled.
[    0.010000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
[    0.010000] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 16
[    0.010000] 	Offload RCU callbacks from CPUs: (none).
[    0.010000] console [ttyS0] enabled
[    0.010000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.010000] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.010000] ... MAX_LOCK_DEPTH:          48
[    0.010000] ... MAX_LOCKDEP_KEYS:        8191
[    0.010000] ... CLASSHASH_SIZE:          4096
[    0.010000] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.010000] ... MAX_LOCKDEP_CHAINS:      65536
[    0.010000] ... CHAINHASH_SIZE:          32768
[    0.010000]  memory used by lock dependency info: 7391 kB
[    0.010000]  per task-struct memory footprint: 1920 bytes
[    0.010000] ------------------------
[    0.010000] | Locking API testsuite:
[    0.010000] ----------------------------------------------------------------------------
[    0.010000]                                  | spin |wlock |rlock |mutex | wsem | rsem |
[    0.010000]   --------------------------------------------------------------------------
[    0.010000]                      A-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.010000]                  A-B-B-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.010000]              A-B-B-C-C-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.010000]              A-B-C-A-B-C deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.010000]          A-B-B-C-C-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.010000]          A-B-C-D-B-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.010000]          A-B-C-D-B-C-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.010000]                     double unlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.010000]                   initialize held:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.010000]   --------------------------------------------------------------------------
[    0.010000]               recursive read-lock:             |  ok  |             |  ok  |
[    0.010000]            recursive read-lock #2:             |  ok  |             |  ok  |
[    0.010000]             mixed read-write-lock:             |  ok  |             |  ok  |
[    0.010000]             mixed write-read-lock:             |  ok  |             |  ok  |
[    0.010000]   mixed read-lock/lock-write ABBA:             |FAILED|             |  ok  |
[    0.010000]    mixed read-lock/lock-read ABBA:             |  ok  |             |  ok  |
[    0.010000]  mixed write-lock/lock-write ABBA:             |  ok  |             |  ok  |
[    0.010000]   --------------------------------------------------------------------------
[    0.010000]      hard-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    0.010000]      soft-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    0.010000]      hard-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    0.010000]      soft-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    0.010000]        sirq-safe-A => hirqs-on/12:  ok  |  ok  |  ok  |
[    0.010000]        sirq-safe-A => hirqs-on/21:  ok  |  ok  |  ok  |
[    0.010000]          hard-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    0.010000]          soft-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    0.010000]          hard-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    0.010000]          soft-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    0.010000]     hard-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    0.010000]     soft-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    0.010000]       hard-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    0.010000]       soft-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    0.010000]       hard-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    0.010000]       soft-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    0.010000]       hard-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    0.010000]       soft-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    0.010000]       hard-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    0.010000]       soft-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    0.010000]       hard-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    0.010000]       soft-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    0.010000]       hard-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    0.010000]       soft-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    0.010000]       hard-irq read-recursion/123:  ok  |
[    0.010000]       soft-irq read-recursion/123:  ok  |
[    0.010000]       hard-irq read-recursion/132:  ok  |
[    0.010000]       soft-irq read-recursion/132:  ok  |
[    0.010000]       hard-irq read-recursion/213:  ok  |
[    0.010000]       soft-irq read-recursion/213:  ok  |
[    0.010000]       hard-irq read-recursion/231:  ok  |
[    0.010000]       soft-irq read-recursion/231:  ok  |
[    0.010000]       hard-irq read-recursion/312:  ok  |
[    0.010000]       soft-irq read-recursion/312:  ok  |
[    0.010000]       hard-irq read-recursion/321:  ok  |
[    0.010000]       soft-irq read-recursion/321:  ok  |
[    0.010000]   --------------------------------------------------------------------------
[    0.010000]   | Wound/wait tests |
[    0.010000]   ---------------------
[    0.010000]                   ww api failures:  ok  |  ok  |  ok  |
[    0.010000]                ww contexts mixing:  ok  |  ok  |
[    0.010000]              finishing ww context:  ok  |  ok  |  ok  |  ok  |
[    0.010000]                locking mismatches:  ok  |  ok  |  ok  |
[    0.010000]                  EDEADLK handling:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.010000]            spinlock nest unlocked:  ok  |
[    0.010000]   -----------------------------------------------------
[    0.010000]                                  |block | try  |context|
[    0.010000]   -----------------------------------------------------
[    0.010000]                           context:  ok  |  ok  |  ok  |
[    0.010000]                               try:  ok  |  ok  |  ok  |
[    0.010000]                             block:  ok  |  ok  |  ok  |
[    0.010000]                          spinlock:  ok  |  ok  |  ok  |
[    0.010000] -------------------------------------------------------
[    0.010000] Good, all 261 testcases passed! |
[    0.010000] ---------------------------------
[    0.010000] ACPI: Core revision 20180313
[    0.010000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
[    0.010000] hpet clockevent registered
[    0.010486] APIC: Switch to symmetric I/O mode setup
[    0.020683] enabled ExtINT on CPU#0
[    0.043294] ENABLING IO-APIC IRQs
[    0.050129] init IO_APIC IRQs
[    0.054895]  apic 0 pin 0 not connected
[    0.061362] IOAPIC[0]: Set routing entry (0-1 -> 0xef -> IRQ 1 Mode:0 Active:0 Dest:1)
[    0.070980] IOAPIC[0]: Set routing entry (0-2 -> 0x30 -> IRQ 0 Mode:0 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-3 -> 0xef -> IRQ 3 Mode:0 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-4 -> 0xef -> IRQ 4 Mode:0 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-5 -> 0xef -> IRQ 5 Mode:1 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-6 -> 0xef -> IRQ 6 Mode:0 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-7 -> 0xef -> IRQ 7 Mode:0 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-8 -> 0xef -> IRQ 8 Mode:0 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-9 -> 0xef -> IRQ 9 Mode:1 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-10 -> 0xef -> IRQ 10 Mode:1 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-11 -> 0xef -> IRQ 11 Mode:1 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-12 -> 0xef -> IRQ 12 Mode:0 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-13 -> 0xef -> IRQ 13 Mode:0 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-14 -> 0xef -> IRQ 14 Mode:0 Active:0 Dest:1)
[    0.080000] IOAPIC[0]: Set routing entry (0-15 -> 0xef -> IRQ 15 Mode:0 Active:0 Dest:1)
[    0.080000]  apic 0 pin 16 not connected
[    0.080000]  apic 0 pin 17 not connected
[    0.080000]  apic 0 pin 18 not connected
[    0.080000]  apic 0 pin 19 not connected
[    0.080000]  apic 0 pin 20 not connected
[    0.080000]  apic 0 pin 21 not connected
[    0.080000]  apic 0 pin 22 not connected
[    0.080000]  apic 0 pin 23 not connected
[    0.080000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.080000] tsc: Detected 2260.998 MHz processor
[    0.080121] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x20974986637, max_idle_ns: 440795286310 ns
[    0.090388] Calibrating delay loop (skipped) preset value.. 4521.99 BogoMIPS (lpj=22609980)
[    0.100072] pid_max: default: 32768 minimum: 301
[    0.121917] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.135279] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.140962] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes)
[    0.160133] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes)
[    0.194999] mce: CPU supports 10 MCE banks
[    0.200186] mce: unknown CPU type - not enabling MCE support
[    0.210096] numa_add_cpu cpu 0 node 0: mask now 0
[    0.216940] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[    0.220092] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
[    0.230168] Spectre V2 : Mitigation: Full generic retpoline
[    0.240091] Spectre V2 : Spectre v2 mitigation: Filling RSB on context switch
[    0.385023] debug: unmapping init [mem 0xffffffff85850000-0xffffffff8585afff]
[    0.406964] Using local APIC timer interrupts.
[    0.406964] calibrating APIC timer ...
[    0.420000] ... lapic delta = 6248278
[    0.420000] ... PM-Timer delta = 357864
[    0.420000] ... PM-Timer result ok
[    0.420000] ..... delta 6248278
[    0.420000] ..... mult: 268361496
[    0.420000] ..... calibration result: 9997244
[    0.420000] ..... CPU clock speed is 2260.8878 MHz.
[    0.420000] ..... host bus clock speed is 999.7244 MHz.
[    0.420617] smpboot: CPU0: GenuineIntel Common KVM processor (family: 0xf, model: 0x6, stepping: 0x1)
[    0.444795] Performance Events: no PMU driver, software events only.
[    0.452949] Hierarchical SRCU implementation.
[    0.465612] NMI watchdog: Perf event create on CPU 0 failed with -2
[    0.470154] NMI watchdog: Perf NMI watchdog permanently disabled
[    0.491711] smp: Bringing up secondary CPUs ...
[    0.498391] smp: Brought up 1 node, 1 CPU
[    0.500095] smpboot: Max logical packages: 1
[    0.510165] ----------------
[    0.514466] | NMI testsuite:
[    0.520131] --------------------
[    0.524996]   remote IPI:  ok  |
[    0.530093]    local IPI:  ok  |
[    0.535210] --------------------
[    0.540094] Good, all   2 testcases passed! |
[    0.546480] ---------------------------------
[    0.550221] smpboot: Total of 1 processors activated (4521.99 BogoMIPS)
[    0.580129] node 0 initialised, 147343 pages in 10ms
[    0.591483] pgdatinit0 (15) used greatest stack depth: 14760 bytes left
[    0.614501] devtmpfs: initialized
[    0.644077] gcov: version magic: 0x4137332a
[    0.731389] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.740743] futex hash table entries: 256 (order: 3, 32768 bytes)
[    0.752624] prandom: seed boundary self test passed
[    0.773825] prandom: 100 self tests passed
[    0.791072] regulator-dummy: no parameters
[    0.819335] NET: Registered protocol family 16
[    0.887119] cpuidle: using governor ladder
[    0.890126] cpuidle: using governor menu
[    0.922977] ACPI: bus type PCI registered
[    0.929717] PCI: Using configuration type 1 for base access
[    2.070072] 
[    2.072471] ============================================
[    2.079791] WARNING: possible recursive locking detected
[    2.080000] 4.17.0-rc1-00048-g21560e1 #1 Not tainted
[    2.080000] --------------------------------------------
[    2.080000] swapper/0/1 is trying to acquire lock:
[    2.080000] 000000007895dd2f (rcu_node_0){..-.}, at: rcu_process_callbacks+0x4b3/0xa28
[    2.080000] 
[    2.080000] but task is already holding lock:
[    2.080000] 000000007895dd2f (rcu_node_0){..-.}, at: rcu_process_callbacks+0x3cf/0xa28
[    2.080000] 
[    2.080000] other info that might help us debug this:
[    2.080000]  Possible unsafe locking scenario:
[    2.080000] 
[    2.080000]        CPU0
[    2.080000]        ----
[    2.080000]   lock(rcu_node_0);
[    2.080000]   lock(rcu_node_0);
[    2.080000] 
[    2.080000]  *** DEADLOCK ***
[    2.080000] 
[    2.080000]  May be due to missing lock nesting notation
[    2.080000] 
[    2.080000] 1 lock held by swapper/0/1:
[    2.080000]  #0: 000000007895dd2f (rcu_node_0){..-.}, at: rcu_process_callbacks+0x3cf/0xa28
[    2.080000] 
[    2.080000] stack backtrace:
[    2.080000] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.17.0-rc1-00048-g21560e1 #1
[    2.080000] Call Trace:
[    2.080000]  <IRQ>
[    2.080000]  dump_stack+0x117/0x182
[    2.080000]  validate_chain+0x8d4/0xec0
[    2.080000]  ? lookup_chain_cache+0x4a/0x9c
[    2.080000]  ? validate_chain+0x9e/0xec0
[    2.080000]  ? lookup_chain_cache+0x4a/0x9c
[    2.080000]  ? lookup_chain_cache+0x4a/0x9c
[    2.080000]  ? lookup_chain_cache+0x4a/0x9c
[    2.080000]  ? __lock_acquire+0x8ed/0x9da
[    2.080000]  __lock_acquire+0x8ed/0x9da
[    2.080000]  lock_acquire+0x9e/0xcd
[    2.080000]  ? rcu_process_callbacks+0x4b3/0xa28
[    2.080000]  _raw_spin_lock_irqsave+0x60/0x88
[    2.080000]  ? rcu_process_callbacks+0x4b3/0xa28
[    2.080000]  rcu_process_callbacks+0x4b3/0xa28
[    2.080000]  ? kvm_clock_read+0x2f/0x45
[    2.080000]  ? kvm_sched_clock_read+0xc/0x1b
[    2.080000]  ? paravirt_sched_clock+0xc/0x16
[    2.080000]  ? sched_clock+0xc/0x14
[    2.080000]  ? sched_clock_local+0x10/0xb8
[    2.080000]  __do_softirq+0x134/0x303
[    2.080000]  irq_exit+0x92/0x143
[    2.080000]  smp_apic_timer_interrupt+0xb9/0xcb
[    2.080000]  apic_timer_interrupt+0xf/0x20
[    2.080000]  </IRQ>
[    2.080000] RIP: 0010:arch_local_irq_restore+0x9/0x16
[    2.080000] RSP: 0000:ffff88000fe63ce0 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff13
[    2.080000] RAX: ffff88000fe58040 RBX: 0000000000000206 RCX: ffff88000fe63b1c
[    2.080000] RDX: 0000000000000001 RSI: 0000000000000001 RDI: 0000000000000206
[    2.080000] RBP: ffff8800346be9b8 R08: ffff8800346beba8 R09: 0000000100080005
[    2.080000] R10: ffff88000fe63ce8 R11: 0000000000000000 R12: 00000000014080c0
[    2.080000] R13: ffffffff812c4f20 R14: ffff88000fcac5c0 R15: 0000000000000000
[    2.080000]  ? __kernfs_new_node+0x56/0x177
[    2.080000]  __slab_alloc+0xa1/0xb2
[    2.080000]  ? __kernfs_new_node+0x56/0x177
[    2.080000]  kmem_cache_alloc+0xe6/0x12c
[    2.080000]  __kernfs_new_node+0x56/0x177
[    2.080000]  kernfs_new_node+0x1d/0x4e
[    2.080000]  __kernfs_create_file+0x38/0x11c
[    2.080000]  sysfs_add_file_mode_ns+0x10a/0x238
[    2.080000]  internal_create_group+0x245/0x404
[    2.080000]  sysfs_create_group+0x11/0x19
[    2.080000]  param_sysfs_init+0x479/0x520
[    2.080000]  ? trace_hardirqs_on_caller+0x219/0x2bc
[    2.080000]  ? trace_hardirqs_on+0x17/0x1f
[    2.080000]  ? locate_module_kobject+0x125/0x125
[    2.080000]  do_one_initcall+0xb4/0x214
[    2.080000]  kernel_init_freeable+0x36a/0x480
[    2.080000]  ? rest_init+0x130/0x130
[    2.080000]  kernel_init+0xc/0x1a0
[    2.080000]  ret_from_fork+0x3a/0x50
BUG: kernel hang in boot stage

Elapsed time: 830

#!/bin/bash

# To reproduce,
# 1) save job-script and this script (both are attached in 0day report email)
# 2) run this script with your compiled kernel and optional env $INSTALL_MOD_PATH

kernel=$1

initrds=(
	/osimage/debian/debian-x86_64-2016-08-31.cgz
	/lkp/lkp/lkp-x86_64.cgz
	/osimage/deps/debian-x86_64-2016-08-31.cgz/run-ipconfig_2016-11-15.cgz
	/osimage/deps/debian-x86_64-2016-08-31.cgz/lkp_2018-04-19.cgz
	/osimage/deps/debian-x86_64-2016-08-31.cgz/rsync-rootfs_2016-11-15.cgz
	/osimage/pkg/debian-x86_64-2016-08-31.cgz/ebizzy-x86_64_2016-11-16.cgz
	/osimage/deps/debian-x86_64-2016-08-31.cgz/mpstat_2017-12-25.cgz
	/osimage/deps/debian-x86_64-2016-08-31.cgz/turbostat_2016-11-15.cgz
	/osimage/pkg/debian-x86_64-2016-08-31.cgz/turbostat-x86_64-d5256b2_2017-06-20.cgz
	/osimage/deps/debian-x86_64-2016-08-31.cgz/perf_2018-04-04.cgz
	/osimage/pkg/debian-x86_64-2016-08-31.cgz/perf-x86_64-f8cf2f16a7c9_2018-04-09.cgz
)

HTTP_PREFIX=https://github.com/0day-ci/lkp-qemu/raw/master
wget --timestamping "${initrds[@]/#/$HTTP_PREFIX}"

{
	cat "${initrds[@]//*\//}"
	[[ $INSTALL_MOD_PATH ]] && (
		cd "$INSTALL_MOD_PATH"
		find lib | cpio -o -H newc --quiet | gzip
	)
	echo  job-script | cpio -o -H newc --quiet | gzip
} > initrd.img

qemu-img create -f qcow2 disk-vm-lkp-wsx03-1G-18-0 256G
qemu-img create -f qcow2 disk-vm-lkp-wsx03-1G-18-1 256G

kvm=(
	qemu-system-x86_64
	-enable-kvm
	-cpu kvm64,+ssse3
	-kernel $kernel
	-initrd initrd.img
	-m 1024
	-smp 1
	-device e1000,netdev=net0
	-netdev user,id=net0,hostfwd=tcp::23617-:22
	-boot order=nc
	-no-reboot
	-watchdog i6300esb
	-watchdog-action debug
	-rtc base=localtime
	-drive file=disk-vm-lkp-wsx03-1G-18-0,media=disk,if=virtio
	-drive file=disk-vm-lkp-wsx03-1G-18-1,media=disk,if=virtio
	-serial stdio
	-display none
	-monitor null
)

append=(
	ip=::::vm-lkp-wsx03-1G-18::dhcp
	root=/dev/ram0
	user=lkp
	job=/job-script
	ARCH=x86_64
	kconfig=x86_64-randconfig-h0-05021444
	branch=linux-devel/devel-spot-201805021321
	commit=21560e10077bf9f7baf69aa82527850271173862
	BOOT_IMAGE=/pkg/linux/x86_64-randconfig-h0-05021444/gcc-7/21560e10077bf9f7baf69aa82527850271173862/vmlinuz-4.17.0-rc1-00048-g21560e1
	max_uptime=3600
	RESULT_ROOT=/result/ebizzy/200%-100x-10s/vm-lkp-wsx03-1G/debian-x86_64-2016-08-31.cgz/x86_64-randconfig-h0-05021444/gcc-7/21560e10077bf9f7baf69aa82527850271173862/0
	result_service=tmpfs
	debug
	apic=debug
	sysrq_always_enabled
	rcupdate.rcu_cpu_stall_timeout=100
	net.ifnames=0
	printk.devkmsg=on
	panic=-1
	softlockup_panic=1
	nmi_watchdog=panic
	oops=panic
	load_ramdisk=2
	prompt_ramdisk=0
	drbd.minor_count=8
	systemd.log_level=err
	ignore_loglevel
	console=tty0
	earlyprintk=ttyS0,115200
	console=ttyS0,115200
	vga=normal
	rw
	rcuperf.shutdown=0
)

"${kvm[@]}" -append "${append[*]}"
