RE: Boot regression (was "Re: [PATCH] genhd: Do not hold event lock when scheduling workqueue elements")

[Dexuan Cui <decui@microsoft.com>]

[-- Attachment #1: Type: text/plain, Size: 2451 bytes --]

> From: hch@lst.de [mailto:hch@lst.de]
> Sent: Tuesday, February 14, 2017 22:51
> To: Dexuan Cui <decui@microsoft.com>
> Cc: hch@lst.de; Jens Axboe <axboe@kernel.dk>; Bart Van Assche
> <Bart.VanAssche@sandisk.com>; hare@suse.com; hare@suse.de; Martin K.
> Petersen <martin.petersen@oracle.com>; linux-kernel@vger.kernel.org;
> linux-block@vger.kernel.org; jth@kernel.org; Nick Meier
> <Nick.Meier@microsoft.com>; Alex Ng (LIS) <alexng@microsoft.com>; Long Li
> <longli@microsoft.com>; Adrian Suhov (Cloudbase Solutions SRL) <v-
> adsuho@microsoft.com>; Chris Valean (Cloudbase Solutions SRL) <v-
> chvale@microsoft.com>
> Subject: Re: Boot regression (was "Re: [PATCH] genhd: Do not hold event lock
> when scheduling workqueue elements")
> 
> On Tue, Feb 14, 2017 at 02:46:41PM +0000, Dexuan Cui wrote:
> > > From: hch@lst.de [mailto:hch@lst.de]
> > > Sent: Tuesday, February 14, 2017 22:29
> > > To: Dexuan Cui <decui@microsoft.com>
> > > Subject: Re: Boot regression (was "Re: [PATCH] genhd: Do not hold event
> lock
> > > when scheduling workqueue elements")
> > >
> > > Ok, thanks for testing.  Can you try the patch below?  It fixes a
> > > clear problem which was partially papered over before the commit
> > > you bisected to, although it can't explain why blk-mq still works.
> >
> > Still bad luck. :-(
> >
> > BTW, I'm using the first "bad" commit (scsi: allocate scsi_cmnd structures
> as
> > part of struct request) + the 2 patches you provided today.
> >
> > I suppose I don't need to test the 2 patches on the latest linux-next repo.
> 
> I'd love a test on that repo actually.  We had a few other for sense
> handling since then I think.

I tested today's linux-next (next-20170214) + the 2 patches just now and got
a weird result: 
sometimes the VM stills hung with a new calltrace (BUG: spinlock bad
magic) , but sometimes the VM did boot up despite the new calltrace!

Attached is the log of a "good" boot.

It looks we have a memory corruption issue somewhere...

Actually previously I saw the "BUG: spinlock bad magic" message once, but I
couldn't repro it later, so I didn't mention it to you.

The good news is that now I can repro the "spinlock bad magic" message
every time. 
I tried to dig into this by enabling Kernel hacking -> Memory debugging,
but didn't find anything abnormal. 
Is it possible that the SCSI layer passes a wrong memory address?

Thanks,
-- Dexuan

[-- Attachment #2: dmesg.log --]
[-- Type: application/octet-stream, Size: 31337 bytes --]

[    0.000000] Linux version 4.10.0-rc8-next-20170214+ (root@decui-u1604) (gcc version 5.3.1 20160413 (Ubuntu 5.3.1-14ubuntu2.1) ) #1 SMP Tue Feb 14 23:10:48 CST 2017
[    0.000000] Command line: BOOT_IMAGE=/boot/hv/bzImage root=UUID=f07ac67a-0109-4738-a388-100218d2c5d2 ro ignore_loglevel scsi_mod.use_blk_mq=N
[    0.000000] KERNEL supported cpus:
[    0.000000]   Intel GenuineIntel
[    0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[    0.000000] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[    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 0x00000000000e0000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000003ffeffff] usable
[    0.000000] BIOS-e820: [mem 0x000000003fff0000-0x000000003fffefff] ACPI data
[    0.000000] BIOS-e820: [mem 0x000000003ffff000-0x000000003fffffff] ACPI NVS
[    0.000000] debug: ignoring loglevel setting.
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] SMBIOS 2.3 present.
[    0.000000] DMI: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS 090006  04/28/2016
[    0.000000] Hypervisor detected: Microsoft HyperV
[    0.000000] HyperV: features 0x2e7f, hints 0xc2c
[    0.000000] Hyper-V Host Build:14393-10.0-0-0.576
[    0.000000] HyperV: LAPIC Timer Frequency: 0xc3500
[    0.000000] tsc: Marking TSC unstable due to running on Hyper-V
[    0.000000] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.000000] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.000000] e820: last_pfn = 0x3fff0 max_arch_pfn = 0x400000000
[    0.000000] MTRR default type: uncachable
[    0.000000] MTRR fixed ranges enabled:
[    0.000000]   00000-9FFFF write-back
[    0.000000]   A0000-DFFFF uncachable
[    0.000000]   E0000-FFFFF write-back
[    0.000000] MTRR variable ranges enabled:
[    0.000000]   0 base 00000000000 mask FFF00000000 write-back
[    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  WC  UC- UC  WB  WC  UC- WT  
[    0.000000] found SMP MP-table at [mem 0x000ff780-0x000ff78f] mapped at [ffff9539400ff780]
[    0.000000] Scanning 1 areas for low memory corruption
[    0.000000] Base memory trampoline at [ffff953940099000] 99000 size 24576
[    0.000000] BRK [0x0e91c000, 0x0e91cfff] PGTABLE
[    0.000000] BRK [0x0e91d000, 0x0e91dfff] PGTABLE
[    0.000000] BRK [0x0e91e000, 0x0e91efff] PGTABLE
[    0.000000] BRK [0x0e91f000, 0x0e91ffff] PGTABLE
[    0.000000] BRK [0x0e920000, 0x0e920fff] PGTABLE
[    0.000000] RAMDISK: [mem 0x2fde8000-0x33eebfff]
[    0.000000] ACPI: Early table checksum verification disabled
[    0.000000] ACPI: RSDP 0x00000000000F56F0 000014 (v00 ACPIAM)
[    0.000000] ACPI: RSDT 0x000000003FFF0000 000040 (v01 VRTUAL MICROSFT 04001628 MSFT 00000097)
[    0.000000] ACPI: FACP 0x000000003FFF0200 000081 (v02 VRTUAL MICROSFT 04001628 MSFT 00000097)
[    0.000000] ACPI: DSDT 0x000000003FFF1724 0033BE (v01 MSFTVM MSFTVM02 00000002 INTL 02002026)
[    0.000000] ACPI: FACS 0x000000003FFFF000 000040
[    0.000000] ACPI: WAET 0x000000003FFF1480 000028 (v01 VRTUAL MICROSFT 04001628 MSFT 00000097)
[    0.000000] ACPI: SLIC 0x000000003FFF14C0 000176 (v01 VRTUAL MICROSFT 04001628 MSFT 00000097)
[    0.000000] ACPI: OEM0 0x000000003FFF16C0 000064 (v01 VRTUAL MICROSFT 04001628 MSFT 00000097)
[    0.000000] ACPI: SRAT 0x000000003FFF0600 0000E0 (v02 VRTUAL MICROSFT 00000001 MSFT 00000001)
[    0.000000] ACPI: APIC 0x000000003FFF0300 000252 (v01 VRTUAL MICROSFT 04001628 MSFT 00000097)
[    0.000000] ACPI: OEMB 0x000000003FFFF040 000064 (v01 VRTUAL MICROSFT 04001628 MSFT 00000097)
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] SRAT: PXM 0 -> APIC 0x00 -> Node 0
[    0.000000] ACPI: SRAT: Node 0 PXM 0 [mem 0x00000000-0x3fffffff] hotplug
[    0.000000] ACPI: SRAT: Node 0 PXM 0 [mem 0x40200000-0xf7ffffff] hotplug
[    0.000000] ACPI: SRAT: Node 0 PXM 0 [mem 0x100000000-0xfdfffffff] hotplug
[    0.000000] ACPI: SRAT: Node 0 PXM 0 [mem 0x1000000000-0xffffffffff] hotplug
[    0.000000] NODE_DATA(0) allocated [mem 0x3ffec000-0x3ffeffff]
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.000000]   DMA32    [mem 0x0000000001000000-0x000000003ffeffff]
[    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-0x000000003ffeffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x000000003ffeffff]
[    0.000000] On node 0 totalpages: 262030
[    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: 258032 pages, LIFO batch:31
[    0.000000] ACPI: PM-Timer IO Port: 0x408
[    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] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.000000] ACPI: IRQ0 used by override.
[    0.000000] ACPI: IRQ9 used by override.
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] smpboot: Allowing 64 CPUs, 63 hotplug CPUs
[    0.000000] e820: [mem 0x40000000-0xffffffff] available for PCI devices
[    0.000000] Booting paravirtualized kernel on bare hardware
[    0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[    0.000000] setup_percpu: NR_CPUS:256 nr_cpumask_bits:256 nr_cpu_ids:64 nr_node_ids:1
[    0.000000] percpu: Embedded 37 pages/cpu @ffff95397d600000 s112328 r8192 d31032 u262144
[    0.000000] pcpu-alloc: s112328 r8192 d31032 u262144 alloc=1*2097152
[    0.000000] pcpu-alloc: [0] 00 01 02 03 04 05 06 07 [0] 08 09 10 11 12 13 14 15 
[    0.000000] pcpu-alloc: [0] 16 17 18 19 20 21 22 23 [0] 24 25 26 27 28 29 30 31 
[    0.000000] pcpu-alloc: [0] 32 33 34 35 36 37 38 39 [0] 40 41 42 43 44 45 46 47 
[    0.000000] pcpu-alloc: [0] 48 49 50 51 52 53 54 55 [0] 56 57 58 59 60 61 62 63 
[    0.000000] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 257913
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: BOOT_IMAGE=/boot/hv/bzImage root=UUID=f07ac67a-0109-4738-a388-100218d2c5d2 ro ignore_loglevel scsi_mod.use_blk_mq=N
[    0.000000] log_buf_len individual max cpu contribution: 4096 bytes
[    0.000000] log_buf_len total cpu_extra contributions: 258048 bytes
[    0.000000] log_buf_len min size: 262144 bytes
[    0.000000] log_buf_len: 524288 bytes
[    0.000000] early log buf free: 254580(97%)
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Memory: 863304K/1048120K available (6896K kernel code, 1440K rwdata, 2784K rodata, 1304K init, 10644K bss, 184816K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=64, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000] 	Build-time adjustment of leaf fanout to 64.
[    0.000000] 	RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=64.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=64
[    0.000000] NR_IRQS:16640 nr_irqs:936 16
[    0.000000] 	Offload RCU callbacks from all CPUs
[    0.000000] 	Offload RCU callbacks from CPUs: 0-63.
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [tty0] enabled
[    0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.000000] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.000000] ... MAX_LOCK_DEPTH:          48
[    0.000000] ... MAX_LOCKDEP_KEYS:        8191
[    0.000000] ... CLASSHASH_SIZE:          4096
[    0.000000] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.000000] ... MAX_LOCKDEP_CHAINS:      65536
[    0.000000] ... CHAINHASH_SIZE:          32768
[    0.000000]  memory used by lock dependency info: 8127 kB
[    0.000000]  per task-struct memory footprint: 1920 bytes
[    0.000000] tsc: Fast TSC calibration failed
[    0.012000] tsc: Unable to calibrate against PIT
[    0.016000] tsc: using PMTIMER reference calibration
[    0.016000] tsc: Detected 2600.008 MHz processor
[    0.016000] Calibrating delay loop (skipped), value calculated using timer frequency.. 5200.01 BogoMIPS (lpj=10400032)
[    0.016000] pid_max: default: 65536 minimum: 512
[    0.020112] ACPI: Core revision 20170119
[    0.025555] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.026775] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.028419] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.030051] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes)
[    0.030981] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes)
[    0.032912] CPU: Physical Processor ID: 0
[    0.033859] mce: CPU supports 1 MCE banks
[    0.034848] Last level iTLB entries: 4KB 512, 2MB 8, 4MB 8
[    0.036046] Last level dTLB entries: 4KB 512, 2MB 0, 4MB 0, 1GB 4
[    0.054815] ftrace: allocating 24941 entries in 98 pages
[    0.069829] smpboot: Max logical packages: 64
[    0.072084] Switched APIC routing to physical flat.
[    0.072963] clocksource: hyperv_clocksource_tsc_page: mask: 0xffffffffffffffff max_cycles: 0x24e6a1710, max_idle_ns: 440795202120 ns
[    0.111150] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.112225] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz (family: 0x6, model: 0x3e, stepping: 0x4)
[    0.113384] Performance Events: unsupported p6 CPU model 62 no PMU driver, software events only.
[    0.116871] NMI watchdog: disabled (cpu0): hardware events not enabled
[    0.117812] NMI watchdog: Shutting down hard lockup detector on all cpus
[    0.118714] smp: Bringing up secondary CPUs ...
[    0.119568] smp: Brought up 1 node, 1 CPU
[    0.120023] smpboot: Total of 1 processors activated (5200.01 BogoMIPS)
[    0.129001] devtmpfs: initialized
[    0.130063] x86/mm: Memory block size: 128MB
[    0.136138] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.137510] pinctrl core: initialized pinctrl subsystem
[    0.138840] NET: Registered protocol family 16
[    0.144098] cpuidle: using governor ladder
[    0.148010] cpuidle: using governor menu
[    0.148845] PCCT header not found.
[    0.149763] ACPI: bus type PCI registered
[    0.152433] PCI: Using configuration type 1 for base access
[    0.158484] HugeTLB registered 1 GB page size, pre-allocated 0 pages
[    0.160011] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    0.162411] ACPI: Added _OSI(Module Device)
[    0.164009] ACPI: Added _OSI(Processor Device)
[    0.164843] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.165672] ACPI: Added _OSI(Processor Aggregator Device)
[    0.176058] ACPI: Interpreter enabled
[    0.176988] ACPI: (supports S0 S5)
[    0.177811] ACPI: Using IOAPIC for interrupt routing
[    0.178691] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.205665] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.206736] acpi PNP0A03:00: _OSC: OS supports [Segments MSI]
[    0.207608] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
[    0.208181] PCI host bridge to bus 0000:00
[    0.209050] pci_bus 0000:00: root bus resource [mem 0xfe0000000-0xfffffffff window]
[    0.209979] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    0.210833] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
[    0.212009] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[    0.212945] pci_bus 0000:00: root bus resource [mem 0xf8000000-0xfffbffff window]
[    0.213875] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.215031] pci 0000:00:00.0: [8086:7192] type 00 class 0x060000
[    0.220504] pci 0000:00:07.0: [8086:7110] type 00 class 0x060100
[    0.225876] pci 0000:00:07.1: [8086:7111] type 00 class 0x010180
[    0.230354] pci 0000:00:07.1: reg 0x20: [io  0xffa0-0xffaf]
[    0.232661] pci 0000:00:07.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
[    0.234841] pci 0000:00:07.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
[    0.235712] pci 0000:00:07.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
[    0.236010] pci 0000:00:07.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
[    0.239084] pci 0000:00:07.3: [8086:7113] type 00 class 0x068000
[    0.240088] * Found PM-Timer Bug on the chipset. Due to workarounds for a bug,
               * this clock source is slow. Consider trying other clock sources
