linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* Bisected GFP in bfq_bfqq_expire on v5.1-rc1
@ 2019-03-29 13:02 Dmitrii Tcvetkov
  2019-03-29 14:10 ` Jens Axboe
  0 siblings, 1 reply; 10+ messages in thread
From: Dmitrii Tcvetkov @ 2019-03-29 13:02 UTC (permalink / raw)
  To: linux-block; +Cc: linux-kernel

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

Hi,

I got kernel panic since v5.1-rc1 when working with files on block
device with BFQ scheduler assigned. I didn't find trivial way to
reproduce the panic but "git checkout origin/linux-5.0.y"
on linux-stable-rc[1] git repo on btrfs filesystem reproduces the
problem 100% of the time on my bare-metal machine and in a VM.

Bisect led me to commit 9dee8b3b057e1 (block, bfq: fix queue removal
from weights tree). After reverting this commit on top of current
mainline master(9936328b41ce) I can't reproduce the problem.

dmesg with the panic and bisect log attached.

[1] https://kernel.googlesource.com/pub/scm/linux/kernel/git/stable/linux-stable-rc.git

[-- Attachment #2: dmesg.txt --]
[-- Type: text/plain, Size: 44805 bytes --]

[    0.000000][    T0] Linux version 5.1.0-rc2-ARCH-test2 (feanor@fire) (gcc version 8.3.0 (GCC)) #4 SMP Fri Mar 29 15:21:03 MSK 2019
[    0.000000][    T0] Command line: BOOT_IMAGE=/vmlinuz-linux-test2 root=UUID=9c04c835-60ce-4acf-973d-4a47ac59e769 rw console=ttyS0,115200n8 stack_guard_gap=512 page_poison=1 slub_debug=FZP pti=on spectre_v2=on
 spectre_v2_user=on spec_store_bypass_disable=on
[    0.000000][    T0] KERNEL supported cpus:
[    0.000000][    T0]   Intel GenuineIntel
[    0.000000][    T0]   AMD AuthenticAMD
[    0.000000][    T0] random: get_random_u32 called from bsp_init_amd+0x171/0x200 with crng_init=0
[    0.000000][    T0] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[    0.000000][    T0] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[    0.000000][    T0] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[    0.000000][    T0] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    0.000000][    T0] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[    0.000000][    T0] BIOS-provided physical RAM map:
[    0.000000][    T0] BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable
[    0.000000][    T0] BIOS-e820: [mem 0x0000000000100000-0x00000000007fffff] usable
[    0.000000][    T0] BIOS-e820: [mem 0x0000000000800000-0x0000000000807fff] ACPI NVS
[    0.000000][    T0] BIOS-e820: [mem 0x0000000000808000-0x000000000080ffff] usable
[    0.000000][    T0] BIOS-e820: [mem 0x0000000000810000-0x00000000008fffff] ACPI NVS
[    0.000000][    T0] BIOS-e820: [mem 0x0000000000900000-0x000000007e7cffff] usable
[    0.000000][    T0] BIOS-e820: [mem 0x000000007e7d0000-0x000000007e7d0fff] ACPI data
[    0.000000][    T0] BIOS-e820: [mem 0x000000007e7d1000-0x000000007ea6dfff] usable
[    0.000000][    T0] BIOS-e820: [mem 0x000000007ea6e000-0x000000007ea79fff] ACPI NVS
[    0.000000][    T0] BIOS-e820: [mem 0x000000007ea7a000-0x000000007eb1afff] reserved
[    0.000000][    T0] BIOS-e820: [mem 0x000000007eb1b000-0x000000007fb9afff] usable
[    0.000000][    T0] BIOS-e820: [mem 0x000000007fb9b000-0x000000007fbcafff] type 20
[    0.000000][    T0] BIOS-e820: [mem 0x000000007fbcb000-0x000000007fbf2fff] reserved
[    0.000000][    T0] BIOS-e820: [mem 0x000000007fbf3000-0x000000007fbfafff] ACPI data
[    0.000000][    T0] BIOS-e820: [mem 0x000000007fbfb000-0x000000007fbfefff] ACPI NVS
[    0.000000][    T0] BIOS-e820: [mem 0x000000007fbff000-0x000000007fedbfff] usable
[    0.000000][    T0] BIOS-e820: [mem 0x000000007fedc000-0x000000007ff5ffff] reserved
[    0.000000][    T0] BIOS-e820: [mem 0x000000007ff60000-0x000000007fffffff] ACPI NVS
[    0.000000][    T0] BIOS-e820: [mem 0x0000000080000000-0x000000008fffffff] reserved
[    0.000000][    T0] BIOS-e820: [mem 0x00000000ffc00000-0x00000000ffffffff] reserved
[    0.000000][    T0] BIOS-e820: [mem 0x0000000100000000-0x000000017fffffff] usable
[    0.000000][    T0] NX (Execute Disable) protection: active
[    0.000000][    T0] efi: EFI v2.70 by EDK II
[    0.000000][    T0] efi:  SMBIOS=0x7fbcc000  ACPI=0x7fbfa000  ACPI 2.0=0x7fbfa014  MEMATTR=0x7e8c4298
[    0.000000][    T0] SMBIOS 2.8 present.
[    0.000000][    T0] DMI: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015
[    0.000000][    T0] Hypervisor detected: KVM
[    0.000000][    T0] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000000][    T0] kvm-clock: cpu 0, msr 2ccf7001, primary cpu clock
[    0.000000][    T0] kvm-clock: using sched offset of 14312683989764 cycles
[    0.000002][    T0] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000004][    T0] tsc: Detected 4515.104 MHz processor
[    0.000027][    T0] last_pfn = 0x180000 max_arch_pfn = 0x400000000
[    0.000077][    T0] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT
[    0.000086][    T0] last_pfn = 0x7fedc max_arch_pfn = 0x400000000
[    0.003468][    T0] check: Scanning 1 areas for low memory corruption
[    0.003480][    T0] Kernel/User page tables isolation: force enabled on command line.
[    0.003484][    T0] Using GB pages for direct mapping
[    0.003890][    T0] Secure boot could not be determined
[    0.003892][    T0] RAMDISK: [mem 0x37157000-0x378a2fff]
[    0.003902][    T0] ACPI: Early table checksum verification disabled
[    0.003904][    T0] ACPI: RSDP 0x000000007FBFA014 000024 (v02 BOCHS )
[    0.003907][    T0] ACPI: XSDT 0x000000007FBF90E8 00004C (v01 BOCHS  BXPCFACP 00000001      01000013)
[    0.003911][    T0] ACPI: FACP 0x000000007FBF6000 0000F4 (v03 BOCHS  BXPCFACP 00000001 BXPC 00000001)
[    0.003915][    T0] ACPI: DSDT 0x000000007FBF7000 001FC9 (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
[    0.003918][    T0] ACPI: FACS 0x000000007FBFD000 000040
[    0.003920][    T0] ACPI: APIC 0x000000007FBF5000 000090 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
[    0.003923][    T0] ACPI: HPET 0x000000007FBF4000 000038 (v01 BOCHS  BXPCHPET 00000001 BXPC 00000001)
[    0.003925][    T0] ACPI: MCFG 0x000000007FBF3000 00003C (v01 BOCHS  BXPCMCFG 00000001 BXPC 00000001)
[    0.003927][    T0] ACPI: BGRT 0x000000007E7D0000 000038 (v01 INTEL  EDK2     00000002      01000013)
[    0.003954][    T0] Zone ranges:
[    0.003955][    T0]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.003956][    T0]   DMA32    [mem 0x0000000001000000-0x00000000ffffffff]
[    0.003958][    T0]   Normal   [mem 0x0000000100000000-0x000000017fffffff]
[    0.003959][    T0] Movable zone start for each node
[    0.003960][    T0] Early memory node ranges
[    0.003961][    T0]   node   0: [mem 0x0000000000001000-0x000000000009ffff]
[    0.003962][    T0]   node   0: [mem 0x0000000000100000-0x00000000007fffff]
[    0.003963][    T0]   node   0: [mem 0x0000000000808000-0x000000000080ffff]
[    0.003964][    T0]   node   0: [mem 0x0000000000900000-0x000000007e7cffff]
[    0.003965][    T0]   node   0: [mem 0x000000007e7d1000-0x000000007ea6dfff]
[    0.003965][    T0]   node   0: [mem 0x000000007eb1b000-0x000000007fb9afff]
[    0.003966][    T0]   node   0: [mem 0x000000007fbff000-0x000000007fedbfff]
[    0.003967][    T0]   node   0: [mem 0x0000000100000000-0x000000017fffffff]
[    0.003984][    T0] Zeroed struct page in unavailable ranges: 911 pages
[    0.003985][    T0] Initmem setup node 0 [mem 0x0000000000001000-0x000000017fffffff]
[    0.021164][    T0] ACPI: PM-Timer IO Port: 0x608
[    0.021174][    T0] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[    0.021207][    T0] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[    0.021209][    T0] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.021211][    T0] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[    0.021212][    T0] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.021214][    T0] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[    0.021215][    T0] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[    0.021219][    T0] Using ACPI (MADT) for SMP configuration information
[    0.021221][    T0] ACPI: HPET id: 0x8086a201 base: 0xfed00000
[    0.021228][    T0] smpboot: Allowing 4 CPUs, 0 hotplug CPUs
[    0.021256][    T0] [mem 0x90000000-0xffbfffff] available for PCI devices
[    0.021258][    T0] Booting paravirtualized kernel on KVM
[    0.021260][    T0] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.110659][    T0] random: get_random_bytes called from start_kernel+0xa5/0x46d with crng_init=0
[    0.110668][    T0] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:4 nr_node_ids:1
[    0.111006][    T0] percpu: Embedded 41 pages/cpu @(____ptrval____) s129624 r8192 d30120 u524288
[    0.111036][    T0] KVM setup async PF for cpu 0
[    0.111042][    T0] kvm-stealtime: cpu 0, msr 17ba14e00
[    0.111048][    T0] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes)
[    0.111051][    T0] Built 1 zonelists, mobility grouping on.  Total pages: 1029479
[    0.111054][    T0] Kernel command line: BOOT_IMAGE=/vmlinuz-linux-test2 root=UUID=9c04c835-60ce-4acf-973d-4a47ac59e769 rw console=ttyS0,115200n8 stack_guard_gap=512 page_poison=1 slub_debug=FZP pti=on spectr
e_v2=on spectre_v2_user=on spec_store_bypass_disable=on
[    0.111762][    T0] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
[    0.112083][    T0] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.740803][    T0] Memory: 3993788K/4190660K available (10242K kernel code, 514K rwdata, 1856K rodata, 960K init, 1128K bss, 196872K reserved, 0K cma-reserved)
[    0.740813][    T0] random: get_random_u64 called from __kmem_cache_create+0x3d/0x4f0 with crng_init=0
[    0.741040][    T0] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.741042][    T0] Kernel/User page tables isolation: enabled
[    0.741151][    T0] rcu: Hierarchical RCU implementation.
[    0.741152][    T0] rcu:     RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=4.
[    0.741154][    T0] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[    0.741155][    T0] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[    0.741171][    T0] NR_IRQS: 4352, nr_irqs: 456, preallocated irqs: 16
[    0.741539][    T0] Console: colour dummy device 80x25
[    0.935721][    T0] printk: console [ttyS0] enabled
[    0.936785][    T0] ACPI: Core revision 20190215
[    0.938098][    T0] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
[    0.940492][    T0] APIC: Switch to symmetric I/O mode setup
[    0.941858][    T0] KVM setup pv IPIs
[    0.943800][    T0] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.945374][    T0] tsc: Marking TSC unstable due to TSCs unsynchronized
[    0.946949][    T0] Calibrating delay loop (skipped) preset value.. 9030.20 BogoMIPS (lpj=45151040)
[    0.948956][    T0] pid_max: default: 32768 minimum: 301
[    0.963016][    T0] LSM: Security Framework initializing
[    0.964218][    T0] Yama: becoming mindful.
[    0.965231][    T0] AppArmor: AppArmor initialized
[    0.966312][    T0] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.966944][    T0] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.969091][    T0] Last level iTLB entries: 4KB 512, 2MB 1024, 4MB 512
[    0.970578][    T0] Last level dTLB entries: 4KB 512, 2MB 255, 4MB 127, 1GB 0
[    0.972098][    T0] Spectre V2 : Mitigation: Full AMD retpoline
[    0.973439][    T0] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[    0.975568][    T0] Spectre V2 : mitigation: Enabling always-on Indirect Branch Prediction Barrier
[    0.976944][    T0] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled
[    0.979106][    T0] Freeing SMP alternatives memory: 24K
[    0.981254][    T1] smpboot: CPU0: AMD FX(tm)-9590 Eight-Core Processor (family: 0x15, model: 0x2, stepping: 0x0)
[    0.983856][    T1] Performance Events: Fam15h core perfctr, AMD PMU driver.
[    0.985498][    T1] ... version:                0
[    0.986631][    T1] ... bit width:              48
[    0.986939][    T1] ... generic registers:      6
[    0.986939][    T1] ... value mask:             0000ffffffffffff
[    0.986939][    T1] ... max period:             00007fffffffffff
[    0.986943][    T1] ... fixed-purpose events:   0
[    0.987935][    T1] ... event mask:             000000000000003f
[    0.989336][    T1] rcu: Hierarchical SRCU implementation.
[    0.990829][    T1] smp: Bringing up secondary CPUs ...
[    0.992239][    T1] x86: Booting SMP configuration:
[    0.993351][    T1] .... node  #0, CPUs:      #1
[    0.205447][    T0] kvm-clock: cpu 1, msr 2ccf7041, secondary cpu clock
[    0.994852][   T14] KVM setup async PF for cpu 1
[    0.994852][   T14] kvm-stealtime: cpu 1, msr 17ba94e00
[    0.997088][    T1]  #2
[    0.205447][    T0] kvm-clock: cpu 2, msr 2ccf7081, secondary cpu clock
[    0.997892][   T19] KVM setup async PF for cpu 2
[    0.999285][   T19] kvm-stealtime: cpu 2, msr 17bb14e00
[    1.000406][    T1]  #3
[    0.205447][    T0] kvm-clock: cpu 3, msr 2ccf70c1, secondary cpu clock
[    1.000406][   T24] KVM setup async PF for cpu 3
[    1.000406][   T24] kvm-stealtime: cpu 3, msr 17bb94e00
[    1.006947][    T1] smp: Brought up 1 node, 4 CPUs
[    1.008089][    T1] smpboot: Max logical packages: 4
[    1.009249][    T1] smpboot: Total of 4 processors activated (36120.83 BogoMIPS)
[    1.011441][    T1] devtmpfs: initialized
[    1.011441][    T1] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    1.011441][    T1] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    1.017103][    T1] xor: automatically using best checksumming function   avx
[    1.019114][    T1] NET: Registered protocol family 16
[    1.020415][    T1] audit: initializing netlink subsys (disabled)
[    1.021830][   T34] audit: type=2000 audit(1553862765.564:1): state=initialized audit_enabled=0 res=1
[    1.021830][    T1] KVM setup pv remote TLB flush
[    1.021830][    T1] ACPI: bus type PCI registered
[    1.021830][    T1] PCI: MMCONFIG for domain 0000 [bus 00-ff] at [mem 0x80000000-0x8fffffff] (base 0x80000000)
[    1.026963][    T1] PCI: MMCONFIG at [mem 0x80000000-0x8fffffff] reserved in E820
[    1.028553][    T1] PCI: Using configuration type 1 for base access
[    1.043902][    T1] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    1.043902][    T1] cryptd: max_cpu_qlen set to 1000
[    1.047083][    T1] raid6: using algorithm sse2x4 gen() 0 MB/s
[    1.048201][    T1] raid6: .... xor() 0 MB/s, rmw enabled
[    1.049376][    T1] raid6: using ssse3x2 recovery algorithm
[    1.050803][    T1] ACPI: Added _OSI(Module Device)
[    1.052030][    T1] ACPI: Added _OSI(Processor Device)
[    1.053108][    T1] ACPI: Added _OSI(3.0 _SCP Extensions)
[    1.054390][    T1] ACPI: Added _OSI(Processor Aggregator Device)
[    1.055920][    T1] ACPI: Added _OSI(Linux-Dell-Video)
[    1.056946][    T1] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    1.058440][    T1] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[    1.069935][    T1] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    1.073425][    T1] ACPI: Interpreter enabled
[    1.074480][    T1] ACPI: (supports S0 S5)
[    1.075513][    T1] ACPI: Using IOAPIC for interrupt routing
[    1.077098][    T1] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    1.079545][    T1] ACPI: Enabled 1 GPEs in block 00 to 3F
[    1.090567][    T1] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    1.092055][    T1] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI]
[    1.094474][    T1] acpi PNP0A08:00: _OSC: platform does not support [LTR]
[    1.096344][    T1] acpi PNP0A08:00: _OSC: OS now controls [PME AER PCIeCapability]
[    1.097052][    T1] PCI host bridge to bus 0000:00
[    1.098135][    T1] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    1.099750][    T1] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
[    1.101524][    T1] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[    1.103482][    T1] pci_bus 0000:00: root bus resource [mem 0x90000000-0xfebfffff window]
[    1.105180][    T1] pci_bus 0000:00: root bus resource [mem 0x800000000-0xfffffffff window]
[    1.106746][    T1] pci_bus 0000:00: root bus resource [bus 00-ff]
[    1.119494][    T1] pci 0000:00:01.0: BAR 0: assigned to efifb
[    1.176675][    T1] pci 0000:00:1f.0: quirk: [io  0x0600-0x067f] claimed by ICH6 ACPI/GPIO/TCO
[    1.192653][    T1] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
[    1.194404][    T1] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[    1.196211][    T1] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[    1.197237][    T1] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
[    1.198921][    T1] ACPI: PCI Interrupt Link [LNKE] (IRQs 5 *10 11)
[    1.200535][    T1] ACPI: PCI Interrupt Link [LNKF] (IRQs 5 *10 11)
[    1.202193][    T1] ACPI: PCI Interrupt Link [LNKG] (IRQs 5 10 *11)
[    1.203854][    T1] ACPI: PCI Interrupt Link [LNKH] (IRQs 5 10 *11)
[    1.205333][    T1] ACPI: PCI Interrupt Link [GSIA] (IRQs *16)
[    1.206798][    T1] ACPI: PCI Interrupt Link [GSIB] (IRQs *17)
[    1.206987][    T1] ACPI: PCI Interrupt Link [GSIC] (IRQs *18)
[    1.208332][    T1] ACPI: PCI Interrupt Link [GSID] (IRQs *19)
[    1.209814][    T1] ACPI: PCI Interrupt Link [GSIE] (IRQs *20)
[    1.211325][    T1] ACPI: PCI Interrupt Link [GSIF] (IRQs *21)
[    1.212832][    T1] ACPI: PCI Interrupt Link [GSIG] (IRQs *22)
[    1.214351][    T1] ACPI: PCI Interrupt Link [GSIH] (IRQs *23)
[    1.216803][    T1] pci 0000:00:01.0: vgaarb: setting as boot VGA device
[    1.216803][    T1] pci 0000:00:01.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none
[    1.216956][    T1] pci 0000:00:01.0: vgaarb: bridge control possible
[    1.218545][    T1] vgaarb: loaded
[    1.219671][    T1] SCSI subsystem initialized
[    1.220864][    T1] ACPI: bus type USB registered
[    1.222132][    T1] usbcore: registered new interface driver usbfs
[    1.223720][    T1] usbcore: registered new interface driver hub
[    1.225273][    T1] usbcore: registered new device driver usb
[    1.226775][    T1] pps_core: LinuxPPS API ver. 1 registered
[    1.226944][    T1] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    1.229148][    T1] PTP clock support registered
[    1.230475][    T1] Registered efivars operations
[    1.231674][    T1] Advanced Linux Sound Architecture Driver Initialized.
[    1.231674][    T1] PCI: Using ACPI for IRQ routing
[    1.289794][    T1] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[    1.291165][    T1] hpet0: 3 comparators, 64-bit 100.000000 MHz counter
[    1.295956][    T1] clocksource: Switched to clocksource kvm-clock
[    1.295956][    T1] AppArmor: AppArmor Filesystem Enabled
[    1.295956][    T1] pnp: PnP ACPI init
[    1.295956][    T1] pnp: PnP ACPI: found 4 devices
[    1.302979][    T1] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[    1.305047][    T1] pci 0000:00:01.0: can't claim BAR 6 [mem 0xffff0000-0xffffffff pref]: no compatible bridge window
[    1.307280][    T1] pci 0000:00:04.0: can't claim BAR 6 [mem 0xfffc0000-0xffffffff pref]: no compatible bridge window
[    1.309508][    T1] pci 0000:00:04.0: BAR 6: assigned [mem 0x90840000-0x9087ffff pref]
[    1.311311][    T1] pci 0000:00:01.0: BAR 6: assigned [mem 0x90810000-0x9081ffff pref]
[    1.313253][    T1] NET: Registered protocol family 2
[    1.314524][    T1] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes)
[    1.316336][    T1] TCP established hash table entries: 32768 (order: 6, 262144 bytes)
[    1.318146][    T1] TCP bind hash table entries: 32768 (order: 7, 524288 bytes)
[    1.320021][    T1] TCP: Hash tables configured (established 32768 bind 32768)
[    1.321795][    T1] UDP hash table entries: 2048 (order: 4, 65536 bytes)
[    1.323416][    T1] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes)
[    1.325156][    T1] NET: Registered protocol family 1
[    1.326395][    T1] pci 0000:00:01.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[    1.330045][    T1] PCI Interrupt Link [GSIA] enabled at IRQ 16
[    1.334552][    T1] PCI Interrupt Link [GSIB] enabled at IRQ 17
[    1.339024][    T1] PCI Interrupt Link [GSIC] enabled at IRQ 18
[    1.343542][    T1] PCI Interrupt Link [GSID] enabled at IRQ 19
[    1.346899][    T1] Unpacking initramfs...
[    1.432913][    T1] Freeing initrd memory: 7472K
[    1.434082][    T1] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[    1.435797][    T1] software IO TLB: mapped [mem 0x77f1e000-0x7bf1e000] (64MB)
[    1.437560][    T1] check: Scanning for low memory corruption every 60 seconds
[    1.460319][    T1] Initialise system trusted keyrings
[    1.461696][    T1] workingset: timestamp_bits=46 max_order=20 bucket_order=0
[    1.518477][    T1] Key type asymmetric registered
[    1.519532][    T1] Asymmetric key parser 'x509' registered
[    1.520972][    T1] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[    1.522956][    T1] io scheduler bfq registered
[    1.524490][    T1] hv_vmbus: registering driver hv_pci
[    1.525614][    T1] hv_vmbus: registering driver hyperv_fb
[    1.526792][    T1] efifb: probing for efifb
[    1.527862][    T1] efifb: framebuffer at 0x90000000, using 1920k, total 1920k
[    1.529478][    T1] efifb: mode is 800x600x32, linelength=3200, pages=1
[    1.530942][    T1] efifb: scrolling: redraw
[    1.531996][    T1] efifb: Truecolor: size=8:8:8:8, shift=24:16:8:0
[    1.537144][    T1] Console: switching to colour frame buffer device 100x37
[    1.541219][    T1] fb0: EFI VGA frame buffer device
[    1.542408][    T1] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[    1.544343][    T1] ACPI: Power Button [PWRF]
[    1.546957][    T1] PCI Interrupt Link [GSIF] enabled at IRQ 21
[    1.550540][    T1] PCI Interrupt Link [GSIG] enabled at IRQ 22
[    1.556323][    T1] PCI Interrupt Link [GSIH] enabled at IRQ 23
[    1.559762][    T1] PCI Interrupt Link [GSIE] enabled at IRQ 20
[    1.561923][    T1] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    1.591484][    T1] 00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[    1.594903][  T802] random: fast init done
[    1.595194][    T1] [drm] pci: virtio-vga detected at 0000:00:01.0
[    1.596091][  T802] random: crng init done
[    1.597492][    T1] fb0: switching to virtiodrmfb from EFI VGA
[    1.599632][  T802] random: 715 get_random_xx warning(s) missed due to ratelimiting
[    1.599683][    T1] Console: switching to colour dummy device 80x25
[    1.603251][    T1] virtio-pci 0000:00:01.0: vgaarb: deactivate vga console
[    1.604886][    T1] [drm] virgl 3d acceleration not supported by host
[    1.607225][    T1] [TTM] Zone  kernel: Available graphics memory: 2015852 kiB
[    1.608923][    T1] [TTM] Initializing pool allocator
[    1.610014][    T1] [TTM] Initializing DMA pool allocator
[    1.611281][    T1] [drm] number of scanouts: 1
[    1.612247][    T1] [drm] number of cap sets: 0
[    1.613562][    T1] [drm] Initialized virtio_gpu 0.1.0 0 for virtio0 on minor 0
[    1.639282][    T1] Console: switching to colour frame buffer device 239x71
[    1.653449][    T1] virtio_gpu virtio0: fb0: DRM emulated frame buffer device
[    1.667567][    T1] loop: module loaded
[    1.669983][    T1] scsi host0: Virtio SCSI HBA
[    1.677105][    T1] hv_vmbus: registering driver hv_storvsc
[    1.677374][   T31] scsi 0:0:0:0: Direct-Access     QEMU     QEMU HARDDISK    2.5+ PQ: 0 ANSI: 5
[    1.682109][    T1] hv_vmbus: registering driver hv_netvsc
[    1.684312][    T1] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.686986][    T1] ehci-pci: EHCI PCI platform driver
[    1.690599][    T1] ehci-pci 0000:00:1d.7: EHCI Host Controller
[    1.692327][    T1] ehci-pci 0000:00:1d.7: new USB bus registered, assigned bus number 1
[    1.694963][    T1] ehci-pci 0000:00:1d.7: irq 19, io mem 0x90801000
[    1.706894][    C3] sd 0:0:0:0: Power-on or device reset occurred
[    1.708559][   T31] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    1.710158][  T799] sd 0:0:0:0: [sda] 83886080 512-byte logical blocks: (42.9 GB/40.0 GiB)
[    1.712103][  T799] sd 0:0:0:0: [sda] Write Protect is off
[    1.713355][  T799] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.715452][  T799] sd 0:0:0:0: [sda] Optimal transfer size 0 bytes < PAGE_SIZE (4096 bytes)
[    1.720368][  T799]  sda: sda1 sda2 sda3
[    1.721871][  T799] sd 0:0:0:0: [sda] Attached SCSI disk
[    1.727039][    T1] ehci-pci 0000:00:1d.7: USB 2.0 started, EHCI 1.00
[    1.728553][    T1] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.01
[    1.730495][    T1] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.732141][    T1] usb usb1: Product: EHCI Host Controller
[    1.733304][    T1] usb usb1: Manufacturer: Linux 5.1.0-rc2-ARCH-test2 ehci_hcd
[    1.734817][    T1] usb usb1: SerialNumber: 0000:00:1d.7
[    1.736158][    T1] hub 1-0:1.0: USB hub found
[    1.737186][    T1] hub 1-0:1.0: 6 ports detected
[    1.738526][    T1] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    1.740025][    T1] ohci-pci: OHCI PCI platform driver
[    1.741224][    T1] uhci_hcd: USB Universal Host Controller Interface driver
[    1.744888][    T1] uhci_hcd 0000:00:1d.0: UHCI Host Controller
[    1.746360][    T1] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2
[    1.748282][    T1] uhci_hcd 0000:00:1d.0: irq 16, io base 0x000060e0
[    1.749789][    T1] usb usb2: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 5.01
[    1.751760][    T1] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.753488][    T1] usb usb2: Product: UHCI Host Controller
[    1.754684][    T1] usb usb2: Manufacturer: Linux 5.1.0-rc2-ARCH-test2 uhci_hcd
[    1.756304][    T1] usb usb2: SerialNumber: 0000:00:1d.0
[    1.757741][    T1] hub 2-0:1.0: USB hub found
[    1.758739][    T1] hub 2-0:1.0: 2 ports detected
[    1.761783][    T1] uhci_hcd 0000:00:1d.1: UHCI Host Controller
[    1.763221][    T1] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3
[    1.765224][    T1] uhci_hcd 0000:00:1d.1: irq 17, io base 0x000060c0
[    1.766993][    T1] usb usb3: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 5.01
[    1.769373][    T1] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.771396][    T1] usb usb3: Product: UHCI Host Controller
[    1.772815][    T1] usb usb3: Manufacturer: Linux 5.1.0-rc2-ARCH-test2 uhci_hcd
[    1.774705][    T1] usb usb3: SerialNumber: 0000:00:1d.1
[    1.776204][    T1] hub 3-0:1.0: USB hub found
[    1.777347][    T1] hub 3-0:1.0: 2 ports detected
[    1.780691][    T1] uhci_hcd 0000:00:1d.2: UHCI Host Controller
[    1.782216][    T1] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4
[    1.784035][    T1] uhci_hcd 0000:00:1d.2: irq 18, io base 0x000060a0
[    1.785520][    T1] usb usb4: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 5.01
[    1.787502][    T1] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.789306][    T1] usb usb4: Product: UHCI Host Controller
[    1.790572][    T1] usb usb4: Manufacturer: Linux 5.1.0-rc2-ARCH-test2 uhci_hcd
[    1.792204][    T1] usb usb4: SerialNumber: 0000:00:1d.2
[    1.793486][    T1] hub 4-0:1.0: USB hub found
[    1.794507][    T1] hub 4-0:1.0: 2 ports detected
[    1.795864][    T1] usbcore: registered new interface driver usb-storage
[    1.797457][    T1] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[    1.800204][    T1] serio: i8042 KBD port at 0x60,0x64 irq 1
[    1.801465][    T1] serio: i8042 AUX port at 0x60,0x64 irq 12
[    1.802769][    T1] hv_vmbus: registering driver hyperv_keyboard
[    1.804135][    T1] mousedev: PS/2 mouse device common for all mice
[    1.806248][  T320] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[    1.807219][    T1] rtc_cmos 00:00: RTC can wake from S4
[    1.811210][    T1] rtc_cmos 00:00: registered as rtc0
[    1.813173][    T1] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram, hpet irqs
[    1.817914][    T1] i801_smbus 0000:00:1f.3: SMBus using PCI interrupt
[    1.819572][    T1] hidraw: raw HID events driver (C) Jiri Kosina
[    1.821063][    T1] hv_vmbus: registering driver hid_hyperv
[    1.822432][    T1] usbcore: registered new interface driver usbhid
[    1.823815][    T1] usbhid: USB HID core driver
[    1.824817][    T1] hv_utils: Registering HyperV Utility Driver
[    1.826225][    T1] hv_vmbus: registering driver hv_utils
[    1.827705][    T1] hv_vmbus: registering driver hv_balloon
[    1.829534][    T1] Initializing XFRM netlink socket
[    1.831013][    T1] NET: Registered protocol family 10
[    1.832693][    T1] Segment Routing with IPv6
[    1.833713][    T1] NET: Registered protocol family 17
[    1.834830][    T1] NET: Registered protocol family 15
[    1.835983][    T1] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[    1.839371][    T1] AVX version of gcm_enc/dec engaged.
[    1.840504][    T1] AES CTR mode by8 optimization enabled
[    1.862135][    T1] sched_clock: Marking stable (1666674337, 195447403)->(1888999479, -26877739)
[    1.864868][    T1] Loading compiled-in X.509 certificates
[    1.870537][    T1] Loaded X.509 cert 'Modules: 6658372c83ac517747ebb777f75c50d93800a9b7'
[    1.873556][    T1] Btrfs loaded, crc32c=crc32c-intel
[    1.874888][    T1] AppArmor: AppArmor sha1 policy hashing enabled
[    1.876781][    T1] ALSA device list:
[    1.877811][    T1]   No soundcards found.
[    1.879649][    T1] Freeing unused kernel image memory: 960K
[    1.927138][    T1] Write protecting the kernel read-only data: 14336k
[    1.929373][    T1] Freeing unused kernel image memory: 2036K
[    1.930858][    T1] Freeing unused kernel image memory: 192K
[    1.932450][    T1] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[    1.934098][    T1] x86/mm: Checking user space page tables
[    1.935462][    T1] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[    1.937041][    T1] Run /init as init process
:: running early hook [udev]
Warning: /lib/modules/5.1.0-rc2-ARCH-test2/modules.devname not found - ignoring
Starting version 241.7-2-arch
:: running hook [udev]
:: Triggering uevents...
[    2.117022][  T915] usb 1-1: new high-speed USB device number 2 using ehci-pci
[    2.206261][ T1167] BTRFS: device label root devid 1 transid 503 /dev/sda3
[    2.318833][  T915] usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00
[    2.321017][  T915] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=5
[    2.322948][  T915] usb 1-1: Product: QEMU USB Tablet
[    2.324118][  T915] usb 1-1: Manufacturer: QEMU
[    2.325256][  T915] usb 1-1: SerialNumber: 42
[    2.329864][  T915] input: QEMU QEMU USB Tablet as /devices/pci0000:00/0000:00:1d.7/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input4
[    2.332760][  T915] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:1d.7-1/input0
:: performing fsck on '/dev/sda3'
:: mounting '/dev/sda3' on real root
[    2.400759][ T1436] BTRFS info (device sda3): using free space tree
[    2.402235][ T1436] BTRFS info (device sda3): has skinny extents
[    2.438597][  T320] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input3
:: running cleanup hook [udev]
[    3.096177][    T1] systemd[1]: Failed to find module 'autofs4'
[    3.113775][    T1] systemd[1]: systemd 241.7-2-arch running in system mode. (+PAM +AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS
+KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid)
[    3.118856][    T1] systemd[1]: Detected virtualization kvm.
[    3.120073][    T1] systemd[1]: Detected architecture x86-64.

Welcome to Arch Linux!

[    3.136227][    T1] systemd[1]: Set hostname to <test>.
[    3.608105][    T1] systemd[1]: Listening on Journal Audit Socket.
[  OK  ] Listening on Journal Audit Socket.
[    3.611457][    T1] systemd[1]: Listening on Device-mapper event daemon FIFOs.
[  OK  ] Listening on Device-mapper event daemon FIFOs.
[    3.615249][    T1] systemd[1]: Listening on LVM2 poll daemon socket.
[  OK  ] Listening on LVM2 poll daemon socket.
[    3.618199][    T1] systemd[1]: Listening on Journal Socket.
[  OK  ] Listening on Journal Socket.
[    3.620667][    T1] systemd[1]: Condition check resulted in Kernel Debug File System being skipped.
[    3.622770][    T1] systemd[1]: Reached target Remote File Systems.
[  OK  ] Reached target Remote File Systems.
[  OK  ] Started Dispatch Password …ts to Console Directory Watch.
[  OK  ] Listening on Process Core Dump Socket.
         Starting Remount Root and Kernel File Systems...
[  OK  ] Listening on Journal Socket (/dev/log).
         Starting Journal Service...
[  OK  ] Created slice system-getty.slice.
         Starting Apply Kernel Variables...
[  OK  ] Listening on Network Service Netlink Socket.
[  OK  ] Created slice User and Session Slice.
[  OK  ] Reached target Slices.
[  OK  ] Listening on udev Control Socket.
[  OK  ] Created slice system-serial\x2dgetty.slice.
[  OK  ] Listening on LVM2 metadata daemon socket.
         Starting Monitoring of LVM…meventd or progress polling...
[  OK  ] Listening on initctl Compatibility Named Pipe.
         Mounting POSIX Message Queue File System...
[  OK  ] Started Forward Password R…uests to Wall Directory Watch.
[  OK  ] Reached target Local Encrypted Volumes.
         Mounting Huge Pages File System...
[  OK  ] Reached target Paths.
[    3.745118][ T1491] BTRFS info (device sda3): use zstd compression, level 3
[    3.747055][ T1491] BTRFS info (device sda3): enabling auto defrag
[    3.748464][ T1491] BTRFS info (device sda3): using free space tree
[  OK  ] Listening on udev Kernel Socket.
         Starting udev Coldplug all Devices...
[  OK  ] Started Remount Root and Kernel File Systems.
[  OK  ] Started Apply Kernel Variables.
[  OK  ] Mounted POSIX Message Queue File System.
[  OK  ] Mounted Huge Pages File System.
[  OK  ] Started LVM2 metadata daemon.
         Starting Load/Save Random Seed...
         Starting Create Static Device Nodes in /dev...
[  OK  ] Started Load/Save Random Seed.
[  OK  ] Started Create Static Device Nodes in /dev.
         Starting udev Kernel Device Manager...
[  OK  ] Started udev Coldplug all Devices.
[  OK  ] Started Journal Service.
[    4.043735][   T34] audit: type=1130 audit(1553862768.584:2): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? ad
dr=? terminal=? res=success'
         Starting Flush Journal to Persistent Storage...
[    4.097598][ T1489] systemd-journald[1489]: Received request to flush runtime journal from PID 1
[  OK  ] Started udev Kernel Device Manager.
[    4.446329][   T34] audit: type=1130 audit(1553862768.984:3): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-udevd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=
? terminal=? res=success'
         Starting Network Service...
[  OK  ] Found device /dev/ttyS0.
[    4.596099][ T1913] virtio_net virtio3 enp0s4: renamed from eth0
[  OK  ] Started Flush Journal to Persistent Storage.
[    4.675012][   T34] audit: type=1130 audit(1553862769.214:4): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-journal-flush comm="systemd" exe="/usr/lib/systemd/systemd" hostname
=? addr=? terminal=? res=success'
[  OK  ] Found device QEMU_HARDDISK 2.
[    4.911481][ T1907] A link change request failed with some changes committed already. Interface enp0s4 may have been left with an inconsistent configuration, please check.
[  OK  ] Found device QEMU_HARDDISK 1.
[  OK  ] Started Network Service.
[    4.925070][   T34] audit: type=1130 audit(1553862769.464:5): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? ad
dr=? terminal=? res=success'
[  OK  ] Reached target Network.
         Activating swap /dev/disk/…8ab3-414f-b6ac-91e0e904eb08...
[    5.045388][ T1939] Adding 4194300k swap on /dev/sda2.  Priority:-2 extents:1 across:4194300k
[  OK  ] Activated swap /dev/disk/b…8-8ab3-414f-b6ac-91e0e904eb08.
[  OK  ] Reached target Swap.
         Mounting Temporary Directory (/tmp)...
[  OK  ] Mounted Temporary Directory (/tmp).
[  OK  ] Started Monitoring of LVM2… dmeventd or progress polling.
[    5.181607][   T34] audit: type=1130 audit(1553862769.724:6): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=lvm2-monitor comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=?
 terminal=? res=success'
[  OK  ] Reached target Local File Systems (Pre).
         Mounting /boot...
[    5.195003][ T1941] FAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[  OK  ] Mounted /boot.
[  OK  ] Reached target Local File Systems.
         Starting Create Volatile Files and Directories...
[  OK  ] Started Create Volatile Files and Directories.
[    5.257618][   T34] audit: type=1130 audit(1553862769.804:7): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostnam
e=? addr=? terminal=? res=success'
         Starting Update UTMP about System Boot/Shutdown...
[    5.268333][   T34] audit: type=1127 audit(1553862769.814:8): pid=1943 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg=' comm="systemd-update-utmp" exe="/usr/lib/systemd/systemd-update-utmp" hostnam
e=? addr=? terminal=? res=success'
[  OK  ] Started Update UTMP about System Boot/Shutdown.
[    5.275548][   T34] audit: type=1130 audit(1553862769.814:9): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-update-utmp comm="systemd" exe="/usr/lib/systemd/systemd" hostname=?
 addr=? terminal=? res=success'
[  OK  ] Reached target System Initialization.
[  OK  ] Started Daily verification of password and group files.
[  OK  ] Started Daily Cleanup of Temporary Directories.
[  OK  ] Started Daily rotation of log files.
[  OK  ] Started Daily man-db regeneration.
[  OK  ] Reached target Timers.
[  OK  ] Listening on D-Bus System Message Bus Socket.
[  OK  ] Reached target Sockets.
[  OK  ] Reached target Basic System.
         Starting Permit User Sessions...
[  OK  ] Started D-Bus System Message Bus.
[    5.304923][   T34] audit: type=1130 audit(1553862769.844:10): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=dbus comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? termin
al=? res=success'
         Starting Login Service...
[  OK  ] Started OpenSSH Daemon.
[  OK  ] Started Permit User Sessions.
[  OK  ] Started Getty on tty1.
[  OK  ] Started Serial Getty on ttyS0.
[  OK  ] Reached target Login Prompts.
[  OK  ] Started Login Service.
[  OK  ] Reached target Multi-User System.
[  OK  ] Reached target Graphical Interface.

Arch Linux 5.1.0-rc2-ARCH-test2 (ttyS0)

test login: [   11.281974][   T34] kauditd_printk_skb: 5 callbacks suppressed
[   11.281975][   T34] audit: type=1006 audit(1553862775.824:16): pid=1965 uid=0 subj==unconfined old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=1 res=1
[   11.315508][   T34] audit: type=1130 audit(1553862775.854:17): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=user-runtime-dir@0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=?
 addr=? terminal=? res=success'
[   11.324377][   T34] audit: type=1006 audit(1553862775.864:18): pid=1968 uid=0 subj==unconfined old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=2 res=1
[   11.418557][   T34] audit: type=1130 audit(1553862775.964:19): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=user@0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? term
inal=? res=success'
[   32.837998][ T1975] bash (1975): drop_caches: 3
[   32.840195][ T1975] bash (1975): drop_caches: 3
[   39.935663][ T1975] bash (1975): drop_caches: 3
[   41.034974][    C0] general protection fault: 0000 [#1] SMP PTI
[   41.036291][    C0] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G                T 5.1.0-rc2-ARCH-test2 #4
[   41.038287][    C0] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015
[   41.040235][    C0] RIP: 0010:bfq_bfqq_expire+0x1f3/0x3d0
[   41.041455][    C0] Code: 01 00 00 00 00 00 00 a8 02 75 3c 41 83 ec 01 41 83 fc 01 76 32 48 0f ba ab 08 01 00 00 03 48 8b 83 c8 00 00 00 48 85 c0 74 07 <c7> 40 40 00 00 00 00 5b 5d 41 5c 41 5d 41 5e c3 e8 e8
42 d3 ff 48
[   41.045818][    C0] RSP: 0018:ffffa1d87ba03ed0 EFLAGS: 00010002
[   41.047207][    C0] RAX: 6b6b6b6b6b6b6b6b RBX: ffffa1d87a2c27c8 RCX: 000000000010000c
[   41.049022][    C0] RDX: 0000000000000046 RSI: 0000000000000000 RDI: ffffa1d87ab13c40
[   41.050907][    C0] RBP: ffffa1d879434e68 R08: 0000000000000000 R09: ffffa1d87a2c2900
[   41.052751][    C0] R10: ffffa1d87a2c27c8 R11: 0000000000000001 R12: 0000000000000000
[   41.054631][    C0] R13: 0000000000000002 R14: ffffa1d879434e00 R15: ffffa1d87ba1b340
[   41.056313][    C0] FS:  0000000000000000(0000) GS:ffffa1d87ba00000(0000) knlGS:0000000000000000
[   41.058442][    C0] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   41.059804][    C0] CR2: 00006ffc44000010 CR3: 00000001774be000 CR4: 00000000000406b0
[   41.061536][    C0] Call Trace:
[   41.062291][    C0]  <IRQ>
[   41.062882][    C0]  bfq_idle_slice_timer+0x5f/0xb0
[   41.063924][    C0]  ? bfq_dispatch_request+0x870/0x870
[   41.065034][    C0]  __hrtimer_run_queues+0xf4/0x1a0
[   41.066091][    C0]  hrtimer_interrupt+0xfe/0x220
[   41.067096][    C0]  smp_apic_timer_interrupt+0x57/0x90
[   41.068209][    C0]  apic_timer_interrupt+0xf/0x20
[   41.069269][    C0]  </IRQ>
[   41.069909][    C0] RIP: 0010:default_idle+0x9/0x20
[   41.070947][    C0] Code: 01 00 00 00 00 ad de 48 89 44 24 20 48 05 00 01 00 00 48 89 44 24 28 eb c5 e8 43 b7 8a ff 90 90 90 65 8b 05 d9 5b c1 6b fb f4 <65> 8b 05 d0 5b c1 6b c3 66 66 2e 0f 1f 84 00 00 00 00
00 0f 1f 40
[   41.075110][    C0] RSP: 0018:ffffffff94a03ee0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
[   41.076855][    C0] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000001
[   41.078619][    C0] RDX: 0000000000005e66 RSI: 0000000000000083 RDI: 0000000000000000
[   41.080255][    C0] RBP: ffffffff94a77a70 R08: 0000000000001400 R09: 0000000000000000
[   41.081898][    C0] R10: 0000000000000000 R11: 000000000000025f R12: ffffffff94a154c0
[   41.083589][    C0] R13: ffffa1d87fff7a00 R14: 000000007bcd65a8 R15: 000000007e797c3e
[   41.085238][    C0]  do_idle+0xd1/0xf0
[   41.086044][    C0]  cpu_startup_entry+0x14/0x20
[   41.087029][    C0]  start_kernel+0x44d/0x46d
[   41.087956][    C0]  secondary_startup_64+0xa4/0xb0
[   41.089076][    C0] Modules linked in:
[   41.089984][    C0] ---[ end trace 0e0bd22bb3439150 ]---
[   41.091187][    C0] RIP: 0010:bfq_bfqq_expire+0x1f3/0x3d0
[   41.092390][    C0] Code: 01 00 00 00 00 00 00 a8 02 75 3c 41 83 ec 01 41 83 fc 01 76 32 48 0f ba ab 08 01 00 00 03 48 8b 83 c8 00 00 00 48 85 c0 74 07 <c7> 40 40 00 00 00 00 5b 5d 41 5c 41 5d 41 5e c3 e8 e8
42 d3 ff 48
[   41.096757][    C0] RSP: 0018:ffffa1d87ba03ed0 EFLAGS: 00010002
[   41.098012][    C0] RAX: 6b6b6b6b6b6b6b6b RBX: ffffa1d87a2c27c8 RCX: 000000000010000c
[   41.099755][    C0] RDX: 0000000000000046 RSI: 0000000000000000 RDI: ffffa1d87ab13c40
[   41.101418][    C0] RBP: ffffa1d879434e68 R08: 0000000000000000 R09: ffffa1d87a2c2900
[   41.103112][    C0] R10: ffffa1d87a2c27c8 R11: 0000000000000001 R12: 0000000000000000
[   41.104841][    C0] R13: 0000000000000002 R14: ffffa1d879434e00 R15: ffffa1d87ba1b340
[   41.106480][    C0] FS:  0000000000000000(0000) GS:ffffa1d87ba00000(0000) knlGS:0000000000000000
[   41.108319][    C0] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   41.109787][    C0] CR2: 00006ffc44000010 CR3: 00000001774be000 CR4: 00000000000406b0
[   41.111502][    C0] Kernel panic - not syncing: Fatal exception in interrupt
[   41.113187][    C0] Kernel Offset: 0x12c00000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)


[-- Attachment #3: bisect-log.txt --]
[-- Type: text/plain, Size: 2825 bytes --]

git bisect start
# bad: [9e98c678c2d6ae3a17cb2de55d17f69dddaa231b] Linux 5.1-rc1
git bisect bad 9e98c678c2d6ae3a17cb2de55d17f69dddaa231b
# good: [1c163f4c7b3f621efff9b28a47abb36f7378d783] Linux 5.0
git bisect good 1c163f4c7b3f621efff9b28a47abb36f7378d783
# good: [e266ca36da7de45b64b05698e98e04b578a88888] Merge tag 'staging-5.1-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/staging
git bisect good e266ca36da7de45b64b05698e98e04b578a88888
# bad: [36011ddc78395b59a8a418c37f20bcc18828f1ef] Merge tag 'gfs2-5.1.fixes' of git://git.kernel.org/pub/scm/linux/kernel/git/gfs2/linux-gfs2
git bisect bad 36011ddc78395b59a8a418c37f20bcc18828f1ef
# good: [4b057e73f28f1df13b77b77a52094238ffdf8abd] Merge tag 'drm-misc-fixes-2019-02-22' of git://anongit.freedesktop.org/drm/drm-misc into drm-next
git bisect good 4b057e73f28f1df13b77b77a52094238ffdf8abd
# good: [610cd4eadec4f97acd25d3108b0e50d1362b3319] Merge branch 'x86-uv-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect good 610cd4eadec4f97acd25d3108b0e50d1362b3319
# good: [cf2e8c544cd3b33e9e403b7b72404c221bf888d1] Merge tag 'mfd-next-5.1' of git://git.kernel.org/pub/scm/linux/kernel/git/lee/mfd
git bisect good cf2e8c544cd3b33e9e403b7b72404c221bf888d1
# bad: [80201fe175cbf7f3e372f53eba0a881a702ad926] Merge tag 'for-5.1/block-20190302' of git://git.kernel.dk/linux-block
git bisect bad 80201fe175cbf7f3e372f53eba0a881a702ad926
# good: [4221b807d1f73c03d22543416d303b60a5d1ef31] Merge tag 'for-5.1/libata-20190301' of git://git.kernel.dk/linux-block
git bisect good 4221b807d1f73c03d22543416d303b60a5d1ef31
# bad: [19d62f6d00972f957c94aba0975c14490cfed385] block: remove bvec_iter_rewind()
git bisect bad 19d62f6d00972f957c94aba0975c14490cfed385
# bad: [e8cf978dffb2c603340d4615eec2e5358c9df06d] bcache: fix indentation issue, remove tabs on a hunk of code
git bisect bad e8cf978dffb2c603340d4615eec2e5358c9df06d
# bad: [058fdecc6de7cdecbf4c59b851e80eb2d6c5295f] block, bfq: fix in-service-queue check for queue merging
git bisect bad 058fdecc6de7cdecbf4c59b851e80eb2d6c5295f
# good: [05c2f5c30b3ca2346a5bb7c74b0c9515d8f4fbd2] block, bfq: split function bfq_better_to_idle
git bisect good 05c2f5c30b3ca2346a5bb7c74b0c9515d8f4fbd2
# bad: [9dee8b3b057e1da26f85f1842f2aaf3bb200fb94] block, bfq: fix queue removal from weights tree
git bisect bad 9dee8b3b057e1da26f85f1842f2aaf3bb200fb94
# good: [530c4cbb3c62f9e42dbf39279fb346f2d2ab4dbb] block, bfq: unconditionally plug I/O in asymmetric scenarios
git bisect good 530c4cbb3c62f9e42dbf39279fb346f2d2ab4dbb
# good: [d87447d84fe194b0e4f5413b5344dc82cc100711] block, bfq: fix sequential rq detection in rate estimation
git bisect good d87447d84fe194b0e4f5413b5344dc82cc100711
# first bad commit: [9dee8b3b057e1da26f85f1842f2aaf3bb200fb94] block, bfq: fix queue removal from weights tree

^ permalink raw reply	[flat|nested] 10+ messages in thread

end of thread, other threads:[~2019-04-09 16:14 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-03-29 13:02 Bisected GFP in bfq_bfqq_expire on v5.1-rc1 Dmitrii Tcvetkov
2019-03-29 14:10 ` Jens Axboe
2019-04-01  7:29   ` Paolo Valente
2019-04-01  8:55     ` Dmitrii Tcvetkov
2019-04-01  9:01       ` Paolo Valente
2019-04-01  9:22         ` Dmitrii Tcvetkov
2019-04-01 10:35           ` Paolo Valente
2019-04-04 19:22             ` Dmitrii Tcvetkov
2019-04-09  9:55               ` Paolo Valente
2019-04-09 16:14                 ` Dmitrii Tcvetkov

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).