early console in setup code [ 0.000000] Linux version 4.14.0-10859-gcf9b077 (kbuild@ivb43) (gcc version 6.4.0 20171026 (Debian 6.4.0-9)) #13 SMP PREEMPT Fri Nov 17 09:04:41 CST 2017 [ 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-0x0000000013fdbfff] usable [ 0.000000] BIOS-e820: [mem 0x0000000013fdc000-0x0000000013ffffff] 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] Notice: NX (Execute Disable) protection missing in CPU! [ 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 = 0x13fdc max_arch_pfn = 0x100000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WT UC- UC WB WT UC- UC [ 0.000000] Scan for SMP in [mem 0x00000000-0x000003ff] [ 0.000000] Scan for SMP in [mem 0x0009fc00-0x0009ffff] [ 0.000000] Scan for SMP in [mem 0x000f0000-0x000fffff] [ 0.000000] found SMP MP-table at [mem 0x000f6a90-0x000f6a9f] mapped at [ffa00a90] [ 0.000000] mpc: f6aa0-f6b80 [ 0.000000] initial memory mapped: [mem 0x00000000-0x033fffff] [ 0.000000] Base memory trampoline at [7809b000] 9b000 size 16384 [ 0.000000] BRK [0x02e82000, 0x02e82fff] PGTABLE [ 0.000000] RAMDISK: [mem 0x13bf3000-0x13fcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F68C0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x0000000013FE15CE 000030 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x0000000013FE142A 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x0000000013FE0040 0013EA (v01 BOCHS BXPCDSDT 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x0000000013FE0000 000040 [ 0.000000] ACPI: APIC 0x0000000013FE151E 000078 (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x0000000013FE1596 000038 (v01 BOCHS BXPCHPET 00000001 BXPC 00000001) [ 0.000000] ACPI: Local APIC address 0xfee00000 [ 0.000000] mapped APIC to ffffc000 ( fee00000) [ 0.000000] 0MB HIGHMEM available. [ 0.000000] 319MB LOWMEM available. [ 0.000000] mapped low ram: 0 - 13fdc000 [ 0.000000] low ram: 0 - 13fdc000 [ 0.000000] kvm-clock: cpu 0, msr 0:13fda001, primary cpu clock [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 2396513518 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] Zone ranges: [ 0.000000] Normal [mem 0x0000000000001000-0x0000000013fdbfff] [ 0.000000] HighMem 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-0x0000000013fdbfff] [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000013fdbfff] [ 0.000000] On node 0 totalpages: 81786 [ 0.000000] Normal zone: 640 pages used for memmap [ 0.000000] Normal zone: 0 pages reserved [ 0.000000] Normal zone: 81786 pages, LIFO batch:15 [ 0.000000] Reserved but unavailable: 98 pages [ 0.000000] Using APIC driver default [ 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 ffffb000 (fec00000) [ 0.000000] e820: [mem 0x14000000-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: 6370452778343963 ns [ 0.000000] random: fast init done [ 0.000000] setup_percpu: NR_CPUS:32 nr_cpumask_bits:1 nr_cpu_ids:1 nr_node_ids:1 [ 0.000000] percpu: Embedded 340 pages/cpu @8b81f000 s1368704 r0 d23936 u1392640 [ 0.000000] pcpu-alloc: s1368704 r0 d23936 u1392640 alloc=340*4096 [ 0.000000] pcpu-alloc: [0] 0 [ 0.000000] KVM setup async PF for cpu 0 [ 0.000000] kvm-stealtime: cpu 0, msr 13821ac0 [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 81146 [ 0.000000] Kernel command line: ip=::::vm-lkp-wsx03-openwrt-i386-21::dhcp root=/dev/ram0 user=lkp job=/lkp/scheduled/vm-lkp-wsx03-openwrt-i386-21/trinity-300s-openwrt-i386-2016-03-16.cgz-cf9b0772f2e410645fece13b749bd56505b998b8-20171117-9157-kjsw0r-0.yaml ARCH=i386 kconfig=i386-randconfig-i0-201746 branch=linus/master commit=cf9b0772f2e410645fece13b749bd56505b998b8 BOOT_IMAGE=/pkg/linux/i386-randconfig-i0-201746/gcc-6/cf9b0772f2e410645fece13b749bd56505b998b8/vmlinuz-4.14.0-10859-gcf9b077 max_uptime=1500 RESULT_ROOT=/result/trinity/300s/vm-lkp-wsx03-openwrt-i386/openwrt-i386-2016-03-16.cgz/i386-randconfig-i0-201746/gcc-6/cf9b0772f2e410645fece13b749bd56505b998b8/1 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 console=ttyS0,115200 vga [ 0.000000] sysrq: sysrq always enabled. [ 0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes) [ 0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes) [ 0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes) [ 0.000000] Initializing CPU#0 [ 0.000000] Initializing HighMem for node 0 (00000000:00000000) [ 0.000000] Memory: 287516K/327144K available (7969K kernel code, 3402K rwdata, 5080K rodata, 2084K init, 12564K bss, 39628K reserved, 0K cma-reserved, 0K highmem) [ 0.000000] virtual kernel memory layout: [ 0.000000] fixmap : 0xffd16000 - 0xfffff000 (2980 kB) [ 0.000000] pkmap : 0xff800000 - 0xffc00000 (4096 kB) [ 0.000000] vmalloc : 0x8c7dc000 - 0xff7fe000 (1840 MB) [ 0.000000] lowmem : 0x78000000 - 0x8bfdc000 ( 319 MB) [ 0.000000] .init : 0x7a024000 - 0x7a22d000 (2084 kB) [ 0.000000] .data : 0x797c873a - 0x7a012900 (8488 kB) [ 0.000000] .text : 0x79000000 - 0x797c873a (7969 kB) [ 0.000000] Checking if this processor honours the WP bit even in supervisor mode...Ok. [ 0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1 [ 0.000000] ftrace: allocating 30893 entries in 61 pages [ 0.000000] [ 0.000000] ********************************************************** [ 0.000000] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.000000] ** ** [ 0.000000] ** trace_printk() being used. Allocating extra memory. ** [ 0.000000] ** ** [ 0.000000] ** This means that this is a DEBUG kernel and it is ** [ 0.000000] ** unsafe for production use. ** [ 0.000000] ** ** [ 0.000000] ** If you see this message and you are not debugging ** [ 0.000000] ** the kernel, report this immediately to your vendor! ** [ 0.000000] ** ** [ 0.000000] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.000000] ********************************************************** [ 0.003333] Running RCU self tests [ 0.003333] Preemptible hierarchical RCU implementation. [ 0.003333] RCU event tracing is enabled. [ 0.003333] RCU lockdep checking is enabled. [ 0.003333] RCU restricting CPUs from NR_CPUS=32 to nr_cpu_ids=1. [ 0.003333] RCU CPU stall warnings timeout set to 100 (rcu_cpu_stall_timeout). [ 0.003333] Tasks RCU enabled. [ 0.003333] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1 [ 0.003333] NR_IRQS: 2304, nr_irqs: 256, preallocated irqs: 16 [ 0.003333] CPU 0 irqstacks, hard=78240000 soft=78242000 [ 0.003333] Offload RCU callbacks from CPUs: . [ 0.003333] console [ttyS0] enabled [ 0.003333] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar [ 0.003333] ... MAX_LOCKDEP_SUBCLASSES: 8 [ 0.003333] ... MAX_LOCK_DEPTH: 48 [ 0.003333] ... MAX_LOCKDEP_KEYS: 8191 [ 0.003333] ... CLASSHASH_SIZE: 4096 [ 0.003333] ... MAX_LOCKDEP_ENTRIES: 32768 [ 0.003333] ... MAX_LOCKDEP_CHAINS: 65536 [ 0.003333] ... CHAINHASH_SIZE: 32768 [ 0.003333] memory used by lock dependency info: 4655 kB [ 0.003333] per task-struct memory footprint: 2304 bytes [ 0.003333] ------------------------ [ 0.003333] | Locking API testsuite: [ 0.003333] ---------------------------------------------------------------------------- [ 0.003333] | spin |wlock |rlock |mutex | wsem | rsem | [ 0.003333] -------------------------------------------------------------------------- [ 0.003333] A-A deadlock: ok | ok | ok | ok | ok | ok | ok | [ 0.003333] A-B-B-A deadlock: ok | ok | ok | ok | ok | ok | ok | [ 0.003333] A-B-B-C-C-A deadlock: ok | ok | ok | ok | ok | ok | ok | [ 0.003333] A-B-C-A-B-C deadlock: ok | ok | ok | ok | ok | ok | ok | [ 0.003333] A-B-B-C-C-D-D-A deadlock: ok | ok | ok | ok | ok | ok | ok | [ 0.003333] A-B-C-D-B-D-D-A deadlock: ok | ok | ok | ok | ok | ok | ok | [ 0.003333] A-B-C-D-B-C-D-A deadlock: ok | ok | ok | ok | ok | ok | ok | [ 0.003333] double unlock: ok | ok | ok | ok | ok | ok | ok | [ 0.003333] initialize held: ok | ok | ok | ok | ok | ok | ok | [ 0.003333] -------------------------------------------------------------------------- [ 0.003333] recursive read-lock: | ok | | ok | [ 0.003333] recursive read-lock #2: | ok | | ok | [ 0.003333] mixed read-write-lock: | ok | | ok | [ 0.003333] mixed write-read-lock: | ok | | ok | [ 0.003333] mixed read-lock/lock-write ABBA: |FAILED| | ok | [ 0.003333] mixed read-lock/lock-read ABBA: | ok | | ok | [ 0.003333] mixed write-lock/lock-write ABBA: | ok | | ok | [ 0.003333] -------------------------------------------------------------------------- [ 0.003333] hard-irqs-on + irq-safe-A/12: ok | ok | ok | [ 0.003333] soft-irqs-on + irq-safe-A/12: ok | ok | ok | [ 0.003333] hard-irqs-on + irq-safe-A/21: ok | ok | ok | [ 0.003333] soft-irqs-on + irq-safe-A/21: ok | ok | ok | [ 0.003333] sirq-safe-A => hirqs-on/12: ok | ok | ok | [ 0.003333] sirq-safe-A => hirqs-on/21: ok | ok | ok | [ 0.003333] hard-safe-A + irqs-on/12: ok | ok | ok | [ 0.003333] soft-safe-A + irqs-on/12: ok | ok | ok | [ 0.003333] hard-safe-A + irqs-on/21: ok | ok | ok | [ 0.003333] soft-safe-A + irqs-on/21: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #1/123: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #1/123: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #1/132: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #1/132: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #1/213: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #1/213: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #1/231: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #1/231: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #1/312: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #1/312: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #1/321: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #1/321: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #2/123: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #2/123: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #2/132: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #2/132: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #2/213: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #2/213: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #2/231: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #2/231: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #2/312: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #2/312: ok | ok | ok | [ 0.003333] hard-safe-A + unsafe-B #2/321: ok | ok | ok | [ 0.003333] soft-safe-A + unsafe-B #2/321: ok | ok | ok | [ 0.003333] hard-irq lock-inversion/123: ok | ok | ok | [ 0.003333] soft-irq lock-inversion/123: ok | ok | ok | [ 0.003333] hard-irq lock-inversion/132: ok | ok | ok | [ 0.003333] soft-irq lock-inversion/132: ok | ok | ok | [ 0.003333] hard-irq lock-inversion/213: ok | ok | ok | [ 0.003333] soft-irq lock-inversion/213: ok | ok | ok | [ 0.003333] hard-irq lock-inversion/231: ok | ok | ok | [ 0.003333] soft-irq lock-inversion/231: ok | ok | ok | [ 0.003333] hard-irq lock-inversion/312: ok | ok | ok | [ 0.003333] soft-irq lock-inversion/312: ok | ok | ok | [ 0.003333] hard-irq lock-inversion/321: ok | ok | ok | [ 0.003333] soft-irq lock-inversion/321: ok | ok | ok | [ 0.003333] hard-irq read-recursion/123: ok | [ 0.003333] soft-irq read-recursion/123: ok | [ 0.003333] hard-irq read-recursion/132: ok | [ 0.003333] soft-irq read-recursion/132: ok | [ 0.003333] hard-irq read-recursion/213: ok | [ 0.003333] soft-irq read-recursion/213: ok | [ 0.003333] hard-irq read-recursion/231: ok | [ 0.003333] soft-irq read-recursion/231: ok | [ 0.003333] hard-irq read-recursion/312: ok | [ 0.003333] soft-irq read-recursion/312: ok | [ 0.003333] hard-irq read-recursion/321: ok | [ 0.003333] soft-irq read-recursion/321: ok | [ 0.003333] -------------------------------------------------------------------------- [ 0.003333] | Wound/wait tests | [ 0.003333] --------------------- [ 0.003333] ww api failures: ok | ok | ok | [ 0.003333] ww contexts mixing: ok | ok | [ 0.003333] finishing ww context: ok | ok | ok | ok | [ 0.003333] locking mismatches: ok | ok | ok | [ 0.003333] EDEADLK handling: ok | ok | ok | ok | ok | ok | ok | ok | ok | ok | [ 0.003333] spinlock nest unlocked: ok | [ 0.003333] ----------------------------------------------------- [ 0.003333] |block | try |context| [ 0.003333] ----------------------------------------------------- [ 0.003333] context: ok | ok | ok | [ 0.003333] try: ok | ok | ok | [ 0.003333] block: ok | ok | ok | [ 0.003333] spinlock: ok | ok | ok | [ 0.003333] ------------------------------------------------------- [ 0.003333] Good, all 261 testcases passed! | [ 0.003333] --------------------------------- [ 0.003333] ACPI: Core revision 20170831 [ 0.003333] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.003333] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.003333] hpet clockevent registered [ 0.003947] APIC: Switch to symmetric I/O mode setup [ 0.006797] Enabling APIC mode: Flat. Using 1 I/O APICs [ 0.010842] enabled ExtINT on CPU#0 [ 0.027419] ENABLING IO-APIC IRQs [ 0.034052] init IO_APIC IRQs [ 0.036795] apic 0 pin 0 not connected [ 0.041427] IOAPIC[0]: Set routing entry (0-1 -> 0xef -> IRQ 1 Mode:0 Active:0 Dest:1) [ 0.044164] IOAPIC[0]: Set routing entry (0-2 -> 0x30 -> IRQ 0 Mode:0 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-3 -> 0xef -> IRQ 3 Mode:0 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-4 -> 0xef -> IRQ 4 Mode:0 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-5 -> 0xef -> IRQ 5 Mode:1 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-6 -> 0xef -> IRQ 6 Mode:0 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-7 -> 0xef -> IRQ 7 Mode:0 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-8 -> 0xef -> IRQ 8 Mode:0 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-9 -> 0xef -> IRQ 9 Mode:1 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-10 -> 0xef -> IRQ 10 Mode:1 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-11 -> 0xef -> IRQ 11 Mode:1 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-12 -> 0xef -> IRQ 12 Mode:0 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-13 -> 0xef -> IRQ 13 Mode:0 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-14 -> 0xef -> IRQ 14 Mode:0 Active:0 Dest:1) [ 0.046666] IOAPIC[0]: Set routing entry (0-15 -> 0xef -> IRQ 15 Mode:0 Active:0 Dest:1) [ 0.046666] apic 0 pin 16 not connected [ 0.046666] apic 0 pin 17 not connected [ 0.046666] apic 0 pin 18 not connected [ 0.046666] apic 0 pin 19 not connected [ 0.046666] apic 0 pin 20 not connected [ 0.046666] apic 0 pin 21 not connected [ 0.046666] apic 0 pin 22 not connected [ 0.046666] apic 0 pin 23 not connected [ 0.046666] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.046666] tsc: Detected 2260.998 MHz processor [ 0.050496] Calibrating delay loop (skipped) preset value.. 4523.41 BogoMIPS (lpj=7536660) [ 0.053432] pid_max: default: 4096 minimum: 301 [ 0.065439] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes) [ 0.067154] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes) [ 0.101746] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.103749] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.142300] Freeing SMP alternatives memory: 12K [ 0.172333] smpboot: Max logical packages: 1 [ 0.177277] Using local APIC timer interrupts. [ 0.177277] calibrating APIC timer ... [ 0.183333] ... lapic delta = 6249065 [ 0.183333] ... PM-Timer delta = 357976 [ 0.183333] ... PM-Timer result ok [ 0.183333] ..... delta 6249065 [ 0.183333] ..... mult: 268395324 [ 0.183333] ..... calibration result: 3332834 [ 0.183333] ..... CPU clock speed is 2260.3020 MHz. [ 0.183333] ..... host bus clock speed is 999.3167 MHz. [ 0.184370] smpboot: CPU0: Intel QEMU Virtual CPU version 2.5+ (family: 0x6, model: 0x6, stepping: 0x3) [ 0.218514] Performance Events: PMU not available due to virtualization, using software events only. [ 0.238827] Hierarchical SRCU implementation. [ 0.276342] NMI watchdog: Perf event create on CPU 0 failed with -2 [ 0.284334] NMI watchdog: Perf NMI watchdog permanently disabled [ 0.308517] smp: Bringing up secondary CPUs ... [ 0.313590] smp: Brought up 1 node, 1 CPU [ 0.317117] smpboot: Total of 1 processors activated (4523.41 BogoMIPS) [ 0.360329] devtmpfs: initialized [ 0.458837] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 6370867519511994 ns [ 0.460586] futex hash table entries: 16 (order: -2, 1024 bytes) [ 0.472720] prandom: seed boundary self test passed [ 0.483013] prandom: 100 self tests passed [ 0.508380] regulator-dummy: no parameters [ 0.541591] NET: Registered protocol family 16 [ 0.634629] cpuidle: using governor menu [ 0.655089] ACPI: bus type PCI registered [ 0.665763] PCI: PCI BIOS revision 2.10 entry at 0xfd501, last bus=0 [ 0.666991] PCI: Using configuration type 1 for base access [ 2.218260] HugeTLB registered 4.00 MiB page size, pre-allocated 0 pages [ 2.250351] gpio-f7188x: Not a Fintek device at 0x0000002e [ 2.257096] gpio-f7188x: Not a Fintek device at 0x0000004e [ 2.285214] ACPI: Added _OSI(Module Device) [ 2.287180] ACPI: Added _OSI(Processor Device) [ 2.294304] ACPI: Added _OSI(3.0 _SCP Extensions) [ 2.297121] ACPI: Added _OSI(Processor Aggregator Device) [ 2.873659] ACPI: Interpreter enabled [ 2.881947] ACPI: (supports S0 S5) [ 2.884215] ACPI: Using IOAPIC for interrupt routing [ 2.894433] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 2.962266] ACPI: Enabled 2 GPEs in block 00 to 0F [ 4.309813] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 4.313949] acpi PNP0A03:00: _OSC: OS supports [Segments] [ 4.319168] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM [ 4.325237] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 4.340912] PCI host bridge to bus 0000:00 [ 4.343851] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 4.347154] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 4.354268] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 4.357090] pci_bus 0000:00: root bus resource [mem 0x14000000-0xfebfffff window] [ 4.360547] pci_bus 0000:00: root bus resource [bus 00-ff] [ 4.370805] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 4.434053] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 4.491878] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 4.533651] pci 0000:00:01.1: reg 0x20: [io 0xc0c0-0xc0cf] [ 4.556862] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 4.560423] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 4.563819] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 4.566993] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 4.615348] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 4.628926] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 4.630675] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 4.682167] pci 0000:00:02.0: [1234:1111] type 00 class 0x030000 [ 4.697048] pci 0000:00:02.0: reg 0x10: [mem 0xfd000000-0xfdffffff pref] [ 4.720385] pci 0000:00:02.0: reg 0x18: [mem 0xfebf0000-0xfebf0fff] [ 4.766987] pci 0000:00:02.0: reg 0x30: [mem 0xfebe0000-0xfebeffff pref] [ 4.819064] pci 0000:00:03.0: [8086:100e] type 00 class 0x020000 [ 4.830234] pci 0000:00:03.0: reg 0x10: [mem 0xfebc0000-0xfebdffff] [ 4.840230] pci 0000:00:03.0: reg 0x14: [io 0xc000-0xc03f] [ 4.887371] pci 0000:00:03.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 4.940252] pci 0000:00:04.0: [1af4:1001] type 00 class 0x010000 [ 4.960253] pci 0000:00:04.0: reg 0x10: [io 0xc040-0xc07f] [ 4.973626] pci 0000:00:04.0: reg 0x14: [mem 0xfebf1000-0xfebf1fff] [ 5.010222] pci 0000:00:04.0: reg 0x20: [mem 0xfe000000-0xfe003fff 64bit pref] [ 5.080231] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 5.093585] pci 0000:00:05.0: reg 0x10: [io 0xc080-0xc0bf] [ 5.106923] pci 0000:00:05.0: reg 0x14: [mem 0xfebf2000-0xfebf2fff] [ 5.140257] pci 0000:00:05.0: reg 0x20: [mem 0xfe004000-0xfe007fff 64bit pref] [ 5.208751] pci 0000:00:06.0: [8086:25ab] type 00 class 0x088000 [ 5.223562] pci 0000:00:06.0: reg 0x10: [mem 0xfebf3000-0xfebf300f] [ 5.329712] pci_bus 0000:00: on NUMA node 0 [ 5.445604] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11) [ 5.471323] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11) [ 5.495212] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11) [ 5.524688] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11) [ 5.539299] ACPI: PCI Interrupt Link [LNKS] (IRQs *9) [ 5.661688] pci 0000:00:02.0: vgaarb: setting as boot VGA device [ 5.663333] pci 0000:00:02.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none [ 5.666926] pci 0000:00:02.0: vgaarb: bridge control possible [ 5.670398] vgaarb: loaded [ 5.730263] media: Linux media interface: v0.10 [ 5.737955] Linux video capture interface: v2.00 [ 5.745472] pps_core: LinuxPPS API ver. 1 registered [ 5.747147] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 5.754920] EDAC MC: Ver: 3.0.0 [ 5.804724] FPGA manager framework [ 5.810356] PCI: Using ACPI for IRQ routing [ 5.813691] PCI: pci_cache_line_size set to 32 bytes [ 5.822526] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff] [ 5.827805] e820: reserve RAM buffer [mem 0x13fdc000-0x13ffffff] [ 5.903283] clocksource: Switched to clocksource kvm-clock [ 6.058778] Warning: could not register all branches stats [ 6.068629] Warning: could not register annotated branches stats [ 8.512955] VFS: Disk quotas dquot_6.6.0 [ 8.528193] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) [ 8.547658] FS-Cache: Loaded [ 8.564741] pnp: PnP ACPI init [ 8.584345] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active) [ 8.603042] pnp 00:01: Plug and Play ACPI device, IDs PNP0303 (active) [ 8.622522] pnp 00:02: Plug and Play ACPI device, IDs PNP0f13 (active) [ 8.636395] pnp 00:03: [dma 2] [ 8.646239] pnp 00:03: Plug and Play ACPI device, IDs PNP0700 (active) [ 8.669127] pnp 00:04: Plug and Play ACPI device, IDs PNP0400 (active) [ 8.691674] pnp 00:05: Plug and Play ACPI device, IDs PNP0501 (active) [ 8.714615] pnp 00:06: Plug and Play ACPI device, IDs PNP0501 (active) [ 8.797513] pnp: PnP ACPI: found 7 devices [ 8.903386] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 8.925588] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 8.935894] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 8.946132] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 8.964174] pci_bus 0000:00: resource 7 [mem 0x14000000-0xfebfffff window] [ 8.998817] NET: Registered protocol family 1 [ 9.007860] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 9.018005] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 9.028242] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 9.039554] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff] [ 9.055242] PCI: CLS 0 bytes, default 32 [ 9.088936] Unpacking initramfs... [ 83.799598] Freeing initrd memory: 3956K [ 84.032398] PCLMULQDQ-NI instructions are not detected. [ 84.056326] spin_lock-torture:--- Start of test [debug]: nwriters_stress=2 nreaders_stress=0 stat_interval=60 verbose=1 shuffle_interval=3 stutter=5 shutdown_secs=0 onoff_interval=0 onoff_holdoff=0 [ 84.084597] spin_lock-torture: Creating torture_shuffle task [ 84.099962] spin_lock-torture: Creating torture_stutter task [ 84.109980] spin_lock-torture: torture_shuffle task started [ 84.125436] spin_lock-torture: Creating lock_torture_writer task [ 84.135153] spin_lock-torture: torture_stutter task started [ 84.158808] spin_lock-torture: Creating lock_torture_writer task [ 84.169118] spin_lock-torture: lock_torture_writer task started [ 84.191674] spin_lock-torture: Creating lock_torture_stats task [ 84.202077] spin_lock-torture: lock_torture_writer task started [ 84.219609] torture_init_begin: Refusing rcu init: spin_lock running. [ 84.231699] spin_lock-torture: lock_torture_stats task started [ 84.242513] torture_init_begin: One torture test at a time! [ 84.413131] Initialise system trusted keyrings [ 84.426216] Key type blacklist registered [ 84.442127] workingset: timestamp_bits=30 max_order=17 bucket_order=0 [ 85.237921] zbud: loaded [ 85.325748] fuse init (API version 7.26) [ 86.745814] Key type asymmetric registered [ 86.763463] Asymmetric key parser 'x509' registered [ 86.835270] test_hexdump: all 1184 tests passed [ 87.183081] test_hash: __hash_32() has no arch implementation to test. [ 87.196017] test_hash: hash_32() has no arch implementation to test. [ 87.206641] test_hash: hash_64() has no arch implementation to test. [ 87.219249] test_hash: 33152 tests passed. [ 87.229233] test_siphash: self-tests: pass [ 87.343173] Running rhashtable test nelem=8, max_size=0, shrinking=0 [ 87.356127] Test 00: [ 87.369327] Adding 50000 keys [ 110.996115] Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0 [ 112.550015] Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0 [ 112.565378] Deleting 50000 keys [ 120.021445] Duration of test: 32646318011 ns [ 120.032984] Test 01: [ 120.039879] Adding 50000 keys [ 142.819032] Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0 [ 144.139740] Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0 [ 144.155559] Deleting 50000 keys [ 144.695049] Writes: Total: 2 Max/Min: 0/0 Fail: 0 [ 150.212806] Duration of test: 30163979041 ns [ 150.223135] Test 02: [ 150.231904] Adding 50000 keys [ 168.376137] Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0 [ 169.681546] Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0 [ 169.695972] Deleting 50000 keys [ 174.882681] Duration of test: 24644482823 ns [ 174.892111] Test 03: [ 174.898405] Adding 50000 keys [ 194.657816] Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0 [ 195.722987] Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0 [ 195.735075] Deleting 50000 keys [ 200.652174] Duration of test: 25747413608 ns [ 204.021031] test if its possible to exceed max_size 8192: no, ok [ 204.036012] Average test time: 28300548370 [ 204.045272] Testing concurrent rhashtable access from 10 threads [ 206.134970] Writes: Total: 2 Max/Min: 0/0 Fail: 0 [ 267.575158] Writes: Total: 2 Max/Min: 0/0 Fail: 0 [ 329.015853] Writes: Total: 2 Max/Min: 0/0 Fail: 0 [ 368.268565] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 62s! [ 368.294584] Showing busy workqueues and worker pools: [ 368.303142] workqueue events: flags=0x0 [ 368.310492] pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=4/256 [ 368.312885] in-flight: 3:rht_deferred_worker [ 368.312885] pending: rht_deferred_worker, tsc_refine_calibration_work, vmstat_shepherd [ 368.342255] pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=62s workers=2 idle: 16 [ 368.356480] INFO: task swapper/0:1 blocked for more than 120 seconds. [ 368.451098] Not tainted 4.14.0-10859-gcf9b077 #13 [ 368.564524] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 368.726003] swapper/0 D 0 1 0 0x80000000 [ 368.845359] Call Trace: [ 368.908714] ? __schedule+0x81a/0x84b [ 368.984507] ? schedule+0x59/0x84 [ 369.067920] ? schedule_timeout+0x1b/0xb9 [ 369.155414] ? _raw_spin_unlock_irq+0x28/0x6a [ 369.241353] ? _raw_spin_unlock_irq+0x4a/0x6a [ 369.334592] ? __wait_for_common+0x186/0x24a [ 369.431098] ? console_conditional_schedule+0x3c/0x3c [ 369.557839] ? do_task_dead+0x46/0x46 [ 369.651937] ? wait_for_completion+0x19/0x1c [ 369.752007] ? kthread_stop+0x196/0x326 [ 369.847831] ? test_rht_init+0x963/0x9da [ 369.942078] ? ___siphash_aligned+0x10/0x10 [ 370.077915] ? test_rhltable+0xd1e/0xd1e [ 370.171118] ? do_one_initcall+0x96/0x19b [ 370.272905] ? parse_args+0x19d/0x250 [ 370.358882] ? kernel_init_freeable+0xd2/0x1b8 [ 370.465397] ? kernel_init_freeable+0xee/0x1b8 [ 370.571169] ? rest_init+0xb3/0xb3 [ 370.658826] ? kernel_init+0xd/0x15f [ 370.746031] ? ret_from_fork+0x19/0x24 [ 370.839497] [ 370.839497] Showing all locks held in the system: [ 370.978033] 2 locks held by khungtaskd/17: [ 370.985872] #0: (rcu_read_lock){....}, at: [<7911eae2>] rcu_read_lock+0x0/0x6c [ 370.999617] #1: (tasklist_lock){.+.+}, at: [<790bb514>] debug_show_all_locks+0x3a/0x13d [ 371.014651] [ 371.018049] ============================================= [ 371.018049] [ 371.651885] NMI backtrace for cpu 0 [ 371.668798] CPU: 0 PID: 17 Comm: khungtaskd Not tainted 4.14.0-10859-gcf9b077 #13 [ 371.670706] Call Trace: [ 371.670706] ? show_stack+0x5e/0x66 [ 371.670706] ? dump_stack+0xc1/0x121 [ 371.670706] ? nmi_cpu_backtrace+0xf7/0x110 [ 371.670706] ? nmi_trigger_cpumask_backtrace+0xcf/0x1b2 [ 371.670706] ? lapic_can_unplug_cpu+0xb5/0xb5 [ 371.670706] ? watchdog+0x524/0x593 [ 371.670706] ? kthread+0x154/0x159 [ 371.670706] ? rcu_read_lock+0x6c/0x6c [ 371.670706] ? queuing_blocked+0x68/0x68 [ 371.670706] ? ret_from_fork+0x19/0x24 [ 372.922491] Kernel panic - not syncing: hung_task: blocked tasks [ 372.923689] CPU: 0 PID: 17 Comm: khungtaskd Not tainted 4.14.0-10859-gcf9b077 #13 [ 372.923689] Call Trace: [ 372.923689] ? show_stack+0x5e/0x66 [ 372.923689] ? dump_stack+0xc1/0x121 [ 372.923689] ? panic+0xec/0x2b6 [ 372.923689] ? watchdog+0x52e/0x593 [ 372.923689] ? kthread+0x154/0x159 [ 372.923689] ? rcu_read_lock+0x6c/0x6c [ 372.923689] ? queuing_blocked+0x68/0x68 [ 372.923689] ? ret_from_fork+0x19/0x24 [ 372.923689] Kernel Offset: disabled Elapsed time: 370 #!/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/openwrt/openwrt-i386-2016-03-16.cgz /lkp/lkp/lkp-i386.cgz /osimage/pkg/debian-x86_64-2016-08-31.cgz/trinity-static-i386-x86_64-6ddabfd2_2017-11-10.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-openwrt-i386-21-0 256G qemu-img create -f qcow2 disk-vm-lkp-wsx03-openwrt-i386-21-1 256G kvm=( qemu-system-i386 -enable-kvm -kernel $kernel -initrd initrd.img -m 320 -smp 1 -device e1000,netdev=net0 -netdev user,id=net0 -boot order=nc -no-reboot -watchdog i6300esb -watchdog-action debug -rtc base=localtime -drive file=disk-vm-lkp-wsx03-openwrt-i386-21-0,media=disk,if=virtio -drive file=disk-vm-lkp-wsx03-openwrt-i386-21-1,media=disk,if=virtio -serial stdio -display none -monitor null ) append=( ip=::::vm-lkp-wsx03-openwrt-i386-21::dhcp root=/dev/ram0 user=lkp job=/job-script ARCH=i386 kconfig=i386-randconfig-i0-201746 branch=linus/master commit=cf9b0772f2e410645fece13b749bd56505b998b8 BOOT_IMAGE=/pkg/linux/i386-randconfig-i0-201746/gcc-6/cf9b0772f2e410645fece13b749bd56505b998b8/vmlinuz-4.14.0-10859-gcf9b077 max_uptime=1500 RESULT_ROOT=/result/trinity/300s/vm-lkp-wsx03-openwrt-i386/openwrt-i386-2016-03-16.cgz/i386-randconfig-i0-201746/gcc-6/cf9b0772f2e410645fece13b749bd56505b998b8/1 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 drbd.minor_count=8 ) "${kvm[@]}" -append "${append[*]}"