[Intel-gfx] log splat from Intel DRM driver on resume

Fri Sep 23 16:20:03 UTC 2016

When I resume my desktop from suspend, the following shows up in the log.
Running 4.8.0-rc6 (net-next branch).dme
Everything appears to be working ok.

[148349.793696] PM: Syncing filesystems ... done.
[148350.599336] PM: Preparing system for sleep (mem)
[148350.599623] Freezing user space processes ... (elapsed 0.002 seconds) done.
[148350.601661] Double checking all user space processes after OOM killer disable... (elapsed 0.000 seconds) 
[148350.601773] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[148350.603094] PM: Suspending system (mem)
[148350.603125] Suspending console(s) (use no_console_suspend to debug)
[148350.603576] sd 3:0:0:0: [sdd] Synchronizing SCSI cache
[148350.603644] sd 2:0:0:0: [sdc] Synchronizing SCSI cache
[148350.603717] sd 3:0:0:0: [sdd] Stopping disk
[148350.603734] sd 1:0:0:0: [sdb] Synchronizing SCSI cache
[148350.603826] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[148350.606447] sd 0:0:0:0: [sda] Stopping disk
[148350.606449] sd 1:0:0:0: [sdb] Stopping disk
[148350.606453] sd 2:0:0:0: [sdc] Stopping disk
[148350.607125] serial 00:06: disabled
[148350.607508] serial 00:05: disabled
[148350.608246] e1000e: EEE TX LPI TIMER: 00000011
[148350.707346] igb 0000:04:00.0: System wakeup enabled by ACPI
[148352.441712] PM: suspend of devices complete after 1838.466 msecs
[148352.442417] [drm:hsw_write_dcomp [i915]] *ERROR* Failed to write to D_COMP
[148352.461491] PM: late suspend of devices complete after 19.764 msecs
[148352.462302] xhci_hcd 0000:07:00.0: System wakeup enabled by ACPI
[148352.462439] ehci-pci 0000:00:1d.0: System wakeup enabled by ACPI
[148352.462592] ehci-pci 0000:00:1a.0: System wakeup enabled by ACPI
[148352.462681] e1000e 0000:00:19.0: System wakeup enabled by ACPI
[148352.462720] xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI
[148352.501430] PM: noirq suspend of devices complete after 39.938 msecs
[148352.501716] ACPI: Preparing to enter system sleep state S3
[148352.917670] PM: Saving platform NVS memory
[148352.917679] Disabling non-boot CPUs ...
[148352.919112] smpboot: CPU 1 is now offline
[148352.935231] smpboot: CPU 2 is now offline
[148352.958025] Broke affinity for irq 51
[148352.959042] smpboot: CPU 3 is now offline
[148352.986027] Broke affinity for irq 16
[148352.986045] Broke affinity for irq 51
[148352.986049] Broke affinity for irq 64
[148352.987059] smpboot: CPU 4 is now offline
[148353.013966] Broke affinity for irq 16
[148353.013977] Broke affinity for irq 42
[148353.013982] Broke affinity for irq 51
[148353.013983] Broke affinity for irq 52
[148353.013985] Broke affinity for irq 64
[148353.014989] smpboot: CPU 5 is now offline
[148353.041918] Broke affinity for irq 16
[148353.041920] Broke affinity for irq 18
[148353.041929] Broke affinity for irq 42
[148353.041934] Broke affinity for irq 51
[148353.041935] Broke affinity for irq 52
[148353.041937] Broke affinity for irq 64
[148353.042945] smpboot: CPU 6 is now offline
[148353.057883] Broke affinity for irq 1
[148353.057885] Broke affinity for irq 8
[148353.057886] Broke affinity for irq 9
[148353.057888] Broke affinity for irq 12
[148353.057890] Broke affinity for irq 16
[148353.057891] Broke affinity for irq 18
[148353.057893] Broke affinity for irq 23
[148353.057901] Broke affinity for irq 42
[148353.057906] Broke affinity for irq 51
[148353.057907] Broke affinity for irq 52
[148353.057909] Broke affinity for irq 64
[148353.058914] smpboot: CPU 7 is now offline
[148353.079391] ACPI: Low-level resume complete
[148353.079445] PM: Restoring platform NVS memory
[148353.081540] Enabling non-boot CPUs ...
[148353.103421] x86: Booting SMP configuration:
[148353.103421] smpboot: Booting Node 0 Processor 1 APIC 0x2
[148353.107035]  cache: parent cpu1 should not be sleeping
[148353.107234] CPU1 is up
[148353.147486] smpboot: Booting Node 0 Processor 2 APIC 0x4
[148353.151108]  cache: parent cpu2 should not be sleeping
[148353.151319] CPU2 is up
[148353.199523] smpboot: Booting Node 0 Processor 3 APIC 0x6
[148353.203150]  cache: parent cpu3 should not be sleeping
[148353.203379] CPU3 is up
[148353.251569] smpboot: Booting Node 0 Processor 4 APIC 0x1
[148353.254215]  cache: parent cpu4 should not be sleeping
[148353.254397] CPU4 is up
[148353.275522] smpboot: Booting Node 0 Processor 5 APIC 0x3
[148353.278010]  cache: parent cpu5 should not be sleeping
[148353.278203] CPU5 is up
[148353.299498] smpboot: Booting Node 0 Processor 6 APIC 0x5
[148353.302104]  cache: parent cpu6 should not be sleeping
[148353.302306] CPU6 is up
[148353.323524] smpboot: Booting Node 0 Processor 7 APIC 0x7
[148353.326132]  cache: parent cpu7 should not be sleeping
[148353.326460] CPU7 is up
[148353.338040] ACPI: Waking up from system sleep state S3
[148353.339125] xhci_hcd 0000:00:14.0: System wakeup disabled by ACPI
[148353.343365] ehci-pci 0000:00:1d.0: System wakeup disabled by ACPI
[148353.343487] ehci-pci 0000:00:1a.0: System wakeup disabled by ACPI
[148353.363405] xhci_hcd 0000:07:00.0: System wakeup disabled by ACPI
[148353.375403] PM: noirq resume of devices complete after 36.582 msecs
[148353.375848] PM: early resume of devices complete after 0.346 msecs
[148353.375909] e1000e 0000:00:19.0: System wakeup disabled by ACPI
[148353.376115] usb usb3: root hub lost power or was reset
[148353.376116] usb usb4: root hub lost power or was reset
[148353.383624] igb 0000:04:00.0: System wakeup disabled by ACPI
[148353.383648] rtc_cmos 00:02: System wakeup disabled by ACPI
[148353.384331] serial 00:05: activated
[148353.384771] serial 00:06: activated
[148353.386827] sd 0:0:0:0: [sda] Starting disk
[148353.386844] sd 1:0:0:0: [sdb] Starting disk
[148353.387040] sd 2:0:0:0: [sdc] Starting disk
[148353.387972] sd 3:0:0:0: [sdd] Starting disk
[148353.426988] xhci_hcd 0000:00:14.0: port 3 resume PLC timeout
[148353.663307] usb 1-4: reset high-speed USB device number 3 using xhci_hcd
[148353.701407] ata8: SATA link down (SStatus 0 SControl 300)
[148353.701440] ata7: SATA link down (SStatus 0 SControl 300)
[148353.757446] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[148353.757500] ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[148353.757536] ata2: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[148353.757550] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[148353.757567] ata6: SATA link down (SStatus 0 SControl 300)
[148353.757582] ata4: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[148353.758196] ata1.00: configured for UDMA/133
[148353.758250] ata1.00: Enabling discard_zeroes_data
[148353.758794] ata2.00: configured for UDMA/133
[148353.759726] ata4.00: configured for UDMA/133
[148353.762027] ata5.00: configured for UDMA/133
[148353.868069] ixgbe 0000:01:00.0: Multiqueue Enabled: Rx Queue count = 8, Tx Queue count = 8
[148353.888468] ata3.00: configured for UDMA/133
[148354.141948] PM: resume of devices complete after 766.138 msecs
[148354.142124] PM: Finishing wakeup.
[148354.142125] Restarting tasks ... 
[148354.142306] pci_bus 0000:06: Allocating resources
[148354.142323] pci 0000:05:00.0: bridge window [io  0x1000-0x0fff] to [bus 06] add_size 1000
[148354.142325] pci 0000:05:00.0: bridge window [mem 0x00100000-0x000fffff 64bit pref] to [bus 06] add_size 200000 add_align 100000
[148354.142328] pci 0000:05:00.0: res[15]=[mem 0x00100000-0x000fffff 64bit pref] res_to_dev_res add_size 200000 min_align 100000
[148354.142329] pci 0000:05:00.0: res[15]=[mem 0x00100000-0x002fffff 64bit pref] res_to_dev_res add_size 200000 min_align 100000
[148354.142331] pci 0000:05:00.0: res[13]=[io  0x1000-0x0fff] res_to_dev_res add_size 1000 min_align 1000
[148354.142331] pci 0000:05:00.0: res[13]=[io  0x1000-0x1fff] res_to_dev_res add_size 1000 min_align 1000
[148354.142334] pci 0000:05:00.0: BAR 15: no space for [mem size 0x00200000 64bit pref]
[148354.142334] pci 0000:05:00.0: BAR 15: failed to assign [mem size 0x00200000 64bit pref]
[148354.142335] pci 0000:05:00.0: BAR 13: no space for [io  size 0x1000]
[148354.142336] pci 0000:05:00.0: BAR 13: failed to assign [io  size 0x1000]
[148354.142338] pci 0000:05:00.0: BAR 15: no space for [mem size 0x00200000 64bit pref]
[148354.142338] pci 0000:05:00.0: BAR 15: failed to assign [mem size 0x00200000 64bit pref]
[148354.142339] pci 0000:05:00.0: BAR 13: no space for [io  size 0x1000]
[148354.142340] pci 0000:05:00.0: BAR 13: failed to assign [io  size 0x1000]
[148354.142341] pci 0000:05:00.0: PCI bridge to [bus 06]
[148354.142352] pci 0000:05:00.0:   bridge window [mem 0xf7a00000-0xf7afffff]
[148354.149323] done.
[148354.149509] video LNXVIDEO:00: Restoring backlight state
[148354.265985] [drm:intel_pipe_config_compare [i915]] *ERROR* mismatch in has_audio (expected 1, found 0)
[148354.265989] ------------[ cut here ]------------
[148354.266012] WARNING: CPU: 7 PID: 4453 at drivers/gpu/drm/i915/intel_display.c:13094 intel_atomic_commit_tail+0xdbc/0x10a0 [i915]
[148354.266012] pipe state doesn't match!
[148354.266013] Modules linked in: fuse(E) ipt_MASQUERADE(E) nf_nat_masquerade_ipv4(E) iptable_nat(E) nf_nat_ipv4(E) xt_CHECKSUM(E) iptable_mangle(E) tun(E) bridge(E) stp(E) llc(E) ebtable_filter(E) ebtables(E) cpufreq_userspace(E) cpufreq_powersave(E) cpufreq_conservative(E) binfmt_misc(E) snd_hda_codec_hdmi(E) intel_rapl(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) i915(E) coretemp(E) kvm_intel(E) kvm(E) iTCO_wdt(E) iTCO_vendor_support(E) snd_hda_codec_realtek(E) snd_hda_codec_generic(E) snd_hda_intel(E) snd_hda_codec(E) irqbypass(E) crct10dif_pclmul(E) drm_kms_helper(E) crc32_pclmul(E) snd_hwdep(E) ghash_clmulni_intel(E) ip6t_REJECT(E) evdev(E) joydev(E) snd_hda_core(E) nf_reject_ipv6(E) aesni_intel(E) aes_x86_64(E) glue_helper(E) drm(E) lrw(E) xt_hl(E) gf128mul(E) snd_pcm_oss(E) ip6t_rt(E) ablk_helper(E)
[148354.266039]  cryptd(E) snd_mixer_oss(E) serio_raw(E) snd_pcm(E) i2c_i801(E) nf_conntrack_ipv6(E) i2c_smbus(E) nf_defrag_ipv6(E) snd_timer(E) snd(E) mei_me(E) ipt_REJECT(E) mei(E) ie31200_edac(E) nf_reject_ipv4(E) edac_core(E) soundcore(E) sg(E) shpchp(E) lpc_ich(E) mfd_core(E) xt_limit(E) xt_tcpudp(E) xt_addrtype(E) battery(E) nf_conntrack_ipv4(E) tpm_crb(E) nf_defrag_ipv4(E) tpm_tis(E) xt_conntrack(E) tpm_tis_core(E) tpm(E) video(E) acpi_pad(E) button(E) ip6table_filter(E) ip6_tables(E) nf_conntrack_netbios_ns(E) nf_conntrack_broadcast(E) nf_nat_ftp(E) nf_nat(E) nf_conntrack_ftp(E) nf_conntrack(E) sch_fq_codel(E) loop(E) iptable_filter(E) parport_pc(E) ip_tables(E) ppdev(E) x_tables(E) lp(E) parport(E) autofs4(E) ext4(E) crc16(E) jbd2(E) mbcache(E) hid_generic(E) btrfs(E) usbhid(E) hid(E) xor(E)
[148354.266068]  raid6_pq(E) sr_mod(E) cdrom(E) sd_mod(E) crc32c_intel(E) ahci(E) psmouse(E) libahci(E) libata(E) scsi_mod(E) ehci_pci(E) ehci_hcd(E) igb(E) xhci_pci(E) xhci_hcd(E) i2c_algo_bit(E) ixgbe(E) usbcore(E) e1000e(E) nvme(E) usb_common(E) nvme_core(E) mdio(E) dca(E) ptp(E) pps_core(E) thermal(E) fan(E) fjes(E)
[148354.266084] CPU: 7 PID: 4453 Comm: Xorg Tainted: G        W   E   4.8.0-rc6-net-next+ #26
[148354.266085] Hardware name: Supermicro X10SAE/X10SAE, BIOS 3.0 05/20/2015
[148354.266086]  0000000000000286 00000000b8c57b6a ffffffff8d2b3ee4 ffff8f9a8cd5fb20
[148354.266089]  0000000000000000 ffffffff8d069934 ffff8f9a8224a000 ffff8f9a8cd5fb78
[148354.266091]  ffff8f99e1984800 0000000000000000 ffff8f9a8a640000 ffff8f99e1984800
[148354.266093] Call Trace:
[148354.266098]  [<ffffffff8d2b3ee4>] ? dump_stack+0x5c/0x78
[148354.266101]  [<ffffffff8d069934>] ? __warn+0xb4/0xd0
[148354.266103]  [<ffffffff8d0699aa>] ? warn_slowpath_fmt+0x5a/0x80
[148354.266127]  [<ffffffffc0a2853c>] ? intel_atomic_commit_tail+0xdbc/0x10a0 [i915]
[148354.266130]  [<ffffffff8d0a4bb0>] ? wake_atomic_t_function+0x50/0x50
[148354.266138]  [<ffffffffc0882728>] ? drm_atomic_helper_setup_commit+0x248/0x310 [drm_kms_helper]
[148354.266161]  [<ffffffffc0a28c5d>] ? intel_atomic_commit+0x43d/0x560 [i915]
[148354.266178]  [<ffffffffc07b3bfd>] ? drm_atomic_set_crtc_for_connector+0x8d/0xf0 [drm]
[148354.266185]  [<ffffffffc0883434>] ? drm_atomic_helper_set_config+0x74/0xb0 [drm_kms_helper]
[148354.266197]  [<ffffffffc07a2eec>] ? drm_mode_set_config_internal+0x5c/0x110 [drm]
[148354.266209]  [<ffffffffc07a7966>] ? drm_mode_setcrtc+0x426/0x550 [drm]
[148354.266218]  [<ffffffffc079ab6e>] ? drm_ioctl+0x1ae/0x440 [drm]
[148354.266220]  [<ffffffff8d074291>] ? recalc_sigpending+0x11/0x40
[148354.266232]  [<ffffffffc07a7540>] ? drm_mode_setplane+0x1c0/0x1c0 [drm]
[148354.266235]  [<ffffffff8d1b4df9>] ? do_vfs_ioctl+0x99/0x5d0
[148354.266237]  [<ffffffff8d1b539f>] ? SyS_ioctl+0x6f/0x80
[148354.266240]  [<ffffffff8d555876>] ? entry_SYSCALL_64_fastpath+0x1e/0xa8
[148354.266241] ---[ end trace b80b31733d50e217 ]---
[148356.383761] igb 0000:04:00.0 eth0: igb: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
[148361.051046] ixgbe 0000:01:00.0 eth2: NIC Link is Up 10 Gbps, Flow Control: RX/TX