Bug 102051 - [KBL][drm:fw_domains_get [i915]] *ERROR* blitter: timed out waiting for forcewake ack request.
Summary: [KBL][drm:fw_domains_get [i915]] *ERROR* blitter: timed out waiting for force...
Status: CLOSED WORKSFORME
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: DRI git
Hardware: x86-64 (AMD64) Linux (All)
: medium normal
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-08-05 16:23 UTC by Matwey V. Kornilov
Modified: 2018-01-04 18:10 UTC (History)
1 user (show)

See Also:
i915 platform: KBL
i915 features: GPU hang

Attachments
Full log (175.94 KB, text/plain)
2017-08-05 16:31 UTC, Matwey V. Kornilov 		no flags Details
View All

Description Matwey V. Kornilov 2017-08-05 16:23:13 UTC 
Hello,

I am running latest drm-tip and see the following in the netconsole when running i915 with live_selftest=1:

Aug  5 19:07:21 omega [    0.000000] microcode: microcode updated early to revision 0x62, date = 2017-04-27
Aug  5 19:07:21 omega [    0.000000] random: get_random_bytes called from start_kernel+0x38/0x49f with crng_init=0
Aug  5 19:07:21 omega [    0.000000] Linux version 4.13.0-rc3-default+ (matwey@omega.local) (gcc version 4.8.5 (SUSE Linux)) #3 SMP PREEMPT Sat Aug 5 18:20:19 MSK 2017
Aug  5 19:07:21 omega [    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.13.0-rc3-default+ root=/dev/mapper/system-root ro showopts crashkernel=1G,high crashkernel=72M,low rd.driver.blacklist=i915 netconsole=6514@192.168.185.131/eth0,514@192.168.185.79/52:54:00:38:7c:1f
Aug  5 19:07:21 omega [    0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
Aug  5 19:07:21 omega [    0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
Aug  5 19:07:21 omega [    0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
Aug  5 19:07:21 omega [    0.000000] x86/fpu: Supporting XSAVE feature 0x008: 'MPX bounds registers'
Aug  5 19:07:21 omega [    0.000000] x86/fpu: Supporting XSAVE feature 0x010: 'MPX CSR'
Aug  5 19:07:21 omega [    0.000000] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
Aug  5 19:07:21 omega [    0.000000] x86/fpu: xstate_offset[3]:  832, xstate_sizes[3]:   64
Aug  5 19:07:21 omega [    0.000000] x86/fpu: xstate_offset[4]:  896, xstate_sizes[4]:   64
Aug  5 19:07:21 omega [    0.000000] x86/fpu: Enabled xstate features 0x1f, context size is 960 bytes, using 'compacted' format.
Aug  5 19:07:21 omega [    0.000000] e820: BIOS-provided physical RAM map:
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x0000000000000000-0x0000000000057fff] usable
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x0000000000058000-0x0000000000058fff] reserved
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x0000000000059000-0x000000000009cfff] usable
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x000000000009d000-0x00000000000fffff] reserved
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000b3046fff] usable
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000b3047000-0x00000000b3047fff] ACPI NVS
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000b3048000-0x00000000b3048fff] reserved
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000b3049000-0x00000000b97c0fff] usable
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000b97c1000-0x00000000bbe0cfff] reserved
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000bbe0d000-0x00000000bbf59fff] ACPI NVS
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000bbf5a000-0x00000000bbf5afff] reserved
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000bbf5b000-0x00000000bbf99fff] ACPI NVS
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000bbf9a000-0x00000000bbffefff] ACPI data
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000bbfff000-0x00000000bbffffff] usable
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000bc000000-0x00000000bf7fffff] reserved
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000e0000000-0x00000000efffffff] reserved
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x00000000fe010000-0x00000000fe010fff] reserved
Aug  5 19:07:21 omega [    0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000013f7fffff] usable
Aug  5 19:07:21 omega [    0.000000] NX (Execute Disable) protection: active
Aug  5 19:07:21 omega [    0.000000] efi: EFI v2.50 by Phoenix Technologies Ltd.
Aug  5 19:07:21 omega [    0.000000] efi:  SMBIOS=0xba260000  SMBIOS 3.0=0xba25d000  ACPI=0xbbffe000  ACPI 2.0=0xbbffe014  ESRT=0xb9eb6000  MEMATTR=0xb7039298 
Aug  5 19:07:21 omega [    0.000000] random: fast init done
Aug  5 19:07:21 omega [    0.000000] SMBIOS 3.0.0 present.
Aug  5 19:07:21 omega [    0.000000] DMI: LENOVO 80WQ/ , BIOS 2WCN29WW 07/12/2017
Aug  5 19:07:21 omega [    0.000000] e820: last_pfn = 0x13f800 max_arch_pfn = 0x400000000
Aug  5 19:07:21 omega [    0.000000] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WC  UC- WT  
Aug  5 19:07:21 omega [    0.000000] e820: last_pfn = 0xbc000 max_arch_pfn = 0x400000000
Aug  5 19:07:21 omega [    0.000000] esrt: Reserving ESRT space from 0x00000000b9eb6000 to 0x00000000b9eb6038.
Aug  5 19:07:21 omega [    0.000000] Scanning 1 areas for low memory corruption
Aug  5 19:07:21 omega [    0.000000] Using GB pages for direct mapping
Aug  5 19:07:21 omega [    0.000000] Secure boot disabled
Aug  5 19:07:21 omega [    0.000000] RAMDISK: [mem 0x3f4d8000-0x3fffafff]
Aug  5 19:07:21 omega [    0.000000] ACPI: Early table checksum verification disabled
Aug  5 19:07:21 omega [    0.000000] ACPI: RSDP 0x00000000BBFFE014 000024 (v02 LENOVO)
Aug  5 19:07:21 omega [    0.000000] ACPI: XSDT 0x00000000BBFB7188 00010C (v01 LENOVO CB-01    00000000  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: FACP 0x00000000BBFF7000 00010C (v05 LENOVO CB-01    00000000  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: DSDT 0x00000000BBFCA000 02966C (v02 LENOVO SKL      00000000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: FACS 0x00000000BBF70000 000040
Aug  5 19:07:21 omega [    0.000000] ACPI: UEFI 0x00000000BBF85000 000042 (v01 LENOVO CB-01    00000002  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFF9000 003791 (v02 LENOVO SaSsdt   00003000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFF8000 0005B6 (v02 LENOVO PerfTune 00001000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: HPET 0x00000000BBFF6000 000038 (v01 LENOVO CB-01    00000001  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: APIC 0x00000000BBFF5000 0000BC (v03 LENOVO CB-01    00000001  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: MCFG 0x00000000BBFF4000 00003C (v01 LENOVO CB-01    00000001  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFC9000 0001BC (v02 LENOVO Sata0Ide 00001000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFC8000 000858 (v02 LENOVO xh_rvp07 00000000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: BOOT 0x00000000BBFC7000 000028 (v01 LENOVO CB-01    00000002  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: BATB 0x00000000BBFC6000 00004A (v02 LENOVO CB-01    00000000  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFC5000 000EDE (v02 LENOVO CpuSsdt  00003000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFC3000 0010B0 (v02 LENOVO UsbCTabl 00001000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: LPIT 0x00000000BBFC2000 000094 (v01 LENOVO CB-01    00000000  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: WSMT 0x00000000BBFC1000 000028 (v01 LENOVO CB-01    00000000  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFC0000 000141 (v02 LENOVO HdaDsp   00000000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFBF000 00029F (v02 LENOVO sensrhub 00000000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFBE000 000346 (v01 LENOVO EInkApp  00000000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFBA000 003002 (v02 LENOVO PtidDevc 00001000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFB9000 000517 (v02 LENOVO TbtTypeC 00000000 INTL 20160527)
Aug  5 19:07:21 omega [    0.000000] ACPI: DBGP 0x00000000BBFB8000 000034 (v01 LENOVO CB-01    00000002  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: DBG2 0x00000000BBFFD000 000054 (v00 LENOVO CB-01    00000002  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: POAT 0x00000000BBFB6000 000055 (v03 LENOVO CB-01    00000000  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: SLIC 0x00000000BBFB5000 000176 (v01 LENOVO CB-01    00000002  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: SSDT 0x00000000BBFB4000 000919 (v02 LENOVO UsbIKTbl 00001000 INTL 20160108)
Aug  5 19:07:21 omega [    0.000000] ACPI: ASF! 0x00000000BBFB3000 0000A0 (v32 LENOVO CB-01    00000001  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: FPDT 0x00000000BBFB2000 000064 (v01 LENOVO CB-01    00000002  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: BGRT 0x00000000BBFB1000 000038 (v01 LENOVO CB-01    00000002  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] ACPI: UEFI 0x00000000BBF6B000 000152 (v01 LENOVO CB-01    00000001  LTP 00000002)
Aug  5 19:07:21 omega [    0.000000] No NUMA configuration found
Aug  5 19:07:21 omega [    0.000000] Faking a node at [mem 0x0000000000000000-0x000000013f7fffff]
Aug  5 19:07:21 omega [    0.000000] NODE_DATA(0) allocated [mem 0x13f7ea000-0x13f7fffff]
Aug  5 19:07:21 omega [    0.000000] Reserving 1024MB of memory at 1760MB for crashkernel (System RAM: 3983MB)
Aug  5 19:07:21 omega [    0.000000] Zone ranges:
Aug  5 19:07:21 omega [    0.000000]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
Aug  5 19:07:21 omega [    0.000000]   DMA32    [mem 0x0000000001000000-0x00000000ffffffff]
Aug  5 19:07:21 omega [    0.000000]   Normal   [mem 0x0000000100000000-0x000000013f7fffff]
Aug  5 19:07:21 omega [    0.000000]   Device   empty
Aug  5 19:07:21 omega [    0.000000] Movable zone start for each node
Aug  5 19:07:21 omega [    0.000000] Early memory node ranges
Aug  5 19:07:21 omega [    0.000000]   node   0: [mem 0x0000000000001000-0x0000000000057fff]
Aug  5 19:07:21 omega [    0.000000]   node   0: [mem 0x0000000000059000-0x000000000009cfff]
Aug  5 19:07:21 omega [    0.000000]   node   0: [mem 0x0000000000100000-0x00000000b3046fff]
Aug  5 19:07:21 omega [    0.000000]   node   0: [mem 0x00000000b3049000-0x00000000b97c0fff]
Aug  5 19:07:21 omega [    0.000000]   node   0: [mem 0x00000000bbfff000-0x00000000bbffffff]
Aug  5 19:07:21 omega [    0.000000]   node   0: [mem 0x0000000100000000-0x000000013f7fffff]
Aug  5 19:07:21 omega [    0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x000000013f7fffff]
Aug  5 19:07:21 omega [    0.000000] Reserving Intel graphics memory at 0x00000000bd800000-0x00000000bf7fffff
Aug  5 19:07:21 omega [    0.000000] ACPI: PM-Timer IO Port: 0x1808
Aug  5 19:07:21 omega [    0.000000] ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
Aug  5 19:07:21 omega [    0.000000] ACPI: LAPIC_NMI (acpi_id[0x02] high edge lint[0x1])
Aug  5 19:07:21 omega [    0.000000] ACPI: LAPIC_NMI (acpi_id[0x03] high edge lint[0x1])
Aug  5 19:07:21 omega [    0.000000] ACPI: LAPIC_NMI (acpi_id[0x04] high edge lint[0x1])
Aug  5 19:07:21 omega [    0.000000] ACPI: LAPIC_NMI (acpi_id[0x05] high edge lint[0x1])
Aug  5 19:07:21 omega [    0.000000] ACPI: LAPIC_NMI (acpi_id[0x06] high edge lint[0x1])
Aug  5 19:07:21 omega [    0.000000] ACPI: LAPIC_NMI (acpi_id[0x07] high edge lint[0x1])
Aug  5 19:07:21 omega [    0.000000] ACPI: LAPIC_NMI (acpi_id[0x08] high edge lint[0x1])
Aug  5 19:07:21 omega [    0.000000] IOAPIC[0]: apic_id 2, version 32, address 0xfec00000, GSI 0-119
Aug  5 19:07:21 omega [    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
Aug  5 19:07:21 omega [    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
Aug  5 19:07:21 omega [    0.000000] Using ACPI (MADT) for SMP configuration information
Aug  5 19:07:21 omega [    0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000
Aug  5 19:07:21 omega [    0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0x00058000-0x00058fff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0x0009d000-0x000fffff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xb3047000-0xb3047fff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xb3048000-0xb3048fff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xb97c1000-0xbbe0cfff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xbbe0d000-0xbbf59fff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xbbf5a000-0xbbf5afff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xbbf5b000-0xbbf99fff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xbbf9a000-0xbbffefff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xbc000000-0xbf7fffff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xbf800000-0xdfffffff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xe0000000-0xefffffff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xf0000000-0xfe00ffff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xfe010000-0xfe010fff]
Aug  5 19:07:21 omega [    0.000000] PM: Registered nosave memory: [mem 0xfe011000-0xffffffff]
Aug  5 19:07:21 omega [    0.000000] e820: [mem 0xbf800000-0xdfffffff] available for PCI devices
Aug  5 19:07:21 omega [    0.000000] Booting paravirtualized kernel on bare hardware
Aug  5 19:07:21 omega [    0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
Aug  5 19:07:21 omega [    0.000000] setup_percpu: NR_CPUS:512 nr_cpumask_bits:512 nr_cpu_ids:4 nr_node_ids:1
Aug  5 19:07:21 omega [    0.000000] percpu: Embedded 39 pages/cpu @ffff966fbf400000 s121496 r8192 d30056 u524288
Aug  5 19:07:21 omega [    0.000000] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 1003783
Aug  5 19:07:21 omega [    0.000000] Policy zone: Normal
Aug  5 19:07:21 omega [    0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-4.13.0-rc3-default+ root=/dev/mapper/system-root ro showopts crashkernel=1G,high crashkernel=72M,low rd.driver.blacklist=i915 netconsole=6514@192.168.185.131/eth0,514@192.168.185.79/52:54:00:38:7c:1f
Aug  5 19:07:21 omega [    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
Aug  5 19:07:21 omega [    0.000000] Memory: 2827420K/4078956K available (7879K kernel code, 1410K rwdata, 3264K rodata, 1972K init, 1616K bss, 1251536K reserved, 0K cma-reserved)
Aug  5 19:07:21 omega [    0.000000] ftrace: allocating 32553 entries in 128 pages
Aug  5 19:07:21 omega [    0.000000] Preemptible hierarchical RCU implementation.
Aug  5 19:07:21 omega [    0.000000]    RCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=4.
Aug  5 19:07:21 omega [    0.000000]    Tasks RCU enabled.
Aug  5 19:07:21 omega [    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
Aug  5 19:07:21 omega [    0.000000] NR_IRQS: 33024, nr_irqs: 1024, preallocated irqs: 16
Aug  5 19:07:21 omega [    0.000000] Console: colour dummy device 80x25
Aug  5 19:07:21 omega [    0.000000] console [tty0] enabled
Aug  5 19:07:21 omega [    0.000000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635855245 ns
Aug  5 19:07:21 omega [    0.004000] tsc: Detected 2700.000 MHz processor
Aug  5 19:07:21 omega [    0.004000] [Firmware Bug]: TSC ADJUST: CPU0: -72306726 force to 0
Aug  5 19:07:21 omega [    0.004000] Calibrating delay loop (skipped), value calculated using timer frequency.. 5424.00 BogoMIPS (lpj=10848000)
Aug  5 19:07:21 omega [    0.004000] pid_max: default: 32768 minimum: 301
Aug  5 19:07:21 omega [    0.004000] ACPI: Core revision 20170531
Aug  5 19:07:21 omega [    0.053505] ACPI: 13 ACPI AML tables successfully acquired and loaded
Aug  5 19:07:21 omega [    0.054013] Security Framework initialized
Aug  5 19:07:21 omega [    0.054029] AppArmor: AppArmor initialized
Aug  5 19:07:21 omega [    0.054714] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
Aug  5 19:07:21 omega [    0.055047] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
Aug  5 19:07:21 omega [    0.055067] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes)
Aug  5 19:07:21 omega [    0.055082] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes)
Aug  5 19:07:21 omega [    0.055273] CPU: Physical Processor ID: 0
Aug  5 19:07:21 omega [    0.055276] CPU: Processor Core ID: 0
Aug  5 19:07:21 omega [    0.055281] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
Aug  5 19:07:21 omega [    0.055284] ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)
Aug  5 19:07:21 omega [    0.055291] mce: CPU supports 8 MCE banks
Aug  5 19:07:21 omega [    0.055302] CPU0: Thermal monitoring enabled (TM1)
Aug  5 19:07:21 omega [    0.055318] process: using mwait in idle threads
Aug  5 19:07:21 omega [    0.055322] Last level iTLB entries: 4KB 64, 2MB 8, 4MB 8
Aug  5 19:07:21 omega [    0.055324] Last level dTLB entries: 4KB 64, 2MB 0, 4MB 0, 1GB 4
Aug  5 19:07:21 omega [    0.055398] Freeing SMP alternatives memory: 28K
Aug  5 19:07:21 omega [    0.057331] smpboot: Max logical packages: 2
Aug  5 19:07:21 omega [    0.058545] x2apic: IRQ remapping doesn't support X2APIC mode
Aug  5 19:07:21 omega [    0.062967] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
Aug  5 19:07:21 omega [    0.102688] smpboot: CPU0: Intel(R) Core(TM) i5-7200U CPU @ 2.50GHz (family: 0x6, model: 0x8e, stepping: 0x9)
Aug  5 19:07:21 omega [    0.116038] Performance Events: PEBS fmt3+, Skylake events, 32-deep LBR, full-width counters, Intel PMU driver.
Aug  5 19:07:21 omega [    0.116120] ... version:                4
Aug  5 19:07:21 omega [    0.116122] ... bit width:              48
Aug  5 19:07:21 omega [    0.116124] ... generic registers:      4
Aug  5 19:07:21 omega [    2.209329] ahci 0000:00:17.0: AHCI 0001.0301 32 slots 3 ports 6 Gbps 0x7 impl SATA mode
Aug  5 19:07:21 omega [    2.209364] ahci 0000:00:17.0: flags: 64bit ncq ilck pm led clo only pio slum part deso sadm sds apst 
Aug  5 19:07:21 omega [    2.210012] scsi host0: ahci
Aug  5 19:07:21 omega [    2.210300] scsi host1: ahci
Aug  5 19:07:21 omega [    2.210551] scsi host2: ahci
Aug  5 19:07:21 omega [    2.210618] ata1: SATA max UDMA/133 abar m2048@0xd132d000 port 0xd132d100 irq 123
Aug  5 19:07:21 omega [    2.210643] ata2: SATA max UDMA/133 abar m2048@0xd132d000 port 0xd132d180 irq 123
Aug  5 19:07:21 omega [    2.210668] ata3: SATA max UDMA/133 abar m2048@0xd132d000 port 0xd132d200 irq 123
Aug  5 19:07:21 omega [    2.210756] i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:PSE3] at 0x60,0x64 irq 1,12
Aug  5 19:07:21 omega [    2.218204] serio: i8042 KBD port at 0x60,0x64 irq 1
Aug  5 19:07:21 omega [    2.218248] serio: i8042 AUX port at 0x60,0x64 irq 12
Aug  5 19:07:21 omega [    2.218501] mousedev: PS/2 mouse device common for all mice
Aug  5 19:07:21 omega [    2.218583] rtc_cmos 00:03: RTC can wake from S4
Aug  5 19:07:21 omega [    2.219083] rtc_cmos 00:03: rtc core: registered rtc_cmos as rtc0
Aug  5 19:07:21 omega [    2.219187] rtc_cmos 00:03: alarms up to one month, y3k, 242 bytes nvram, hpet irqs
Aug  5 19:07:21 omega [    2.219217] intel_pstate: Intel P-state driver initializing
Aug  5 19:07:21 omega [    2.219648] intel_pstate: HWP enabled
Aug  5 19:07:21 omega [    2.219817] ledtrig-cpu: registered to indicate activity on CPUs
Aug  5 19:07:21 omega [    2.219835] EFI Variables Facility v0.08 2004-May-17
Aug  5 19:07:21 omega [    2.226758] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
Aug  5 19:07:21 omega [    4.641938] input: Sleep Button as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0E:00/input/input3
Aug  5 19:07:21 omega [    4.642718] ACPI: Sleep Button [SLPB]
Aug  5 19:07:21 omega [    4.645850] input: Lid Switch as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0D:00/input/input4
Aug  5 19:07:21 omega [    4.647940] ACPI: Lid Switch [LID0]
Aug  5 19:07:21 omega [    4.647982] input: Power Button as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0C:00/input/input5
Aug  5 19:07:21 omega [    4.648025] ACPI: Power Button [PWRB]
Aug  5 19:07:21 omega [    4.648065] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input6
Aug  5 19:07:21 omega [    4.648098] ACPI: Power Button [PWRF]
Aug  5 19:07:21 omega [    4.662356] ACPI: bus type USB registered
Aug  5 19:07:21 omega [    4.663152] usbcore: registered new interface driver usbfs
Aug  5 19:07:21 omega [    4.663927] usbcore: registered new interface driver hub
Aug  5 19:07:21 omega [    4.665130] usbcore: registered new device driver usb
Aug  5 19:07:21 omega [    4.666449] xhci_hcd 0000:00:14.0: xHCI Host Controller
Aug  5 19:07:21 omega [    4.666455] xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 1
Aug  5 19:07:21 omega [    4.667540] xhci_hcd 0000:00:14.0: hcc params 0x200077c1 hci version 0x100 quirks 0x00109810
Aug  5 19:07:21 omega [    4.667636] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Aug  5 19:07:21 omega [    4.667638] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Aug  5 19:07:21 omega [    4.667639] usb usb1: Product: xHCI Host Controller
Aug  5 19:07:21 omega [    4.667639] usb usb1: Manufacturer: Linux 4.13.0-rc3-default+ xhci-hcd
Aug  5 19:07:21 omega [    4.667640] usb usb1: SerialNumber: 0000:00:14.0
Aug  5 19:07:21 omega [    4.668922] hub 1-0:1.0: USB hub found
Aug  5 19:07:21 omega [    4.668939] hub 1-0:1.0: 12 ports detected
Aug  5 19:07:21 omega [    4.671872] xhci_hcd 0000:00:14.0: xHCI Host Controller
Aug  5 19:07:21 omega [    4.671875] xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 2
Aug  5 19:07:21 omega [    4.671900] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003
Aug  5 19:07:21 omega [    4.671900] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Aug  5 19:07:21 omega [    4.671901] usb usb2: Product: xHCI Host Controller
Aug  5 19:07:21 omega [    4.671901] usb usb2: Manufacturer: Linux 4.13.0-rc3-default+ xhci-hcd
Aug  5 19:07:21 omega [    4.671902] usb usb2: SerialNumber: 0000:00:14.0
Aug  5 19:07:21 omega [    4.676076] hub 2-0:1.0: USB hub found
Aug  5 19:07:21 omega [    4.676086] hub 2-0:1.0: 6 ports detected
Aug  5 19:07:21 omega [    4.686355] sr 0:0:0:0: [sr0] scsi3-mmc drive: 24x/24x writer dvd-ram cd/rw xa/form2 cdda tray
Aug  5 19:07:21 omega [    4.686357] cdrom: Uniform CD-ROM driver Revision: 3.20
Aug  5 19:07:21 omega [    4.996313] usb 1-5: new low-speed USB device number 2 using xhci_hcd
Aug  5 19:07:21 omega [    5.139934] usb 1-5: New USB device found, idVendor=046d, idProduct=c077
Aug  5 19:07:21 omega [    5.139978] usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Aug  5 19:07:21 omega [    5.140032] usb 1-5: Product: USB Optical Mouse
Aug  5 19:07:21 omega [    5.140057] usb 1-5: Manufacturer: Logitech
Aug  5 19:07:21 omega [    5.144142] usbcore: registered new interface driver usbhid
Aug  5 19:07:21 omega [    5.144180] usbhid: USB HID core driver
Aug  5 19:07:21 omega [    5.144973] input: Logitech USB Optical Mouse as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/0003:046D:C077.0001/input/input7
Aug  5 19:07:21 omega [    5.145194] hid-generic 0003:046D:C077.0001: input,hidraw0: USB HID v1.11 Mouse [Logitech USB Optical Mouse] on usb-0000:00:14.0-5/input0
Aug  5 19:07:22 omega [    5.260264] usb 1-6: new full-speed USB device number 3 using xhci_hcd
Aug  5 19:07:22 omega [    5.401862] usb 1-6: New USB device found, idVendor=138a, idProduct=0011
Aug  5 19:07:22 omega [    5.401961] usb 1-6: New USB device strings: Mfr=0, Product=0, SerialNumber=1
Aug  5 19:07:22 omega [    5.402033] usb 1-6: SerialNumber: 32607634f0a8
Aug  5 19:07:22 omega [    5.520305] usb 1-7: new high-speed USB device number 4 using xhci_hcd
Aug  5 19:07:22 omega [    5.614487] EXT4-fs: Warning: mounting with data=journal disables delayed allocation and O_DIRECT support!
Aug  5 19:07:22 omega [    5.634182] EXT4-fs (dm-1): mounted filesystem with journalled data mode. Opts: (null)
Aug  5 19:07:22 omega [    5.664331] usb 1-7: New USB device found, idVendor=0bda, idProduct=0129
Aug  5 19:07:22 omega [    5.664467] usb 1-7: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Aug  5 19:07:22 omega [    5.664609] usb 1-7: Product: USB2.0-CRW
Aug  5 19:07:22 omega [    5.664681] usb 1-7: Manufacturer: Generic
Aug  5 19:07:22 omega [    5.664768] usb 1-7: SerialNumber: 20100201396000000
Aug  5 19:07:22 omega [    5.671696] usbcore: registered new interface driver rtsx_usb
Aug  5 19:07:22 omega [    5.784020] usb 1-8: new full-speed USB device number 5 using xhci_hcd
Aug  5 19:07:22 omega [    5.906824] systemd-journald[156]: Received SIGTERM from PID 1 (systemd).
Aug  5 19:07:22 omega [    5.925585] usb 1-8: New USB device found, idVendor=0cf3, idProduct=e500
Aug  5 19:07:22 omega [    5.928184] usb 1-8: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug  5 19:07:22 omega [    6.108052] usb 1-9: new high-speed USB device number 6 using xhci_hcd
Aug  5 19:07:22 omega [    6.153612] systemd: 19 output lines suppressed due to ratelimiting
Aug  5 19:07:23 omega [    6.264316] usb 1-9: New USB device found, idVendor=174f, idProduct=2410
Aug  5 19:07:23 omega [    6.267215] usb 1-9: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Aug  5 19:07:23 omega [    6.269691] usb 1-9: Product: EasyCamera
Aug  5 19:07:23 omega [    6.272087] usb 1-9: Manufacturer: W161221b2720
Aug  5 19:07:27 omega [   10.583256] EXT4-fs (dm-1): re-mounted. Opts: data=journal,acl,user_xattr
Aug  5 19:07:27 omega [   10.872884] systemd-journald[523]: Received request to flush runtime journal from PID 1
Aug  5 19:07:29 omega [   12.505611] audit: type=1400 audit(1501949250.756:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/{usr/,}bin/ping" pid=572 comm="apparmor_parser"
Aug  5 19:07:29 omega [   12.527688] audit: type=1400 audit(1501949250.778:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="klogd" pid=579 comm="apparmor_parser"
Aug  5 19:07:29 omega [   12.618350] audit: type=1400 audit(1501949250.868:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="syslog-ng" pid=583 comm="apparmor_parser"
Aug  5 19:07:29 omega [   12.758379] audit: type=1400 audit(1501949251.008:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="syslogd" pid=587 comm="apparmor_parser"
Aug  5 19:07:29 omega [   12.990453] audit: type=1400 audit(1501949251.241:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/lessopen.sh" pid=592 comm="apparmor_parser"
Aug  5 19:07:30 omega [   13.433512] ACPI: Battery Slot [BAT1] (battery present)
Aug  5 19:07:30 omega [   13.435672] ACPI: AC Adapter [ACAD] (on-line)
Aug  5 19:07:30 omega [   13.455244] acpi PNP0C14:02: duplicate WMI GUID 05901221-D566-11D1-B2F0-00A0C9062910 (first instance was on PNP0C14:01)
Aug  5 19:07:30 omega [   13.487423] audit: type=1400 audit(1501949251.738:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/apache2/mpm-prefork/apache2" pid=596 comm="apparmor_parser"
Aug  5 19:07:30 omega [   13.488757] audit: type=1400 audit(1501949251.738:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/apache2/mpm-prefork/apache2//DEFAULT_URI" pid=596 comm="apparmor_parser"
Aug  5 19:07:30 omega [   13.489973] audit: type=1400 audit(1501949251.738:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/apache2/mpm-prefork/apache2//HANDLING_UNTRUSTED_INPUT" pid=596 comm="apparmor_parser"
Aug  5 19:07:30 omega [   13.491125] audit: type=1400 audit(1501949251.738:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/apache2/mpm-prefork/apache2//phpsysinfo" pid=596 comm="apparmor_parser"
Aug  5 19:07:30 omega [   13.539615] (NULL device *): hwmon_device_register() is deprecated. Please convert the driver to use hwmon_device_register_with_info().
Aug  5 19:07:30 omega [   13.562096] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
Aug  5 19:07:30 omega [   13.649028] input: Ideapad extra buttons as /devices/pci0000:00/0000:00:1f.0/PNP0C09:00/VPC2004:00/input/input8
Aug  5 19:07:30 omega [   13.718725] Bluetooth: Core ver 2.22
Aug  5 19:07:30 omega [   13.721984] NET: Registered protocol family 31
Aug  5 19:07:30 omega [   13.726635] Bluetooth: HCI device and connection manager initialized
Aug  5 19:07:30 omega [   13.731299] Bluetooth: HCI socket layer initialized
Aug  5 19:07:30 omega [   13.735309] Bluetooth: L2CAP socket layer initialized
Aug  5 19:07:30 omega [   13.739644] Bluetooth: SCO socket layer initialized
Aug  5 19:07:30 omega [   13.758690] AVX2 version of gcm_enc/dec engaged.
Aug  5 19:07:30 omega [   13.761952] AES CTR mode by8 optimization enabled
Aug  5 19:07:30 omega [   13.766030] input: PC Speaker as /devices/platform/pcspkr/input/input9
Aug  5 19:07:30 omega [   13.779634] i801_smbus 0000:00:1f.4: enabling device (0000 -> 0003)
Aug  5 19:07:30 omega [   13.783524] i801_smbus 0000:00:1f.4: SPD Write Disable is set
Aug  5 19:07:30 omega [   13.786955] i801_smbus 0000:00:1f.4: SMBus using PCI interrupt
Aug  5 19:07:30 omega [   13.897127] audit: type=1400 audit(1501949252.147:11): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/dovecot/anvil" pid=847 comm="apparmor_parser"
Aug  5 19:07:30 omega [   13.920491] iTCO_vendor_support: vendor-support=0
Aug  5 19:07:30 omega [   13.953996] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.11
Aug  5 19:07:30 omega [   13.957564] iTCO_wdt: Found a Intel PCH TCO device (Version=4, TCOBASE=0x0400)
Aug  5 19:07:30 omega [   13.961251] iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0)
Aug  5 19:07:31 omega [   14.168458] mei_me 0000:00:16.0: enabling device (0000 -> 0002)
Aug  5 19:07:31 omega [   14.191371] Bluetooth: HCI UART driver ver 2.3
Aug  5 19:07:31 omega [   14.194981] Bluetooth: HCI UART protocol H4 registered
Aug  5 19:07:31 omega [   14.198349] Bluetooth: HCI UART protocol BCSP registered
Aug  5 19:07:31 omega [   14.201774] Bluetooth: HCI UART protocol LL registered
Aug  5 19:07:31 omega [   14.205938] Bluetooth: HCI UART protocol ATH3K registered
Aug  5 19:07:31 omega [   14.209441] Bluetooth: HCI UART protocol Three-wire (H5) registered
Aug  5 19:07:31 omega [   14.212951] Bluetooth: HCI UART protocol Intel registered
Aug  5 19:07:31 omega [   14.216490] Bluetooth: HCI UART protocol Broadcom registered
Aug  5 19:07:31 omega [   14.219840] Bluetooth: HCI UART protocol QCA registered
Aug  5 19:07:31 omega [   14.222797] Bluetooth: HCI UART protocol AG6XX registered
Aug  5 19:07:31 omega [   14.224987] Bluetooth: HCI UART protocol Marvell registered
Aug  5 19:07:31 omega [   14.432203] usbcore: registered new interface driver btusb
Aug  5 19:07:31 omega [   14.546529] kvm: disabled by bios
Aug  5 19:07:31 omega [   14.656774] Setting dangerous option live_selftests - tainting kernel
Aug  5 19:07:31 omega [   14.663672] [drm] Memory usable by graphics device = 4096M
Aug  5 19:07:31 omega [   14.667035] fb: switching to inteldrmfb from EFI VGA
Aug  5 19:07:31 omega [   14.670451] Console: switching to colour dummy device 80x25
Aug  5 19:07:31 omega [   14.670679] [drm] Replacing VGA console driver
Aug  5 19:07:31 omega [   14.677249] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
Aug  5 19:07:31 omega [   14.677270] [drm] Driver supports precise vblank timestamp query.
Aug  5 19:07:31 omega [   14.679494] i915 0000:00:02.0: vgaarb: changed VGA decodes: olddecodes=io+mem,decodes=io+mem:owns=io+mem
Aug  5 19:07:31 omega [   14.688580] [drm] Initialized i915 1.6.0 20170731 for 0000:00:02.0 on minor 0
Aug  5 19:07:31 omega [   14.694461] ACPI: Video Device [GFX0] (multi-head: yes  rom: no  post: no)
Aug  5 19:07:31 omega [   14.694841] input: Video Bus as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/LNXVIDEO:00/input/input10
Aug  5 19:07:31 omega [   14.695061] [drm] DRM_I915_DEBUG enabled
Aug  5 19:07:31 omega [   14.695076] i915: Performing live selftests with st_random_seed=0xbe91e1bd st_timeout=1000
Aug  5 19:07:31 omega [   14.695092] i915: i915_live_sanitycheck() - ok!

Here it hangs. Unfortunately, I see blank screen at the laptop itself and cannot figure out wether there are any other messages. Kdump also seems to be not triggered.
Comment 1 Matwey V. Kornilov 2017-08-05 16:31:15 UTC 
Created attachment 133258 [details]
Full log

After half an our the rest of messages appears.
Comment 2 Matwey V. Kornilov 2017-08-05 16:59:26 UTC 
This scenario reproduces every time.
Comment 3 Elizabeth 2017-08-24 16:53:50 UTC 
Hello Matwey,
Could you please attach error state from hang, also could you replicate with drm.debug=0x1e log_bug_len=2M on grub and attach log. After it goes blank is there any way to recovery besides power off?
Comment 4 Elizabeth 2017-10-25 20:28:30 UTC 
(In reply to Elizabeth from comment #3)
> Hello Matwey,
> Could you please attach error state from hang, also could you replicate with
> drm.debug=0x1e log_bug_len=2M on grub and attach log. After it goes blank is
> there any way to recovery besides power off?
Hello Matwey, any look reproducing with debug info? Thank you.
Comment 5 Chris Wilson 2017-11-02 11:54:55 UTC 
Mika suspected that

commit 7130630323c562597191653560963e61c5bd0f57
Author: Mika Kuoppala <mika.kuoppala@linux.intel.com>
Date:   Thu Nov 2 11:48:36 2017 +0200

    drm/i915: Use fallback forcewake if primary ack missing
    
    There is a possibility on gen9 hardware to miss the forcewake ack
    message. The recommended workaround is to use another free
    bit and toggle it until original bit is successfully acknowledged.
    
    Some future gen9 revs might or might not fix the underlying issue but
    using fallback forcewake bit dance can be considered as harmless:
    without the ack timeout we never reach the fallback bit forcewake.
    Thus as of now we adopt a blanket approach for all gen9 and leave
    the bypassing the fallback bit approach for future patches if
    corresponding hw revisions do appear.
    
    Commit 83e3337204b2 ("drm/i915: Increase maximum polling time to 50ms
    for forcewake request/clear ack") did increase the forcewake timeout.
    If the issue was a delayed ack, future work could include finding
    a suitable timeout value both for primary ack and reserve toggle
    to reduce the worst case latency.
    
    v2: use bit 15, naming, comment (Chris), only wait fallback ack
    v3: fix return on fallback, backoff after fallback write (Chris)
    v4: udelay on first pass, grammar (Chris)
    v4: s/reserve/fallback
    
    References: HSDES #1604254524
    References: https://bugs.freedesktop.org/show_bug.cgi?id=102051
    Cc: Chris Wilson <chris@chris-wilson.co.uk>
    Cc: Rodrigo Vivi <rodrigo.vivi@intel.com>
    Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
    Cc: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
    Cc: Sagar Arun Kamble <sagar.a.kamble@intel.com>
    Signed-off-by: Mika Kuoppala <mika.kuoppala@linux.intel.com>
    Reviewed-by: Chris Wilson <chris@chris-wilson.co.uk>
    Link: https://patchwork.freedesktop.org/patch/msgid/20171102094836.2506-1-mika.kuoppala@linux.intel.com

may help, but live_uncore is deliberately unfriendly to the hw...
Comment 6 Chris Wilson 2017-11-23 21:28:04 UTC 
Test is now disabled by default; and perchance the w/a was relevant.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.