[    0.245925] pci 0000:00:07.3: quirk: [io  0x0400-0x043f] claimed by PIIX4 ACPI
[    0.248454] pci 0000:00:08.0: [1414:5353] type 00 class 0x030000
[    0.250097] pci 0000:00:08.0: reg 0x10: [mem 0xf8000000-0xfbffffff]
[    0.269769] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 7 9 10 *11 12 14 15)
[    0.271040] ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 7 9 10 11 12 14 15) *0, disabled.
[    0.272376] ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 7 9 10 11 12 14 15) *0, disabled.
[    0.273715] ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 7 9 10 11 12 14 15) *0, disabled.
[    0.274964] ACPI: Enabled 1 GPEs in block 00 to 0F
[    0.277122] pci 0000:00:08.0: vgaarb: setting as boot VGA device
[    0.277911] pci 0000:00:08.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none
[    0.278775] pci 0000:00:08.0: vgaarb: bridge control possible
[    0.279559] vgaarb: loaded
[    0.280170] SCSI subsystem initialized
[    0.281217] libata version 3.00 loaded.
[    0.284051] PCI: Using ACPI for IRQ routing
[    0.286144] PCI: pci_cache_line_size set to 64 bytes
[    0.287653] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
[    0.288023] e820: reserve RAM buffer [mem 0x3fff0000-0x3fffffff]
[    0.289406] clocksource: Switched to clocksource hyperv_clocksource_tsc_page
[    0.342146] VFS: Disk quotas dquot_6.6.0
[    0.343311] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.345144] pnp: PnP ACPI init
[    0.346201] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.347171] pnp 00:01: Plug and Play ACPI device, IDs PNP0303 PNP030b (active)
[    0.348231] pnp 00:02: Plug and Play ACPI device, IDs PNP0f03 PNP0f13 (active)
[    0.350505] pnp 00:03: [dma 0 disabled]
[    0.351389] pnp 00:03: Plug and Play ACPI device, IDs PNP0501 (active)
[    0.353580] pnp 00:04: [dma 0 disabled]
[    0.354429] pnp 00:04: Plug and Play ACPI device, IDs PNP0501 (active)
[    0.356734] pnp 00:05: [dma 2]
[    0.357670] pnp 00:05: Plug and Play ACPI device, IDs PNP0700 (active)
[    0.358706] system 00:06: [io  0x01e0-0x01ef] has been reserved
[    0.359537] system 00:06: [io  0x0160-0x016f] has been reserved
[    0.360393] system 00:06: [io  0x0278-0x027f] has been reserved
[    0.361216] system 00:06: [io  0x0378-0x037f] has been reserved
[    0.362032] system 00:06: [io  0x0678-0x067f] has been reserved
[    0.362848] system 00:06: [io  0x0778-0x077f] has been reserved
[    0.363661] system 00:06: [io  0x04d0-0x04d1] has been reserved
[    0.364519] system 00:06: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.365670] system 00:07: [io  0x0400-0x043f] has been reserved
[    0.366579] system 00:07: [io  0x0370-0x0371] has been reserved
[    0.367403] system 00:07: [io  0x0440-0x044f] has been reserved
[    0.368261] system 00:07: [mem 0xfec00000-0xfec00fff] could not be reserved
[    0.369087] system 00:07: [mem 0xfee00000-0xfee00fff] has been reserved
[    0.369875] system 00:07: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.370930] system 00:08: [mem 0x00000000-0x0009ffff] could not be reserved
[    0.371843] system 00:08: [mem 0x000c0000-0x000dffff] could not be reserved
[    0.374012] system 00:08: [mem 0x000e0000-0x000fffff] could not be reserved
[    0.374858] system 00:08: [mem 0x00100000-0xf7ffffff] could not be reserved
[    0.375703] system 00:08: [mem 0xfffc0000-0xffffffff] has been reserved
[    0.376579] system 00:08: Plug and Play ACPI device, IDs PNP0c01 (active)
[    0.379161] pnp: PnP ACPI: found 9 devices
[    0.387621] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[    0.388618] pci_bus 0000:00: resource 4 [mem 0xfe0000000-0xfffffffff window]
[    0.389456] pci_bus 0000:00: resource 5 [io  0x0000-0x0cf7 window]
[    0.390281] pci_bus 0000:00: resource 6 [io  0x0d00-0xffff window]
[    0.391105] pci_bus 0000:00: resource 7 [mem 0x000a0000-0x000bffff window]
[    0.391931] pci_bus 0000:00: resource 8 [mem 0xf8000000-0xfffbffff window]
[    0.392959] NET: Registered protocol family 2
[    0.394453] TCP established hash table entries: 8192 (order: 4, 65536 bytes)
[    0.395457] TCP bind hash table entries: 8192 (order: 7, 524288 bytes)
[    0.396936] TCP: Hash tables configured (established 8192 bind 8192)
[    0.398239] UDP hash table entries: 512 (order: 4, 81920 bytes)
[    0.399295] UDP-Lite hash table entries: 512 (order: 4, 81920 bytes)
[    0.400881] NET: Registered protocol family 1
[    0.401792] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[    0.403210] pci 0000:00:08.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[    0.404276] PCI: CLS 0 bytes, default 64
[    0.405282] Unpacking initramfs...
[    1.706148] Freeing initrd memory: 66576K
[    1.706919] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[    1.707234] software IO TLB [mem 0x39600000-0x3d600000] (64MB) mapped at [ffff953979600000-ffff95397d5fffff]
[    1.707690] RAPL PMU: API unit is 2^-32 Joules, 3 fixed counters, 10737418240 ms ovfl timer
[    1.708045] RAPL PMU: hw unit of domain pp0-core 2^-0 Joules
[    1.708358] RAPL PMU: hw unit of domain package 2^-0 Joules
[    1.708669] RAPL PMU: hw unit of domain dram 2^-0 Joules
[    1.709048] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x257a4365b0e, max_idle_ns: 440795224253 ns
[    1.709427] Scanning for low memory corruption every 60 seconds
[    1.710395] futex hash table entries: 16384 (order: 9, 2097152 bytes)
[    1.711254] audit: initializing netlink subsys (disabled)
[    1.711684] cryptomgr_test (31) used greatest stack depth: 14528 bytes left
[    1.712237] Initialise system trusted keyrings
[    1.712598] audit: type=2000 audit(1487085689.712:1): state=initialized audit_enabled=0 res=1
[    1.713063] workingset: timestamp_bits=40 max_order=18 bucket_order=0
[    1.714737] zbud: loaded
[    1.715782] SGI XFS with security attributes, no debug enabled
[    1.718151] Key type asymmetric registered
[    1.718518] Asymmetric key parser 'x509' registered
[    1.718887] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[    1.719379] io scheduler noop registered
[    1.719720] io scheduler deadline registered (default)
[    1.720518] io scheduler cfq registered
[    1.720877] io scheduler mq-deadline registered
[    1.721393] GHES: HEST is not enabled!
[    1.721770] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
[    1.769785] 00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[    1.818962] 00:04: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
[    1.820459] Linux agpgart interface v0.103
[    1.820970] ata_piix 0000:00:07.1: version 2.13
[    1.821431] ata_piix 0000:00:07.1: Hyper-V Virtual Machine detected, ATA device ignore set
[    1.823794] scsi host0: ata_piix
[    1.824253] scsi host1: ata_piix
[    1.824589] ata1: PATA max UDMA/33 cmd 0x1f0 ctl 0x3f6 bmdma 0xffa0 irq 14
[    1.824922] ata2: PATA max UDMA/33 cmd 0x170 ctl 0x376 bmdma 0xffa8 irq 15
[    1.825372] i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f03:PS2M] at 0x60,0x64 irq 1,12
[    1.828787] serio: i8042 KBD port at 0x60,0x64 irq 1
[    1.829127] serio: i8042 AUX port at 0x60,0x64 irq 12
[    1.830457] rtc_cmos 00:00: RTC can wake from S4
[    1.852390] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0
[    1.853241] rtc_cmos 00:00: alarms up to one month, 114 bytes nvram
[    1.853629] ledtrig-cpu: registered to indicate activity on CPUs
[    1.854189] NET: Registered protocol family 10
[    1.855119] Segment Routing with IPv6
[    1.855495] NET: Registered protocol family 17
[    1.855813] Key type dns_resolver registered
[    1.856411] registered taskstats version 1
[    1.857175] Loading compiled-in X.509 certificates
[    1.857529] zswap: loaded using pool lzo/zbud
[    1.858415] rtc_cmos 00:00: setting system clock to 2017-02-14 15:21:30 UTC (1487085690)
[    1.858766] BIOS EDD facility v0.16 2004-Jun-25, 0 devices found
[    1.859087] EDD information not available.
[    2.093148] ata1.01: NODEV after polling detection
[    2.143359] ata1.00: host indicates ignore ATA devices, ignored
[    2.144884] Freeing unused kernel memory: 1304K
[    2.145283] Write protecting the kernel read-only data: 12288k
[    2.146252] Freeing unused kernel memory: 1280K
[    2.148804] Freeing unused kernel memory: 1312K
[    2.150963] mount (67) used greatest stack depth: 14512 bytes left
[    2.152646] exe (70) used greatest stack depth: 14504 bytes left
[    2.155475] exe (73) used greatest stack depth: 14064 bytes left
[    2.163564] random: udevadm: uninitialized urandom read (16 bytes read)
[    2.163978] random: udevadm: uninitialized urandom read (16 bytes read)
[    2.164923] random: systemd-udevd: uninitialized urandom read (16 bytes read)
[    2.165384] random: systemd-udevd: uninitialized urandom read (16 bytes read)
[    2.165716] random: systemd-udevd: uninitialized urandom read (16 bytes read)
[    2.166047] random: systemd-udevd: uninitialized urandom read (16 bytes read)
[    2.171533] random: udevadm: uninitialized urandom read (16 bytes read)
[    2.171994] random: udevadm: uninitialized urandom read (16 bytes read)
[    2.172758] random: udevadm: uninitialized urandom read (16 bytes read)
[    2.173192] random: udevadm: uninitialized urandom read (16 bytes read)
[    2.235888] udevadm (84) used greatest stack depth: 13904 bytes left
[    2.279298] hv_vmbus: Vmbus version:4.0
[    2.291556] hv_vmbus: registering driver hyperv_fb
[    2.301275] hyperv_fb: Screen resolution: 1152x864, Color depth: 32
[    2.310220] Console: switching to colour frame buffer device 144x54
[    2.342210] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
[    2.454348] hidraw: raw HID events driver (C) Jiri Kosina
[    2.455357] hv_vmbus: registering driver hid_hyperv
[    2.456632] hv_vmbus: registering driver hyperv_keyboard
[    2.459289] hv_utils: Registering HyperV Utility Driver
[    2.459346] hv_vmbus: registering driver hv_util
[    2.468340] hv_vmbus: registering driver hv_netvsc
[    2.472734] hv_vmbus: registering driver hv_storvsc
[    2.477142] input: Microsoft Vmbus HID-compliant Mouse as /devices/0006:045E:0621.0001/input/input3
[    2.477250] hid 0006:045E:0621.0001: input: <UNKNOWN> HID v0.01 Mouse [Microsoft Vmbus HID-compliant Mouse] on 
[    2.478576] hv_utils: Heartbeat IC version 3.0
[    2.524966] scsi host2: storvsc_host_t
[    2.525973] scsi 2:0:0:0: Direct-Access     Msft     Virtual Disk     1.0  PQ: 0 ANSI: 5
[    2.527299] sd 2:0:0:0: Attached scsi generic sg0 type 0
[    2.531966] hv_utils: cannot register PTP clock: 0
[    2.532187] hv_utils: Shutdown IC version 3.0
[    2.532790] hv_utils: TimeSync IC version 4.0
[    2.534166] sd 2:0:0:0: [sda] 83886080 512-byte logical blocks: (42.9 GB/40.0 GiB)
[    2.534244] sd 2:0:0:0: [sda] 4096-byte physical blocks
[    2.534394] sd 2:0:0:0: [sda] Write Protect is off
[    2.534448] sd 2:0:0:0: [sda] Mode Sense: 0f 00 00 00
[    2.534952] sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    2.552432]  sda: sda1 sda2 < sda5 >
[    2.566464] sd 2:0:0:0: [sda] Attached SCSI disk
[    2.570541] random: fast init done
[    2.582194] scsi host3: storvsc_host_t
[    2.584084] hv_utils: VSS IC version 5.0
[    2.593413] scsi 3:0:0:0: Direct-Access     Msft     Virtual Disk     1.0  PQ: 0 ANSI: 5
[    2.618615] sd 3:0:0:0: Attached scsi generic sg1 type 0
[    2.623955] sd 3:0:0:0: [sdb] 266338304 512-byte logical blocks: (136 GB/127 GiB)
[    2.625517] sd 3:0:0:0: [sdb] 4096-byte physical blocks
[    2.627181] sd 3:0:0:0: [sdb] Write Protect is off
[    2.628748] sd 3:0:0:0: [sdb] Mode Sense: 0f 00 00 00
[    2.630468] sd 3:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    2.634044]  sdb: sdb1
[    2.643154] sd 3:0:0:0: [sdb] Attached SCSI disk
[    2.704593] systemd-udevd (96) used greatest stack depth: 13392 bytes left
[    2.706902] systemd-udevd (90) used greatest stack depth: 12816 bytes left
[    2.787475] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
[    2.804051] psmouse serio1: trackpoint: failed to get extended button data
[    3.004174] systemd[1]: systemd 229 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ -LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN)
[    3.007863] systemd[1]: Detected virtualization microsoft.
[    3.010207] systemd[1]: Detected architecture x86-64.
[    3.017969] systemd[1]: Set hostname to <decui-u1604>.
[    3.239480] systemd[1]: Listening on Journal Audit Socket.
[    3.240013] systemd[1]: Reached target Encrypted Volumes.
[    3.248937] systemd[1]: Created slice User and Session Slice.
[    3.253336] systemd[1]: Created slice System Slice.
[    3.257596] systemd[1]: Listening on Device-mapper event daemon FIFOs.
[    3.261790] systemd[1]: Listening on LVM2 poll daemon socket.
[    3.731378] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro
[    3.798352] systemd-journald[212]: Received request to flush runtime journal from PID 1
[    4.406082] hv_vmbus: registering driver hv_pci
[    4.518904] piix4_smbus 0000:00:07.3: SMBus base address uninitialized - upgrade BIOS or use force_addr=0xaddr
[    4.599516] ACPI: \: failed to evaluate _DSM (0x1001)
[    4.601025] hv_pci 2d985bf6-6e3e-453e-bca5-7e5f5930df64: PCI host bridge to bus bca5:00
[    4.668864] pci_bus bca5:00: root bus resource [mem 0xfe0000000-0xfe07fffff window]
[    4.732549] pci bca5:00:02.0: [15b3:1004] type 00 class 0x020000
[    4.742880] pci bca5:00:02.0: reg 0x18: [mem 0xfe0000000-0xfe07fffff 64bit pref]
[    4.804954] AVX version of gcm_enc/dec engaged.
[    4.805602] AES CTR mode by8 optimization enabled
[    4.926729] pci bca5:00:02.0: BAR 2: assigned [mem 0xfe0000000-0xfe07fffff 64bit pref]
[    5.055412] alg: No test for pcbc(aes) (pcbc-aes-aesni)
[    5.526597] random: crng init done
[    5.573076] hv_vmbus: registering driver hv_balloon
[    5.666867] hv_balloon: Using Dynamic Memory protocol version 2.0
[    6.182094] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[    6.208794] sd 2:0:0:0: [storvsc] Sense Key : Illegal Request [current] 
[    6.209447] sd 2:0:0:0: [storvsc] Add. Sense: Invalid command operation code
[    6.210043] sd 3:0:0:0: [storvsc] Sense Key : Illegal Request [current] 
[    6.210618] sd 3:0:0:0: [storvsc] Add. Sense: Invalid command operation code
[    6.212272] sd 2:0:0:0: [storvsc] Sense Key : Illegal Request [current] 
[    6.212897] sd 2:0:0:0: [storvsc] Add. Sense: Invalid command operation code
[    6.213474] sd 3:0:0:0: [storvsc] Sense Key : Illegal Request [current] 
[    6.214051] sd 3:0:0:0: [storvsc] Add. Sense: Invalid command operation code
[    6.358405] XFS (sdb1): Mounting V5 Filesystem
[    6.404478] XFS (sdb1): Ending clean mount
[    7.535174] BUG: spinlock bad magic on CPU#0, swapper/0/0
[    7.536807]  lock: host_ts+0x30/0xffffffffffffe1a0 [hv_utils], .magic: 00000000, .owner: <none>/-1, .owner_cpu: 0
[    7.538436] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.10.0-rc8-next-20170214+ #1
[    7.539142] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS 090006  04/28/2016
[    7.539142] Call Trace:
[    7.539142]  <IRQ>
[    7.539142]  dump_stack+0x63/0x82
[    7.539142]  spin_dump+0x78/0xc0
[    7.539142]  do_raw_spin_lock+0xfd/0x160
[    7.539142]  _raw_spin_lock_irqsave+0x4c/0x60
[    7.539142]  ? timesync_onchannelcallback+0x153/0x220 [hv_utils]
[    7.539142]  timesync_onchannelcallback+0x153/0x220 [hv_utils]
[    7.539142]  vmbus_on_event+0x101/0x170 [hv_vmbus]
[    7.539142]  tasklet_action+0x118/0x130
[    7.539142]  __do_softirq+0x10a/0x2da
[    7.539142]  irq_exit+0xf3/0x100
[    7.539142]  hyperv_vector_handler+0x39/0x50
[    7.539142]  hyperv_callback_vector+0x93/0xa0
[    7.539142] RIP: 0010:native_safe_halt+0x6/0x10
[    7.539142] RSP: 0018:ffffffff81c03e08 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff0c
[    7.539142] RAX: 0000000000000000 RBX: ffffffff81c14500 RCX: 0000000000000000
[    7.539142] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[    7.539142] RBP: ffffffff81c03e08 R08: 0100000000000000 R09: 0000000000000000
[    7.539142] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[    7.539142] R13: ffffffff81c14500 R14: 0000000000000000 R15: 0000000000000000
[    7.539142]  </IRQ>
[    7.539142]  default_idle+0x1e/0xd0
[    7.539142]  arch_cpu_idle+0xf/0x20
[    7.539142]  default_idle_call+0x23/0x30
[    7.539142]  do_idle+0x179/0x1c0
[    7.539142]  cpu_startup_entry+0x62/0x70
[    7.539142]  rest_init+0xb3/0xc0
[    7.539142]  start_kernel+0x45e/0x46b
[    7.539142]  ? early_idt_handler_array+0x120/0x120
[    7.539142]  x86_64_start_reservations+0x24/0x26
[    7.539142]  x86_64_start_kernel+0x134/0x141
[    7.539142]  start_cpu+0x14/0x14
[    7.704113] psmouse serio1: trackpoint: IBM TrackPoint firmware: 0x01, buttons: 0/0
[    7.711357] input: TPPS/2 IBM TrackPoint as /devices/platform/i8042/serio1/input/input2
[    7.723446] input: AT Translated Set 2 keyboard as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/d34b2567-b9b6-42b9-8778-0a4ec0b955bf/serio2/input/input4
[   53.756564] hv_balloon: INFO_TYPE_MAX_PAGE_CNT = 262144
[   58.336111] hv_utils: KVP IC version 4.0