Created attachment 129298 [details] HTML output of `analyze_suspend.py` On the Dell XPS13 9360 using a Kaby Lake device, suspend takes quite long. ``` i915 @ 0000:00:02.0 {i915} async_device (Total Suspend: 1228.609 ms Total Resume: 344.585 ms) ``` Please find the HTML output of AnalyzeSuspend v4.5 [1] attached. ``` $ lspci -nn -v -s 0:02.0 00:02.0 VGA compatible controller [0300]: Intel Corporation Device [8086:5916] (rev 02) (prog-if 00 [VGA controller]) Subsystem: Dell Device [1028:075b] Flags: bus master, fast devsel, latency 0, IRQ 285 Memory at db000000 (64-bit, non-prefetchable) [size=16M] Memory at 90000000 (64-bit, prefetchable) [size=256M] I/O ports at f000 [size=64] [virtual] Expansion ROM at 000c0000 [disabled] [size=128K] Capabilities: <access denied> Kernel driver in use: i915 Kernel modules: i915 $ more /proc/version Linux version 4.10.0-rc6+ (peter@xps13) (gcc version 6.3.0 20170124 (Debian 6.3.0-5) ) #32 SMP Thu Feb 2 15:06:22 CET 2017 $ more /proc/cmdline BOOT_IMAGE=/boot/vmlinuz-4.10.0-rc6+ root=UUID=2809c0c6-7152-4e35-a6da-a26e7400e556 ro quiet noisapnp mem_sleep_default=deep drm.debug=0xe $ sudo more /sys/kernel/debug/dri/0/eDP-1/i915_panel_timings Panel power up delay: 200 Panel power down delay: 50 Backlight on delay: 1 Backlight off delay: 200 ``` [1] https://01.org/suspendresume/ ``` # suspend-020217-155509 xps13 mem 4.10.0-rc6+ # fwsuspend 0 fwresume 3721283 [ 121.805411] PM: Syncing filesystems ... done. [ 121.807419] PM: Preparing system for sleep (mem) [ 121.807599] Freezing user space processes ... (elapsed 0.001 seconds) done. [ 121.809204] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done. [ 121.810492] PM: Suspending system (mem) [ 121.810606] Suspending console(s) (use no_console_suspend to debug) [ 122.028852] wlp58s0: deauthenticating from 6c:f3:7f:10:ae:18 by local choice (Reason: 3=DEAUTH_LEAVING) [ 122.035369] ACPI : EC: event blocked [ 122.035580] [drm:intel_power_well_enable [i915]] enabling DC off [ 122.035624] [drm:gen9_set_dc_state [i915]] Setting DC state from 02 to 00 [ 122.035670] [drm:intel_power_well_enable [i915]] enabling power well 2 [ 122.035712] [drm:skl_set_power_well [i915]] Enabling power well 2 [ 122.035773] [drm:intel_power_well_enable [i915]] enabling DDI B power well [ 122.035812] [drm:skl_set_power_well [i915]] Enabling DDI B power well [ 122.035849] [drm:intel_power_well_enable [i915]] enabling DDI C power well [ 122.035886] [drm:skl_set_power_well [i915]] Enabling DDI C power well [ 122.035924] [drm:intel_power_well_enable [i915]] enabling DDI D power well [ 122.035962] [drm:skl_set_power_well [i915]] Enabling DDI D power well [ 122.038363] [drm:intel_atomic_check [i915]] [CONNECTOR:47:eDP-1] checking for sink bpp constrains [ 122.038417] [drm:intel_atomic_check [i915]] clamping display bpp (was 36) to EDID reported max of 24 [ 122.038476] [drm:intel_dp_compute_config [i915]] DP link computation with max lane count 4 max bw 540000 pixel clock 373250KHz [ 122.038539] [drm:intel_dp_compute_config [i915]] DP link bw 14 rate select 00 lane count 4 clock 540000 bpp 24 [ 122.038585] [drm:intel_dp_compute_config [i915]] DP link bw required 895800 available 1728000 [ 122.038637] [drm:intel_atomic_check [i915]] hw max bpp: 36, pipe bpp: 24, dithering: 0 [ 122.038707] [drm:intel_dump_pipe_config [i915]] [CRTC:31:pipe A][modeset] [ 122.038813] [drm:intel_dump_pipe_config [i915]] cpu_transcoder: EDP, pipe bpp: 24, dithering: 0 [ 122.038860] [drm:intel_dump_pipe_config [i915]] dp m_n: lanes: 4; gmch_m: 4348677, gmch_n: 8388608, link_m: 724779, link_n: 1048576, tu: 64 [ 122.038911] [drm:intel_dump_pipe_config [i915]] audio: 0, infoframes: 0 [ 122.038953] [drm:intel_dump_pipe_config [i915]] requested mode: [ 122.038993] [drm:drm_mode_debug_printmodeline [drm]] Modeline 0:"3200x1800" 60 373250 3200 3248 3280 3360 1800 1803 1808 1852 0x48 0xa [ 122.039037] [drm:intel_dump_pipe_config [i915]] adjusted mode: [ 122.039069] [drm:drm_mode_debug_printmodeline [drm]] Modeline 0:"3200x1800" 60 373250 3200 3248 3280 3360 1800 1803 1808 1852 0x48 0xa [ 122.039116] [drm:intel_dump_pipe_config [i915]] crtc timings: 373250 3200 3248 3280 3360 1800 1803 1808 1852, type: 0x48 flags: 0xa [ 122.039158] [drm:intel_dump_pipe_config [i915]] port clock: 540000, pipe src size: 3200x1800 [ 122.039200] [drm:intel_dump_pipe_config [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1 [ 122.039247] [drm:intel_dump_pipe_config [i915]] pch pfit: pos: 0x00000000, size: 0x00000000, disabled [ 122.039287] [drm:intel_dump_pipe_config [i915]] ips: 0, double wide: 0 [ 122.039326] [drm:intel_dump_pipe_config [i915]] dpll_hw_state: ctrl1: 0x1, cfgcr1: 0x0, cfgcr2: 0x0 [ 122.039365] [drm:intel_dump_pipe_config [i915]] planes on this crtc [ 122.039410] [drm:intel_dump_pipe_config [i915]] [PLANE:25:plane 1A] FB:70, fb = 3200x1800 format = XR24 little-endian (0x34325258) [ 122.039451] [drm:intel_dump_pipe_config [i915]] scaler:-1 src 0x0+3200+1800 dst 0x0+3200+1800 [ 122.039490] [drm:intel_dump_pipe_config [i915]] [PLANE:27:plane 2A] disabled, scaler_id = -1 [ 122.039529] [drm:intel_dump_pipe_config [i915]] [PLANE:29:cursor A] disabled, scaler_id = -1 [ 122.039591] [drm:intel_atomic_check [i915]] New cdclk calculated to be atomic 450000, actual 337500 [ 122.039655] [drm:intel_find_shared_dpll [i915]] [CRTC:31:pipe A] allocated DPLL 0 [ 122.039704] [drm:intel_reference_shared_dpll [i915]] using DPLL 0 for pipe A [ 122.041930] [drm:intel_edp_backlight_off.part.28 [i915]] [ 122.247122] [drm:intel_panel_actually_set_backlight [i915]] set backlight PWM = 0 [ 122.247252] [drm:intel_disable_pipe [i915]] disabling pipe A [ 122.253198] [drm:edp_panel_vdd_on [i915]] Turning eDP port A VDD on [ 122.253314] [drm:edp_panel_vdd_on [i915]] PP_STATUS: 0x80000008 PP_CONTROL: 0x0000000b [ 122.253573] [drm:edp_panel_off [i915]] Turn eDP port A panel power off [ 122.253650] [drm:edp_panel_off [i915]] Wait for panel power off time [ 122.253758] [drm:wait_panel_status [i915]] mask b0000000 value 00000000 status a0000003 control 00000000 [ 122.253832] [drm:intel_get_hpd_pins [i915]] hotplug event received, stat 0x01000000, dig 0x11101010, pins 0x00000010 [ 122.253893] [drm:intel_hpd_irq_handler [i915]] digital hpd port A - short [ 122.254039] [drm:intel_dp_hpd_pulse [i915]] got hpd irq on port A - short [ 122.304208] [drm:wait_panel_status [i915]] Wait complete [ 122.304296] [drm:intel_disable_shared_dpll [i915]] disable DPLL 0 (active 1, on? 1) for crtc 31 [ 122.304367] [drm:edp_panel_vdd_on [i915]] Turning eDP port A VDD on [ 122.304421] [drm:intel_disable_shared_dpll [i915]] disabling DPLL 0 [ 122.304477] [drm:wait_panel_power_cycle [i915]] Wait for panel power cycle [ 122.304538] [drm:skl_set_cdclk [i915]] Changing CDCLK to 337500 kHz (VCO 8100000 kHz) [ 122.306796] [drm:intel_get_hpd_pins [i915]] hotplug event received, stat 0x01000000, dig 0x12101010, pins 0x00000010 [ 122.306857] [drm:intel_hpd_irq_handler [i915]] digital hpd port A - long [ 122.306912] [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 0 [ 122.307235] [drm:intel_update_cdclk [i915]] Current CD clock rate: 337500 kHz, VCO: 8100000 kHz, ref: 24000 kHz [ 122.307296] [drm:intel_atomic_commit_tail [i915]] [ENCODER:46:DDI A] [ 122.307351] [drm:intel_atomic_commit_tail [i915]] [ENCODER:55:DDI B] [ 122.307407] [drm:intel_atomic_commit_tail [i915]] [ENCODER:57:DP-MST A] [ 122.307455] [drm:intel_atomic_commit_tail [i915]] [ENCODER:58:DP-MST B] [ 122.307500] [drm:intel_atomic_commit_tail [i915]] [ENCODER:59:DP-MST C] [ 122.307543] [drm:intel_atomic_commit_tail [i915]] [ENCODER:62:DDI C] [ 122.307587] [drm:intel_atomic_commit_tail [i915]] [ENCODER:64:DP-MST A] [ 122.307629] [drm:intel_atomic_commit_tail [i915]] [ENCODER:65:DP-MST B] [ 122.307671] [drm:intel_atomic_commit_tail [i915]] [ENCODER:66:DP-MST C] [ 122.307720] [drm:verify_single_dpll_state.isra.115 [i915]] DPLL 0 [ 122.307770] [drm:verify_single_dpll_state.isra.115 [i915]] DPLL 1 [ 122.307817] [drm:verify_single_dpll_state.isra.115 [i915]] DPLL 2 [ 122.307862] [drm:verify_single_dpll_state.isra.115 [i915]] DPLL 3 [ 122.307919] [drm:verify_connector_state.isra.82 [i915]] [CONNECTOR:47:eDP-1] [ 122.307969] [drm:intel_atomic_commit_tail [i915]] [CRTC:31:pipe A] [ 122.308019] [drm:verify_single_dpll_state.isra.115 [i915]] DPLL 0 [ 122.863123] [drm:wait_panel_status [i915]] mask b800000f value 00000000 status 00000000 control 00000000 [ 122.863166] [drm:wait_panel_status [i915]] Wait complete [ 122.863237] [drm:edp_panel_vdd_on [i915]] PP_STATUS: 0x00000000 PP_CONTROL: 0x00000008 [ 122.863276] [drm:edp_panel_vdd_on [i915]] eDP port A panel power wasn't enabled [ 123.110663] [drm:intel_dp_read_dpcd [i915]] DPCD: 12 14 84 40 00 00 01 01 02 00 00 00 00 0b 00 [ 123.230667] [drm:edp_panel_vdd_off_sync [i915]] Turning eDP port A VDD off [ 123.230716] [drm:edp_panel_vdd_off_sync [i915]] PP_STATUS: 0x00000000 PP_CONTROL: 0x00000000 [ 123.232890] PM: suspend of devices complete after 1204.477 msecs [ 123.235649] [drm:intel_power_well_disable [i915]] disabling DDI D power well [ 123.235659] [drm:skl_set_power_well [i915]] Disabling DDI D power well [ 123.235668] [drm:intel_power_well_disable [i915]] disabling DDI C power well [ 123.235676] [drm:skl_set_power_well [i915]] Disabling DDI C power well [ 123.235685] [drm:intel_power_well_disable [i915]] disabling DDI B power well [ 123.235693] [drm:skl_set_power_well [i915]] Disabling DDI B power well [ 123.235702] [drm:intel_power_well_disable [i915]] disabling DDI A/E power well [ 123.235710] [drm:skl_set_power_well [i915]] Disabling DDI A/E power well [ 123.235718] [drm:intel_power_well_disable [i915]] disabling power well 2 [ 123.235731] [drm:skl_set_power_well [i915]] Disabling power well 2 [ 123.235739] [drm:intel_power_well_disable [i915]] disabling DC off [ 123.235748] [drm:skl_enable_dc6 [i915]] Enabling DC6 [ 123.235756] [drm:gen9_set_dc_state [i915]] Setting DC state from 00 to 02 [ 123.235765] [drm:intel_power_well_disable [i915]] disabling always-on [ 123.236165] [drm:gen9_set_dc_state [i915]] Setting DC state from 02 to 00 [ 123.236189] [drm:skl_set_cdclk [i915]] Changing CDCLK to 24000 kHz (VCO 0 kHz) [ 123.247164] [drm:intel_update_cdclk [i915]] Current CD clock rate: 24000 kHz, VCO: 0 kHz, ref: 24000 kHz [ 123.247173] [drm:intel_power_well_disable [i915]] disabling MISC IO power well [ 123.247185] [drm:skl_set_power_well [i915]] Disabling MISC IO power well [ 123.247196] [drm:skl_set_power_well [i915]] Clearing auxiliary requests for MISC IO power well forced on by DMC [ 123.247206] [drm:intel_power_well_disable [i915]] disabling power well 1 [ 123.247218] [drm:skl_set_power_well [i915]] Clearing auxiliary requests for power well 1 forced on by DMC [ 123.267004] PM: late suspend of devices complete after 34.108 msecs [ 123.267296] pcieport 0000:01:00.0: System wakeup enabled by ACPI [ 123.267680] ACPI : EC: interrupt blocked [ 123.269985] xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI [ 123.306840] PM: noirq suspend of devices complete after 39.828 msecs [ 123.307682] ACPI: Preparing to enter system sleep state S3 [ 123.315722] ACPI : EC: EC stopped [ 123.315724] PM: Saving platform NVS memory [ 123.315839] Disabling non-boot CPUs ... [ 123.318501] smpboot: CPU 1 is now offline [ 123.331693] Broke affinity for irq 274 [ 123.331705] Broke affinity for irq 277 [ 123.331720] Broke affinity for irq 285 [ 123.332785] smpboot: CPU 2 is now offline [ 123.355437] Broke affinity for irq 1 [ 123.355442] Broke affinity for irq 8 [ 123.355446] Broke affinity for irq 9 [ 123.355451] Broke affinity for irq 12 [ 123.355455] Broke affinity for irq 14 [ 123.355459] Broke affinity for irq 16 [ 123.355464] Broke affinity for irq 17 [ 123.355470] Broke affinity for irq 51 [ 123.355501] Broke affinity for irq 274 [ 123.355505] Broke affinity for irq 275 [ 123.355509] Broke affinity for irq 276 [ 123.355513] Broke affinity for irq 277 [ 123.355520] Broke affinity for irq 279 [ 123.355526] Broke affinity for irq 285 [ 123.355530] Broke affinity for irq 286 [ 123.355535] Broke affinity for irq 292 [ 123.356589] smpboot: CPU 3 is now offline [ 123.378571] ACPI: Low-level resume complete [ 123.378699] ACPI : EC: EC started [ 123.378700] PM: Restoring platform NVS memory [ 123.379535] Suspended for 5.873 seconds [ 123.379610] Enabling non-boot CPUs ... [ 123.391155] x86: Booting SMP configuration: [ 123.391155] smpboot: Booting Node 0 Processor 1 APIC 0x2 [ 123.391815] cache: parent cpu1 should not be sleeping [ 123.392009] CPU1 is up [ 123.403209] smpboot: Booting Node 0 Processor 2 APIC 0x1 [ 123.404307] cache: parent cpu2 should not be sleeping [ 123.404664] CPU2 is up [ 123.427237] smpboot: Booting Node 0 Processor 3 APIC 0x3 [ 123.428231] cache: parent cpu3 should not be sleeping [ 123.428601] CPU3 is up [ 123.435784] ACPI: Waking up from system sleep state S3 [ 123.675807] acpi LNXPOWER:13: Turning OFF [ 123.675874] acpi LNXPOWER:12: Turning OFF [ 123.675934] acpi LNXPOWER:11: Turning OFF [ 123.676223] acpi LNXPOWER:10: Turning OFF [ 123.676289] acpi LNXPOWER:0f: Turning OFF [ 123.676355] acpi LNXPOWER:0e: Turning OFF [ 123.676690] acpi LNXPOWER:0d: Turning OFF [ 123.676750] acpi LNXPOWER:0c: Turning OFF [ 123.676817] acpi LNXPOWER:0b: Turning OFF [ 123.676878] acpi LNXPOWER:0a: Turning OFF [ 123.677160] acpi LNXPOWER:09: Turning OFF [ 123.677227] acpi LNXPOWER:08: Turning OFF [ 123.677293] acpi LNXPOWER:07: Turning OFF [ 123.677592] acpi LNXPOWER:06: Turning OFF [ 123.677652] acpi LNXPOWER:05: Turning OFF [ 123.677719] acpi LNXPOWER:04: Turning OFF [ 123.677995] acpi LNXPOWER:03: Turning OFF [ 123.678056] acpi LNXPOWER:02: Turning OFF [ 123.678122] acpi LNXPOWER:01: Turning OFF [ 123.678182] acpi LNXPOWER:00: Turning OFF [ 123.678506] ACPI : EC: interrupt unblocked [ 123.715584] pcieport 0000:02:02.0: System wakeup disabled by ACPI [ 123.715698] xhci_hcd 0000:00:14.0: System wakeup disabled by ACPI [ 123.715827] PM: noirq resume of devices complete after 37.463 msecs [ 123.716351] [drm:gen9_set_dc_state [i915]] Setting DC state from 00 to 00 [ 123.716387] [drm:intel_power_well_enable [i915]] enabling power well 1 [ 123.716430] [drm:intel_power_well_enable [i915]] enabling MISC IO power well [ 123.716483] [drm:skl_init_cdclk [i915]] Sanitizing cdclk programmed by pre-os [ 123.716516] [drm:skl_set_cdclk [i915]] Changing CDCLK to 337500 kHz (VCO 8100000 kHz) [ 123.718190] [drm:intel_update_cdclk [i915]] Current CD clock rate: 337500 kHz, VCO: 8100000 kHz, ref: 24000 kHz [ 123.719717] [drm:intel_power_well_enable [i915]] enabling always-on [ 123.719743] [drm:intel_power_well_enable [i915]] enabling DC off [ 123.719762] [drm:gen9_set_dc_state [i915]] Setting DC state from 00 to 00 [ 123.719791] [drm:intel_power_well_enable [i915]] enabling power well 2 [ 123.719810] [drm:intel_power_well_enable [i915]] enabling DDI A/E power well [ 123.719835] [drm:skl_set_power_well [i915]] Enabling DDI A/E power well [ 123.719853] [drm:intel_power_well_enable [i915]] enabling DDI B power well [ 123.719878] [drm:skl_set_power_well [i915]] Enabling DDI B power well [ 123.719895] [drm:intel_power_well_enable [i915]] enabling DDI C power well [ 123.719920] [drm:skl_set_power_well [i915]] Enabling DDI C power well [ 123.719937] [drm:intel_power_well_enable [i915]] enabling DDI D power well [ 123.719962] [drm:skl_set_power_well [i915]] Enabling DDI D power well [ 123.719980] [drm:gen9_set_dc_state [i915]] Setting DC state from 00 to 00 [ 123.720122] PM: early resume of devices complete after 4.070 msecs [ 123.720269] ACPI : EC: event unblocked [ 123.720642] [drm:intel_opregion_setup [i915]] graphic opregion physical addr: 0x7abf7018 [ 123.720830] [drm:intel_opregion_setup [i915]] Public ACPI methods supported [ 123.720853] [drm:intel_opregion_setup [i915]] SWSCI supported [ 123.721501] usb usb3: root hub lost power or was reset [ 123.721502] usb usb4: root hub lost power or was reset [ 123.790556] xhci_hcd 0000:00:14.0: port 3 resume PLC timeout [ 123.812532] xhci_hcd 0000:00:14.0: port 2 resume PLC timeout [ 123.812568] [drm:swsci [i915]] SWSCI request timed out [ 123.812580] [drm:swsci [i915]] SWSCI request already in progress [ 123.812591] [drm:intel_opregion_setup [i915]] SWSCI GBDA callbacks 00000001, SBCB callbacks 00000001 [ 123.812610] [drm:intel_opregion_setup [i915]] ASLE supported [ 123.812619] [drm:intel_opregion_setup [i915]] ASLE extension supported [ 123.812628] [drm:intel_opregion_setup [i915]] Found valid VBT in ACPI OpRegion (Mailbox #4) [ 123.812699] [drm:intel_dp_init_panel_power_sequencer_registers [i915]] panel power sequencer register settings: PP_ON 0x7d00001, PP_OFF 0x1f40001, PP_DIV 0x4af06 [ 123.813147] [drm:gen8_init_common_ring [i915]] Execlists enabled for render ring [ 123.813217] [drm:gen8_init_common_ring [i915]] Execlists enabled for blitter ring [ 123.813272] [drm:gen8_init_common_ring [i915]] Execlists enabled for bsd ring [ 123.813329] [drm:gen8_init_common_ring [i915]] Execlists enabled for video enhancement ring [ 123.813379] [drm:intel_guc_setup [i915]] GuC fw status: path i915/kbl_guc_ver9_14.bin, fetch NONE, load NONE [ 123.813385] [drm] GuC firmware load skipped [ 123.813403] [drm:intel_update_cdclk [i915]] Current CD clock rate: 337500 kHz, VCO: 8100000 kHz, ref: 24000 kHz [ 123.813493] [drm:intel_modeset_setup_hw_state [i915]] [CRTC:31:pipe A] hw state readout: disabled [ 123.813505] [drm:intel_modeset_setup_hw_state [i915]] [CRTC:38:pipe B] hw state readout: disabled [ 123.813515] [drm:intel_modeset_setup_hw_state [i915]] [CRTC:45:pipe C] hw state readout: disabled [ 123.813526] [drm:intel_modeset_setup_hw_state [i915]] DPLL 0 hw state readout: crtc_mask 0x00000000, on 1 [ 123.813541] [drm:intel_modeset_setup_hw_state [i915]] DPLL 1 hw state readout: crtc_mask 0x00000000, on 0 [ 123.813550] [drm:intel_modeset_setup_hw_state [i915]] DPLL 2 hw state readout: crtc_mask 0x00000000, on 0 [ 123.813558] [drm:intel_modeset_setup_hw_state [i915]] DPLL 3 hw state readout: crtc_mask 0x00000000, on 0 [ 123.813574] [drm:intel_modeset_setup_hw_state [i915]] [ENCODER:46:DDI A] hw state readout: disabled, pipe A [ 123.813586] [drm:intel_modeset_setup_hw_state [i915]] [ENCODER:55:DDI B] hw state readout: disabled, pipe A [ 123.813596] [drm:intel_modeset_setup_hw_state [i915]] [ENCODER:57:DP-MST A] hw state readout: disabled, pipe A [ 123.813605] [drm:intel_modeset_setup_hw_state [i915]] [ENCODER:58:DP-MST B] hw state readout: disabled, pipe B [ 123.813622] [drm:intel_modeset_setup_hw_state [i915]] [ENCODER:59:DP-MST C] hw state readout: disabled, pipe C [ 123.813633] [drm:intel_modeset_setup_hw_state [i915]] [ENCODER:62:DDI C] hw state readout: disabled, pipe A [ 123.813641] [drm:intel_modeset_setup_hw_state [i915]] [ENCODER:64:DP-MST A] hw state readout: disabled, pipe A [ 123.813649] [drm:intel_modeset_setup_hw_state [i915]] [ENCODER:65:DP-MST B] hw state readout: disabled, pipe B [ 123.813664] [drm:intel_modeset_setup_hw_state [i915]] [ENCODER:66:DP-MST C] hw state readout: disabled, pipe C [ 123.813672] [drm:intel_modeset_setup_hw_state [i915]] [CONNECTOR:47:eDP-1] hw state readout: disabled [ 123.813681] [drm:intel_modeset_setup_hw_state [i915]] [CONNECTOR:56:DP-1] hw state readout: disabled [ 123.813689] [drm:intel_modeset_setup_hw_state [i915]] [CONNECTOR:60:HDMI-A-1] hw state readout: disabled [ 123.813704] [drm:intel_modeset_setup_hw_state [i915]] [CONNECTOR:63:DP-2] hw state readout: disabled [ 123.813712] [drm:intel_modeset_setup_hw_state [i915]] [CONNECTOR:67:HDMI-A-2] hw state readout: disabled [ 123.813724] [drm:intel_dump_pipe_config [i915]] [CRTC:31:pipe A][setup_hw_state] [ 123.813740] [drm:intel_dump_pipe_config [i915]] cpu_transcoder: A, pipe bpp: 0, dithering: 0 [ 123.813749] [drm:intel_dump_pipe_config [i915]] audio: 0, infoframes: 0 [ 123.813758] [drm:intel_dump_pipe_config [i915]] requested mode: [ 123.813772] [drm:drm_mode_debug_printmodeline [drm]] Modeline 0:"" 0 0 0 0 0 0 0 0 0 0 0x0 0x0 [ 123.813789] [drm:intel_dump_pipe_config [i915]] adjusted mode: [ 123.813797] [drm:drm_mode_debug_printmodeline [drm]] Modeline 0:"" 0 0 0 0 0 0 0 0 0 0 0x0 0x0 [ 123.813807] [drm:intel_dump_pipe_config [i915]] crtc timings: 0 0 0 0 0 0 0 0 0, type: 0x0 flags: 0x0 [ 123.813822] [drm:intel_dump_pipe_config [i915]] port clock: 0, pipe src size: 0x0 [ 123.813831] [drm:intel_dump_pipe_config [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: 0 [ 123.813839] [drm:intel_dump_pipe_config [i915]] pch pfit: pos: 0x00000000, size: 0x00000000, disabled [ 123.813847] [drm:intel_dump_pipe_config [i915]] ips: 0, double wide: 0 [ 123.813862] [drm:intel_dump_pipe_config [i915]] dpll_hw_state: ctrl1: 0x0, cfgcr1: 0x0, cfgcr2: 0x0 [ 123.813869] [drm:intel_dump_pipe_config [i915]] planes on this crtc [ 123.813879] [drm:intel_dump_pipe_config [i915]] [PLANE:25:plane 1A] FB:70, fb = 3200x1800 format = XR24 little-endian (0x34325258) [ 123.813887] [drm:intel_dump_pipe_config [i915]] scaler:-1 src 0x0+3200+1800 dst 0x0+3200+1800 [ 123.813902] [drm:intel_dump_pipe_config [i915]] [PLANE:27:plane 2A] disabled, scaler_id = -1 [ 123.813912] [drm:intel_dump_pipe_config [i915]] [PLANE:29:cursor A] disabled, scaler_id = -1 [ 123.813925] [drm:intel_dump_pipe_config [i915]] [CRTC:38:pipe B][setup_hw_state] [ 123.813934] [drm:intel_dump_pipe_config [i915]] cpu_transcoder: B, pipe bpp: 0, dithering: 0 [ 123.813949] [drm:intel_dump_pipe_config [i915]] audio: 0, infoframes: 0 [ 123.813957] [drm:intel_dump_pipe_config [i915]] requested mode: [ 123.813964] [drm:drm_mode_debug_printmodeline [drm]] Modeline 0:"" 0 0 0 0 0 0 0 0 0 0 0x0 0x0 [ 123.813972] [drm:intel_dump_pipe_config [i915]] adjusted mode: [ 123.813985] [drm:drm_mode_debug_printmodeline [drm]] Modeline 0:"" 0 0 0 0 0 0 0 0 0 0 0x0 0x0 [ 123.813993] [drm:intel_dump_pipe_config [i915]] crtc timings: 0 0 0 0 0 0 0 0 0, type: 0x0 flags: 0x0 [ 123.814001] [drm:intel_dump_pipe_config [i915]] port clock: 0, pipe src size: 0x0 [ 123.814009] [drm:intel_dump_pipe_config [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: 0 [ 123.814017] [drm:intel_dump_pipe_config [i915]] pch pfit: pos: 0x00000000, size: 0x00000000, disabled [ 123.814031] [drm:intel_dump_pipe_config [i915]] ips: 0, double wide: 0 [ 123.814039] [drm:intel_dump_pipe_config [i915]] dpll_hw_state: ctrl1: 0x0, cfgcr1: 0x0, cfgcr2: 0x0 [ 123.814046] [drm:intel_dump_pipe_config [i915]] planes on this crtc [ 123.814054] [drm:intel_dump_pipe_config [i915]] [PLANE:32:plane 1B] disabled, scaler_id = -1 [ 123.814069] [drm:intel_dump_pipe_config [i915]] [PLANE:34:plane 2B] disabled, scaler_id = -1 [ 123.814076] [drm:intel_dump_pipe_config [i915]] [PLANE:36:cursor B] disabled, scaler_id = -1 [ 123.814085] [drm:intel_dump_pipe_config [i915]] [CRTC:45:pipe C][setup_hw_state] [ 123.814092] [drm:intel_dump_pipe_config [i915]] cpu_transcoder: C, pipe bpp: 0, dithering: 0 [ 123.814100] [drm:intel_dump_pipe_config [i915]] audio: 0, infoframes: 0 [ 123.814116] [drm:intel_dump_pipe_config [i915]] requested mode: [ 123.814123] [drm:drm_mode_debug_printmodeline [drm]] Modeline 0:"" 0 0 0 0 0 0 0 0 0 0 0x0 0x0 [ 123.814132] [drm:intel_dump_pipe_config [i915]] adjusted mode: [ 123.814138] [drm:drm_mode_debug_printmodeline [drm]] Modeline 0:"" 0 0 0 0 0 0 0 0 0 0 0x0 0x0 [ 123.814153] [drm:intel_dump_pipe_config [i915]] crtc timings: 0 0 0 0 0 0 0 0 0, type: 0x0 flags: 0x0 [ 123.814160] [drm:intel_dump_pipe_config [i915]] port clock: 0, pipe src size: 0x0 [ 123.814168] [drm:intel_dump_pipe_config [i915]] num_scalers: 1, scaler_users: 0x0, scaler_id: 0 [ 123.814175] [drm:intel_dump_pipe_config [i915]] pch pfit: pos: 0x00000000, size: 0x00000000, disabled [ 123.814183] [drm:intel_dump_pipe_config [i915]] ips: 0, double wide: 0 [ 123.814197] [drm:intel_dump_pipe_config [i915]] dpll_hw_state: ctrl1: 0x0, cfgcr1: 0x0, cfgcr2: 0x0 [ 123.814204] [drm:intel_dump_pipe_config [i915]] planes on this crtc [ 123.814212] [drm:intel_dump_pipe_config [i915]] [PLANE:39:plane 1C] disabled, scaler_id = -1 [ 123.814219] [drm:intel_dump_pipe_config [i915]] [PLANE:41:plane 2C] disabled, scaler_id = -1 [ 123.814233] [drm:intel_dump_pipe_config [i915]] [PLANE:43:cursor C] disabled, scaler_id = -1 [ 123.814245] [drm:intel_modeset_setup_hw_state [i915]] DPLL 0 enabled but not in use, disabling [ 123.814318] [drm:intel_power_well_disable [i915]] disabling DDI D power well [ 123.814327] [drm:skl_set_power_well [i915]] Disabling DDI D power well [ 123.814335] [drm:intel_power_well_disable [i915]] disabling DDI C power well [ 123.814344] [drm:skl_set_power_well [i915]] Disabling DDI C power well [ 123.814359] [drm:intel_power_well_disable [i915]] disabling DDI B power well [ 123.814367] [drm:skl_set_power_well [i915]] Disabling DDI B power well [ 123.814375] [drm:intel_power_well_disable [i915]] disabling DDI A/E power well [ 123.814384] [drm:skl_set_power_well [i915]] Disabling DDI A/E power well [ 123.814398] [drm:intel_power_well_disable [i915]] disabling power well 2 [ 123.814410] [drm:skl_set_power_well [i915]] Disabling power well 2 [ 123.814419] [drm:intel_power_well_disable [i915]] disabling DC off [ 123.814427] [drm:skl_enable_dc6 [i915]] Enabling DC6 [ 123.814443] [drm:gen9_set_dc_state [i915]] Setting DC state from 00 to 02 [ 123.814872] [drm:intel_power_well_disable [i915]] disabling always-on [ 123.814891] [drm:intel_atomic_check [i915]] [CONNECTOR:47:eDP-1] checking for sink bpp constrains [ 123.814907] [drm:intel_atomic_check [i915]] clamping display bpp (was 36) to EDID reported max of 24 [ 123.814921] [drm:intel_dp_compute_config [i915]] DP link computation with max lane count 4 max bw 540000 pixel clock 373250KHz [ 123.814940] [drm:intel_dp_compute_config [i915]] DP link bw 14 rate select 00 lane count 4 clock 540000 bpp 24 [ 123.814950] [drm:intel_dp_compute_config [i915]] DP link bw required 895800 available 1728000 [ 123.814960] [drm:intel_atomic_check [i915]] hw max bpp: 36, pipe bpp: 24, dithering: 0 [ 123.814970] [drm:intel_dump_pipe_config [i915]] [CRTC:31:pipe A][modeset] [ 123.814985] [drm:intel_dump_pipe_config [i915]] cpu_transcoder: EDP, pipe bpp: 24, dithering: 0 [ 123.814994] [drm:intel_dump_pipe_config [i915]] dp m_n: lanes: 4; gmch_m: 4348677, gmch_n: 8388608, link_m: 724779, link_n: 1048576, tu: 64 [ 123.815002] [drm:intel_dump_pipe_config [i915]] audio: 0, infoframes: 0 [ 123.815010] [drm:intel_dump_pipe_config [i915]] requested mode: [ 123.815037] [drm:drm_mode_debug_printmodeline [drm]] Modeline 0:"3200x1800" 60 373250 3200 3248 3280 3360 1800 1803 1808 1852 0x48 0xa [ 123.815048] [drm:intel_dump_pipe_config [i915]] adjusted mode: [ 123.815061] [drm:drm_mode_debug_printmodeline [drm]] Modeline 0:"3200x1800" 60 373250 3200 3248 3280 3360 1800 1803 1808 1852 0x48 0xa [ 123.815070] [drm:intel_dump_pipe_config [i915]] crtc timings: 373250 3200 3248 3280 3360 1800 1803 1808 1852, type: 0x48 flags: 0xa [ 123.815079] [drm:intel_dump_pipe_config [i915]] port clock: 540000, pipe src size: 3200x1800 [ 123.815087] [drm:intel_dump_pipe_config [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1 [ 123.815095] [drm:intel_dump_pipe_config [i915]] pch pfit: pos: 0x00000000, size: 0x00000000, disabled [ 123.815360] [drm:intel_dump_pipe_config [i915]] ips: 0, double wide: 0 [ 123.815369] [drm:intel_dump_pipe_config [i915]] dpll_hw_state: ctrl1: 0x1, cfgcr1: 0x0, cfgcr2: 0x0 [ 123.815378] [drm:intel_dump_pipe_config [i915]] planes on this crtc [ 123.815388] [drm:intel_dump_pipe_config [i915]] [PLANE:25:plane 1A] FB:70, fb = 3200x1800 format = XR24 little-endian (0x34325258) [ 123.815404] [drm:intel_dump_pipe_config [i915]] scaler:-1 src 0x0+3200+1800 dst 0x0+3200+1800 [ 123.815412] [drm:intel_dump_pipe_config [i915]] [PLANE:27:plane 2A] disabled, scaler_id = -1 [ 123.815420] [drm:intel_dump_pipe_config [i915]] [PLANE:29:cursor A] disabled, scaler_id = -1 [ 123.815431] [drm:intel_atomic_check [i915]] New cdclk calculated to be atomic 450000, actual 450000 [ 123.815452] [drm:intel_find_shared_dpll [i915]] [CRTC:31:pipe A] allocated DPLL 0 [ 123.815462] [drm:intel_reference_shared_dpll [i915]] using DPLL 0 for pipe A [ 123.815484] [drm:intel_power_well_enable [i915]] enabling always-on [ 123.815492] [drm:intel_power_well_enable [i915]] enabling DC off [ 123.815863] [drm:gen9_set_dc_state [i915]] Setting DC state from 02 to 00 [ 123.815902] [drm:intel_power_well_enable [i915]] enabling DDI A/E power well [ 123.815913] [drm:skl_set_power_well [i915]] Enabling DDI A/E power well [ 123.815923] [drm:skl_set_cdclk [i915]] Changing CDCLK to 450000 kHz (VCO 8100000 kHz) [ 123.816272] rtc_cmos 00:01: System wakeup disabled by ACPI [ 123.818346] [drm:intel_update_cdclk [i915]] Current CD clock rate: 450000 kHz, VCO: 8100000 kHz, ref: 24000 kHz [ 123.818359] [drm:intel_atomic_commit_tail [i915]] [ENCODER:46:DDI A] [ 123.818376] [drm:intel_atomic_commit_tail [i915]] [ENCODER:55:DDI B] [ 123.818405] [drm:intel_atomic_commit_tail [i915]] [ENCODER:57:DP-MST A] [ 123.818423] [drm:intel_atomic_commit_tail [i915]] [ENCODER:58:DP-MST B] [ 123.818436] [drm:intel_atomic_commit_tail [i915]] [ENCODER:59:DP-MST C] [ 123.818448] [drm:intel_atomic_commit_tail [i915]] [ENCODER:62:DDI C] [ 123.818467] [drm:intel_atomic_commit_tail [i915]] [ENCODER:64:DP-MST A] [ 123.818479] [drm:intel_atomic_commit_tail [i915]] [ENCODER:65:DP-MST B] [ 123.818490] [drm:intel_atomic_commit_tail [i915]] [ENCODER:66:DP-MST C] [ 123.818510] [drm:verify_connector_state.isra.82 [i915]] [CONNECTOR:56:DP-1] [ 123.818522] [drm:verify_connector_state.isra.82 [i915]] [CONNECTOR:60:HDMI-A-1] [ 123.818556] [drm:verify_connector_state.isra.82 [i915]] [CONNECTOR:63:DP-2] [ 123.818568] [drm:verify_connector_state.isra.82 [i915]] [CONNECTOR:67:HDMI-A-2] [ 123.818587] [drm:verify_single_dpll_state.isra.115 [i915]] DPLL 0 [ 123.818599] [drm:verify_single_dpll_state.isra.115 [i915]] DPLL 1 [ 123.818612] [drm:verify_single_dpll_state.isra.115 [i915]] DPLL 2 [ 123.818629] [drm:verify_single_dpll_state.isra.115 [i915]] DPLL 3 [ 123.818645] [drm:intel_enable_shared_dpll [i915]] enable DPLL 0 (active 1, on? 0) for crtc 31 [ 123.819044] [drm:intel_enable_shared_dpll [i915]] enabling DPLL 0 [ 123.819083] [drm:edp_panel_on [i915]] Turn eDP port A panel power on [ 123.819109] [drm:wait_panel_power_cycle [i915]] Wait for panel power cycle [ 123.819187] [drm:wait_panel_status [i915]] mask b800000f value 00000000 status 00000000 control 00000000 [ 123.819206] [drm:wait_panel_status [i915]] Wait complete [ 123.819245] [drm:edp_panel_on [i915]] Wait for panel power on [ 123.819337] [drm:wait_panel_status [i915]] mask b000000f value 80000008 status 9000000a control 00000003 [ 123.869071] [drm:intel_get_hpd_pins [i915]] hotplug event received, stat 0x01000000, dig 0x12101010, pins 0x00000010 [ 123.869105] [drm:intel_hpd_irq_handler [i915]] digital hpd port A - long [ 123.869137] [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 0 [ 123.869182] [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP port A [ 124.020054] [drm:wait_panel_status [i915]] Wait complete [ 124.020113] [drm:edp_panel_vdd_on [i915]] Turning eDP port A VDD on [ 124.020177] [drm:edp_panel_vdd_on [i915]] PP_STATUS: 0x80000008 PP_CONTROL: 0x0000000b [ 124.021308] [drm:intel_dp_set_signal_levels [i915]] Using signal levels 00000000 [ 124.021317] [drm:intel_dp_set_signal_levels [i915]] Using vswing level 0 [ 124.021326] [drm:intel_dp_set_signal_levels [i915]] Using pre-emphasis level 0 [ 124.021338] [drm:intel_dp_program_link_training_pattern [i915]] Using DP training pattern TPS1 [ 124.022022] [drm:intel_dp_start_link_train [i915]] clock recovery OK [ 124.022031] [drm:intel_dp_start_link_train [i915]] 5.4 Gbps link rate without sink TPS3 support [ 124.022045] [drm:intel_dp_program_link_training_pattern [i915]] Using DP training pattern TPS2 [ 124.023022] [drm:intel_dp_set_signal_levels [i915]] Using signal levels 08000000 [ 124.023037] [drm:intel_dp_set_signal_levels [i915]] Using vswing level 2 [ 124.023045] [drm:intel_dp_set_signal_levels [i915]] Using pre-emphasis level 1 [ 124.024026] [drm:intel_dp_start_link_train [i915]] Channel EQ done. DP Training successful [ 124.024223] [drm:skylake_pfit_enable [i915]] for crtc_state = ffff943f656af000 [ 124.024532] [drm:intel_enable_pipe [i915]] enabling pipe A [ 124.024569] [drm:intel_edp_backlight_on.part.27 [i915]] [ 124.024578] [drm:intel_panel_enable_backlight [i915]] pipe A [ 124.024653] [drm:intel_panel_actually_set_backlight [i915]] set backlight PWM = 798 [ 124.031080] [drm:intel_psr_enable [i915]] PSR disable by flag [ 124.031089] [drm:intel_enable_ddi [i915]] Panel doesn't support DRRS [ 124.041332] [drm:verify_connector_state.isra.82 [i915]] [CONNECTOR:47:eDP-1] [ 124.041348] [drm:intel_atomic_commit_tail [i915]] [CRTC:31:pipe A] [ 124.041383] [drm:verify_single_dpll_state.isra.115 [i915]] DPLL 0 [ 124.041397] [drm:intel_atomic_commit_tail [i915]] [CRTC:38:pipe B] [ 124.041413] [drm:intel_atomic_commit_tail [i915]] [CRTC:45:pipe C] [ 124.041502] [drm:intel_opregion_register [i915]] 5 outputs detected [ 124.041517] [drm:intel_dp_detect [i915]] [CONNECTOR:47:eDP-1] [ 124.041526] [drm:intel_dp_detect [i915]] Display Port TPS3 support: source yes, sink no [ 124.041543] [drm:intel_dp_print_rates [i915]] source rates: 162000, 216000, 270000, 324000, 432000, 540000 [ 124.041551] [drm:intel_dp_print_rates [i915]] sink rates: 162000, 270000, 540000 [ 124.041560] [drm:intel_dp_print_rates [i915]] common rates: 162000, 270000, 540000 [ 124.042011] [drm:intel_dp_read_desc [i915]] DP sink: OUI 38-ec-11(NS) dev-ID HW-rev 0.0 SW-rev 0.0 [ 124.042390] [drm:drm_helper_hpd_irq_event [drm_kms_helper]] [CONNECTOR:47:eDP-1] status updated from connected to connected [ 124.042406] [drm:intel_dp_detect [i915]] [CONNECTOR:56:DP-1] [ 124.042414] [drm:intel_power_well_enable [i915]] enabling power well 2 [ 124.042423] [drm:skl_set_power_well [i915]] Enabling power well 2 [ 124.042467] [drm:intel_power_well_disable [i915]] disabling power well 2 [ 124.042507] [drm:skl_set_power_well [i915]] Disabling power well 2 [ 124.042512] [drm:drm_helper_hpd_irq_event [drm_kms_helper]] [CONNECTOR:56:DP-1] status updated from disconnected to disconnected [ 124.042522] [drm:intel_hdmi_detect [i915]] [CONNECTOR:60:HDMI-A-1] [ 124.044710] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0050 w(1) [ 124.044722] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry [ 124.046911] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0050 w(1) [ 124.046929] [drm:drm_do_probe_ddc_edid [drm]] drm: skipping non-existent adapter i915 gmbus dpb [ 124.049104] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0040 w(1) [ 124.049115] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry [ 124.051219] usb 1-4: reset full-speed USB device number 3 using xhci_hcd [ 124.051309] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0040 w(1) [ 124.051314] [drm:drm_dp_dual_mode_detect [drm_kms_helper]] DP dual mode HDMI ID: (err -6) [ 124.051317] [drm:drm_helper_hpd_irq_event [drm_kms_helper]] [CONNECTOR:60:HDMI-A-1] status updated from disconnected to disconnected [ 124.051343] [drm:intel_dp_detect [i915]] [CONNECTOR:63:DP-2] [ 124.051352] [drm:intel_power_well_enable [i915]] enabling power well 2 [ 124.051362] [drm:skl_set_power_well [i915]] Enabling power well 2 [ 124.051434] [drm:intel_power_well_disable [i915]] disabling power well 2 [ 124.051476] [drm:skl_set_power_well [i915]] Disabling power well 2 [ 124.051486] [drm:drm_helper_hpd_irq_event [drm_kms_helper]] [CONNECTOR:63:DP-2] status updated from disconnected to disconnected [ 124.051496] [drm:intel_hdmi_detect [i915]] [CONNECTOR:67:HDMI-A-2] [ 124.053671] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpc] NAK for addr: 0050 w(1) [ 124.053682] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpc] NAK on first message, retry [ 124.055862] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpc] NAK for addr: 0050 w(1) [ 124.055870] [drm:drm_do_probe_ddc_edid [drm]] drm: skipping non-existent adapter i915 gmbus dpc [ 124.058051] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpc] NAK for addr: 0040 w(1) [ 124.058062] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpc] NAK on first message, retry [ 124.060242] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpc] NAK for addr: 0040 w(1) [ 124.060246] [drm:drm_dp_dual_mode_detect [drm_kms_helper]] DP dual mode HDMI ID: (err -6) [ 124.060250] [drm:drm_helper_hpd_irq_event [drm_kms_helper]] [CONNECTOR:67:HDMI-A-2] status updated from disconnected to disconnected [ 124.311278] usb 1-3: reset full-speed USB device number 2 using xhci_hcd [ 124.571242] usb 1-5: reset high-speed USB device number 4 using xhci_hcd [ 125.847248] [drm] RC6 on [ 126.015310] ath10k_pci 0000:3a:00.0: failed to set coverage class: expected slot time of 9 or 20us in HW register. It is 0us. [ 126.026877] PM: resume of devices complete after 2306.767 msecs [ 126.027223] usb 1-3:1.0: rebind failed: -517 [ 126.027224] usb 1-3:1.1: rebind failed: -517 [ 126.027871] PM: Finishing wakeup. [ 126.027873] Restarting tasks ... [ 126.028167] pci_bus 0000:02: Allocating resources [ 126.028206] pcieport 0000:02:01.0: bridge window [io 0x1000-0x0fff] to [bus 04-38] add_size 1000 [ 126.028214] pcieport 0000:02:02.0: bridge window [io 0x1000-0x0fff] to [bus 39] add_size 1000 [ 126.028216] pcieport 0000:02:02.0: bridge window [mem 0x00100000-0x000fffff 64bit pref] to [bus 39] add_size 200000 add_align 100000 [ 126.028225] pcieport 0000:02:01.0: res[13]=[io 0x1000-0x0fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028226] pcieport 0000:02:02.0: res[13]=[io 0x1000-0x0fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028233] pcieport 0000:01:00.0: bridge window [io 0x1000-0x0fff] to [bus 02-39] add_size 2000 [ 126.028235] pcieport 0000:01:00.0: res[13]=[io 0x1000-0x0fff] res_to_dev_res add_size 2000 min_align 1000 [ 126.028236] pcieport 0000:01:00.0: res[13]=[io 0x1000-0x2fff] res_to_dev_res add_size 2000 min_align 1000 [ 126.028238] pcieport 0000:01:00.0: BAR 13: no space for [io size 0x2000] [ 126.028239] pcieport 0000:01:00.0: BAR 13: failed to assign [io size 0x2000] [ 126.028240] pcieport 0000:01:00.0: BAR 13: no space for [io size 0x2000] [ 126.028241] pcieport 0000:01:00.0: BAR 13: failed to assign [io size 0x2000] [ 126.028243] pcieport 0000:02:02.0: res[15]=[mem 0x00100000-0x000fffff 64bit pref] res_to_dev_res add_size 200000 min_align 100000 [ 126.028244] pcieport 0000:02:02.0: res[15]=[mem 0x00100000-0x002fffff 64bit pref] res_to_dev_res add_size 200000 min_align 100000 [ 126.028246] pcieport 0000:02:01.0: res[13]=[io 0x1000-0x0fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028247] pcieport 0000:02:01.0: res[13]=[io 0x1000-0x1fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028248] pcieport 0000:02:02.0: res[13]=[io 0x1000-0x0fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028249] pcieport 0000:02:02.0: res[13]=[io 0x1000-0x1fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028251] pcieport 0000:02:02.0: BAR 15: no space for [mem size 0x00200000 64bit pref] [ 126.028252] pcieport 0000:02:02.0: BAR 15: failed to assign [mem size 0x00200000 64bit pref] [ 126.028253] pcieport 0000:02:01.0: BAR 13: no space for [io size 0x1000] [ 126.028254] pcieport 0000:02:01.0: BAR 13: failed to assign [io size 0x1000] [ 126.028255] pcieport 0000:02:02.0: BAR 13: no space for [io size 0x1000] [ 126.028256] pcieport 0000:02:02.0: BAR 13: failed to assign [io size 0x1000] [ 126.028258] pcieport 0000:02:02.0: BAR 15: no space for [mem size 0x00200000 64bit pref] [ 126.028258] pcieport 0000:02:02.0: BAR 15: failed to assign [mem size 0x00200000 64bit pref] [ 126.028259] pcieport 0000:02:02.0: BAR 13: no space for [io size 0x1000] [ 126.028260] pcieport 0000:02:02.0: BAR 13: failed to assign [io size 0x1000] [ 126.028261] pcieport 0000:02:01.0: BAR 13: no space for [io size 0x1000] [ 126.028261] pcieport 0000:02:01.0: BAR 13: failed to assign [io size 0x1000] [ 126.028812] pci_bus 0000:02: Allocating resources [ 126.028853] pcieport 0000:02:01.0: bridge window [io 0x1000-0x0fff] to [bus 04-38] add_size 1000 [ 126.028862] pcieport 0000:02:02.0: bridge window [io 0x1000-0x0fff] to [bus 39] add_size 1000 [ 126.028863] pcieport 0000:02:02.0: bridge window [mem 0x00100000-0x000fffff 64bit pref] to [bus 39] add_size 200000 add_align 100000 [ 126.028872] pcieport 0000:02:01.0: res[13]=[io 0x1000-0x0fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028873] pcieport 0000:02:02.0: res[13]=[io 0x1000-0x0fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028874] pcieport 0000:01:00.0: bridge window [io 0x1000-0x0fff] to [bus 02-39] add_size 2000 [ 126.028876] pcieport 0000:01:00.0: res[13]=[io 0x1000-0x0fff] res_to_dev_res add_size 2000 min_align 1000 [ 126.028877] pcieport 0000:01:00.0: res[13]=[io 0x1000-0x2fff] res_to_dev_res add_size 2000 min_align 1000 [ 126.028879] pcieport 0000:01:00.0: BAR 13: no space for [io size 0x2000] [ 126.028880] pcieport 0000:01:00.0: BAR 13: failed to assign [io size 0x2000] [ 126.028881] pcieport 0000:01:00.0: BAR 13: no space for [io size 0x2000] [ 126.028882] pcieport 0000:01:00.0: BAR 13: failed to assign [io size 0x2000] [ 126.028884] pcieport 0000:02:02.0: res[15]=[mem 0x00100000-0x000fffff 64bit pref] res_to_dev_res add_size 200000 min_align 100000 [ 126.028885] pcieport 0000:02:02.0: res[15]=[mem 0x00100000-0x002fffff 64bit pref] res_to_dev_res add_size 200000 min_align 100000 [ 126.028892] pcieport 0000:02:01.0: res[13]=[io 0x1000-0x0fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028893] pcieport 0000:02:01.0: res[13]=[io 0x1000-0x1fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028894] pcieport 0000:02:02.0: res[13]=[io 0x1000-0x0fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028895] pcieport 0000:02:02.0: res[13]=[io 0x1000-0x1fff] res_to_dev_res add_size 1000 min_align 1000 [ 126.028898] pcieport 0000:02:02.0: BAR 15: no space for [mem size 0x00200000 64bit pref] [ 126.028899] pcieport 0000:02:02.0: BAR 15: failed to assign [mem size 0x00200000 64bit pref] [ 126.028900] pcieport 0000:02:01.0: BAR 13: no space for [io size 0x1000] [ 126.028901] pcieport 0000:02:01.0: BAR 13: failed to assign [io size 0x1000] [ 126.028902] pcieport 0000:02:02.0: BAR 13: no space for [io size 0x1000] [ 126.028903] pcieport 0000:02:02.0: BAR 13: failed to assign [io size 0x1000] [ 126.028904] pcieport 0000:02:02.0: BAR 15: no space for [mem size 0x00200000 64bit pref] [ 126.028905] pcieport 0000:02:02.0: BAR 15: failed to assign [mem size 0x00200000 64bit pref] [ 126.028906] pcieport 0000:02:02.0: BAR 13: no space for [io size 0x1000] [ 126.028907] pcieport 0000:02:02.0: BAR 13: failed to assign [io size 0x1000] [ 126.028908] pcieport 0000:02:01.0: BAR 13: no space for [io size 0x1000] [ 126.028909] pcieport 0000:02:01.0: BAR 13: failed to assign [io size 0x1000] [ 126.046967] done. [ 126.394266] wlp58s0: authenticate with 6c:f3:7f:10:a0:f8 ```
Could you re-run analyze_suspend.py, but with the following parameters: analyze_suspend.py config/suspend-callgraph.cfg -filter i915 Without a callgraph the suspend log is pretty much useless (and without filtering it'll be far too large to process).
Created attachment 129386 [details] Output file from `xps13_mem_dmesg.txt` (In reply to David Weinehall from comment #1) > Could you re-run analyze_suspend.py, but with the following parameters: > > analyze_suspend.py config/suspend-callgraph.cfg -filter i915 […] Sure. The switch `-config` has to be added. ``` $ sudo ./analyze_suspend.py -config config/suspend-callgraph.cfg -filter i915 ``` Please note, the system freezes on resume, when run from the GNOME Terminal in the GNOME Shell (with GNOME Shell shown, but mouse cursor not moving). Switch to the virtual tty2, the system goes further. The resulting file is 691 MB big, so that I am unable to attach it, even if I wanted to. You can download it from [1]. Please tell me, if you need anything else. [1] https://www.molgen.mpg.de/~pmenzel/suspend-xps13-170207-142236-cg/xps13_mem_ftrace.txt`
Sorry for missing the -config bit. Yeah, the ftrace log is unfiltered, so it's indeed huge; I only need the html (which is filtered and should be in the order of 3-10MB).
(In reply to David Weinehall from comment #3) > Yeah, the ftrace log is unfiltered, so it's indeed huge; I only need the > html (which is filtered and should be in the order of 3-10MB). Only the following two files `xps13_mem_dmesg.txt` and `xps13_mem_ftrace.txt` are present in the folder. I am using `analyze_suspend.py` from the git repository.
The latest from here, I assume: https://github.com/01org/suspendresume.git For me that generates a file named <machine>_mem.html in the same directory as the <machine>_mem_ftrace.txt and <machine>_mem_dmesg.txt files.
Created attachment 129393 [details] HTML output of `analyze_suspend.py -config config/… -filter i915` This time it worked. I take the other file offline.
Something seems to be really wrong with that graph you posted (suspend only taking 0.011ms)--or did you filter these figures to only contain resume time? Anyhow, let's start with the low-hanging fruit: The 206ms spent in skl_update_crtcs() is the VBT-mandated panel on-timeout (200ms) + DP link training. There's also cdclk programming which takes a few milliseconds. This covers intel_display_resume(), which is the biggest "culprit". The ~16ms schedule_timeout() is where we wait for vblank before programming vblanks; that section is covered by a FIXME and a TODO, so that bit is a known issue. The remaining slow-poke is intel_opregion_setup() (63ms). I must admit that I cannot explain that slowdown without diving further into the code; our kabylake here does not exhibit this behaviour; I just ran a test on a machine in our lab--that function took roughly 6ms.
(In reply to David Weinehall from comment #7) […] > The remaining slow-poke is intel_opregion_setup() (63ms). I must admit that > I cannot explain that slowdown without diving further into the code; our > kabylake here does not exhibit this behaviour; I just ran a test on a > machine in our lab--that function took roughly 6ms. Len Brown, and the Intel ACPI folks should have such a device. Do you have access to that? Maybe Dell can give you access to such a device? Mario, is that possible to ship the Intel Open Source Technology Center such a device?
(In reply to David Weinehall from comment #7) > Something seems to be really wrong with that graph you posted (suspend only > taking 0.011ms)--or did you filter these figures to only contain resume time? Indeed. Something seems off. I didn’t do anything besides running the script. It looks like there is a bug. > Anyhow, let's start with the low-hanging fruit: > > The 206ms spent in skl_update_crtcs() is the VBT-mandated panel on-timeout > (200ms) + DP link training. There's also cdclk programming which takes a few > milliseconds. This covers intel_display_resume(), which is the biggest > "culprit". Indeed. What are the options to improve that? My first naive and ignorant thought would be, on a laptop, and even desktop systems, the display doesn’t change during suspend/resume. So can this be cached, and those values tried first? […]
(In reply to Paul Menzel from comment #8) > (In reply to David Weinehall from comment #7) > > […] > > > The remaining slow-poke is intel_opregion_setup() (63ms). I must admit that > > I cannot explain that slowdown without diving further into the code; our > > kabylake here does not exhibit this behaviour; I just ran a test on a > > machine in our lab--that function took roughly 6ms. > > Len Brown, and the Intel ACPI folks should have such a device. Do you have > access to that? At least not physically; Len & the rest of the ACPI folks are located at another site. I'm located at the Espoo site in Finland. > > Maybe Dell can give you access to such a device? Mario, is that possible to > ship the Intel Open Source Technology Center such a device?
(In reply to Paul Menzel from comment #9) > (In reply to David Weinehall from comment #7) > > Something seems to be really wrong with that graph you posted (suspend only > > taking 0.011ms)--or did you filter these figures to only contain resume time? > > Indeed. Something seems off. I didn’t do anything besides running the > script. It looks like there is a bug. > > > Anyhow, let's start with the low-hanging fruit: > > > > The 206ms spent in skl_update_crtcs() is the VBT-mandated panel on-timeout > > (200ms) + DP link training. There's also cdclk programming which takes a few > > milliseconds. This covers intel_display_resume(), which is the biggest > > "culprit". > > Indeed. What are the options to improve that? My first naive and ignorant > thought would be, on a laptop, and even desktop systems, the display doesn’t > change during suspend/resume. So can this be cached, and those values tried > first? > > […] Sadly the news about the VESA timeouts are rather bad; according to spec it's not permitted to run the timeouts in parallel, nor can they be skipped. The link training can possibly be cached, but for eDP this is just a short pulse anyway, so the time saving would be fairly minimal. Looking at complete suspend/resume logs (without other drivers filtered out) from other machines it seems that the i915 driver is the blocking factor on suspend, but not on resume; other drivers (notably the USB subsystem) take far longer to resume; since driver suspend, and driver resume, happens in parallel between most drivers, we don't benefit all that much at the moment from trying to "cheat" by making the i915 resume asynchronously; no matter if we resume in the normal way or if we do it asynchronously it'll still take as long to get to a point where the system can use the driver again. As I analysed in another bug, slowdowns in intel_opregion_setup() seem to be caused by slow replies from the BIOS when reading the GBDA. All in all we're looking at: 322ms - 206ms (panel timeout) - (64 - 6)ms (opregion adjusted for a "normally slow" read) = 58ms. This is a perfectly reasonable resume time, well on par with what is to be expected. To shorten the panel timeout delay you'll need a different panel (or the VBT timings adjusted for the panel you have; don't go around overriding these timeouts without full knowledge of what the specs of the panel is though). To fix the opregion slowdown you'll most likely either need another BIOS (and I mean another; it's unlikely that slow reads from BIOS is something that a typical BIOS upgrade would fix) or other hardware (depending on where the slowdown is). If you aren't worried about runtime power consumption (but since this is a laptop you probably are) you could try removing/renaming the DMC firmware, which will save you the 4.5ms it takes to load that firmware). Finally you should be aware that as soon as the HuC firmware is available on your system the driver will load it, which means that you'll see another slowdown on the order of 30ms or so; if you do not need hardware optimisation for HEVC you might want to remove/rename that file too. Long story short: nothing in this log seems to indicate that we're spending too much time resuming in our driver. Believe me, I'd love to find things that could improve the suspend/resume times.
I changed the bug title, to make this issue about the resume time, as resume was the only thing discussed here. Please use bug #104856 [1] to discuss the suspend time. [1] https://bugs.freedesktop.org/show_bug.cgi?id=104856
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.