Stdout
Using IGT_SRANDOM=1717561199 for randomisation
Opened device: /dev/dri/card0
Starting subtest: s4-basic
Stack trace:
#0 ../../../usr/src/igt-gpu-tools/lib/igt_core.c:1988 __igt_fail_assert()
#1 ../../../usr/src/igt-gpu-tools/lib/igt_aux.c:803 igt_system_suspend_autoresume()
#2 ../../../usr/src/igt-gpu-tools/tests/intel/xe_pm.c:721 __igt_unique____real_main669()
#3 ../../../usr/src/igt-gpu-tools/tests/intel/xe_pm.c:669 main()
#4 [__libc_start_main+0xf3]
#5 [_start+0x2e]
Subtest s4-basic: FAIL (4.936s)
Stderr
Starting subtest: s4-basic
(xe_pm:3265) igt_aux-CRITICAL: Test assertion failure function suspend_via_sysfs, file ../../../usr/src/igt-gpu-tools/lib/igt_aux.c:834:
(xe_pm:3265) igt_aux-CRITICAL: Failed assertion: igt_sysfs_set(power_dir, "state", suspend_state_name[state])
(xe_pm:3265) igt_aux-CRITICAL: Last errno: 16, Device or resource busy
Subtest s4-basic failed.
**** DEBUG ****
(xe_pm:3265) igt_aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
(xe_pm:3265) igt_aux-DEBUG: Test requirement passed: is_state_supported(power_dir, state)
(xe_pm:3265) igt_aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
(xe_pm:3265) igt_aux-DEBUG: Test requirement passed: !(state == SUSPEND_STATE_DISK && !igt_get_total_swap_mb())
(xe_pm:3265) igt_aux-CRITICAL: Test assertion failure function suspend_via_sysfs, file ../../../usr/src/igt-gpu-tools/lib/igt_aux.c:834:
(xe_pm:3265) igt_aux-CRITICAL: Failed assertion: igt_sysfs_set(power_dir, "state", suspend_state_name[state])
(xe_pm:3265) igt_aux-CRITICAL: Last errno: 16, Device or resource busy
(xe_pm:3265) igt_core-INFO: Stack trace:
(xe_pm:3265) igt_core-INFO: #0 ../../../usr/src/igt-gpu-tools/lib/igt_core.c:1988 __igt_fail_assert()
(xe_pm:3265) igt_core-INFO: #1 ../../../usr/src/igt-gpu-tools/lib/igt_aux.c:803 igt_system_suspend_autoresume()
(xe_pm:3265) igt_core-INFO: #2 ../../../usr/src/igt-gpu-tools/tests/intel/xe_pm.c:721 __igt_unique____real_main669()
(xe_pm:3265) igt_core-INFO: #3 ../../../usr/src/igt-gpu-tools/tests/intel/xe_pm.c:669 main()
(xe_pm:3265) igt_core-INFO: #4 [__libc_start_main+0xf3]
(xe_pm:3265) igt_core-INFO: #5 [_start+0x2e]
**** END ****
Subtest s4-basic: FAIL (4.936s)
Dmesg
<7> [416.927300] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off
<7> [416.927430] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6
<7> [416.927490] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02
<6> [416.958593] Console: switching to colour dummy device 80x25
<6> [416.958894] [IGT] xe_pm: executing
<6> [417.098355] [IGT] xe_pm: starting subtest s4-basic
<6> [417.099042] PM: hibernation: hibernation entry
<6> [417.111375] Filesystems sync: 0.011 seconds
<6> [417.112173] Freezing user space processes
<6> [417.115839] Freezing user space processes completed (elapsed 0.003 seconds)
<6> [417.115862] OOM killer disabled.
<7> [417.117863] PM: hibernation: Marking nosave pages: [mem 0x00000000-0x00000fff]
<7> [417.117876] PM: hibernation: Marking nosave pages: [mem 0x0009f000-0x000fffff]
<7> [417.117895] PM: hibernation: Marking nosave pages: [mem 0x699f0000-0x69a0afff]
<7> [417.117901] PM: hibernation: Marking nosave pages: [mem 0x69a0f000-0x69a0ffff]
<7> [417.117903] PM: hibernation: Marking nosave pages: [mem 0x6cace000-0x6fffefff]
<7> [417.119519] PM: hibernation: Marking nosave pages: [mem 0x70000000-0x1043fffff]
<7> [417.178821] PM: hibernation: Basic memory bitmaps created
<6> [417.179898] PM: hibernation: Preallocating image memory
<7> [418.671333] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 turning VDD off
<7> [418.671462] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067
<6> [420.295870] PM: hibernation: Allocated 560635 pages for snapshot
<6> [420.295878] PM: hibernation: Allocated 2242540 kbytes in 3.11 seconds (721.07 MB/s)
<6> [420.295881] Freezing remaining freezable tasks
<6> [420.298323] Freezing remaining freezable tasks completed (elapsed 0.002 seconds)
<6> [420.419065] r8169 0000:7f:00.0 enp127s0: Link is Down
<7> [420.423173] xe 0000:00:02.0: [drm:xe_pm_suspend [xe]] Suspending device
<7> [420.423605] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off
<7> [420.424117] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00
<7> [420.424196] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2
<7> [420.424332] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B
<7> [420.424576] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_C
<7> [420.424702] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_D
<7> [420.424792] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PICA_TC
<7> [420.425269] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [420.425273] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [420.425275] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [420.425277] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in lane_count (expected 4, found 0)
<7> [420.425281] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 8355985/8388608 link 696332/524288, found tu 0, data 0/0 link 0/0)
<7> [420.425284] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)
<7> [420.425287] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [420.425289] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 3840, found 0)
<7> [420.425290] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3920, found 0)
<7> [420.425292] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 3840, found 0)
<7> [420.425293] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3920, found 0)
<7> [420.425295] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 3888, found 0)
<7> [420.425296] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 3920, found 0)
<7> [420.425298] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 2160, found 0)
<7> [420.425299] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 2160, found 0)
<7> [420.425301] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 2163, found 0)
<7> [420.425302] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 2168, found 0)
<7> [420.425304] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 2287, found 0)
<7> [420.425306] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 2287, found 0)
<7> [420.425307] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 3840, found 0)
<7> [420.425309] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3920, found 0)
<7> [420.425310] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 3840, found 0)
<7> [420.425312] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3920, found 0)
<7> [420.425313] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 3888, found 0)
<7> [420.425315] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 3920, found 0)
<7> [420.425316] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 2160, found 0)
<7> [420.425318] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 2160, found 0)
<7> [420.425319] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 2163, found 0)
<7> [420.425321] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 2168, found 0)
<7> [420.425323] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 2287, found 0)
<7> [420.425324] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 2287, found 0)
<7> [420.425326] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [420.425327] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0)
<7> [420.425329] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [420.425333] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [420.425335] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 1075800, found 0)
<7> [420.425336] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 1075800, found 0)
<7> [420.425338] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in port_clock (expected 810000, found 0)
<7> [420.425339] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] fastset requirement not met in min_voltage_level (expected 1, found 0)
<7> [420.425343] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset
<7> [420.425466] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no
<7> [420.425512] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:82:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0
<7> [420.425608] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:32:plane 1A] ddb ( 0 - 4008) -> ( 0 - 0), size 4008 -> 0
<7> [420.425655] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:77:cursor A] ddb (4008 - 4096) -> ( 0 - 0), size 88 -> 0
<7> [420.425692] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:32:plane 1A] level *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm
<7> [420.425730] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:32:plane 1A] lines 2, 22, 22, 22, 20, 26, 0, 0, 0, 6, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [420.425766] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:32:plane 1A] blocks 63, 683, 683, 683, 621, 807, 0, 0, 77, 187, 201 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [420.425801] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:32:plane 1A] min_ddb 71, 753, 753, 753, 685, 889, 0, 0, 78, 207, 207 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [420.425836] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:82:pipe A] data rate 0 num active planes 0
<7> [420.425895] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400
<7> [420.425948] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400
<7> [420.426001] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400
<7> [420.426052] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400
<7> [420.426103] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0
<7> [420.426158] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via crawling and squashing
<7> [420.426210] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz
<7> [420.426262] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 0, actual 0
<7> [420.426336] xe 0000:00:02.0: [drm] [CRTC:82:pipe A] enable: no [modeset]
<7> [420.426339] xe 0000:00:02.0: [drm] [PLANE:32:plane 1A] fb: [NOFB], visible: no
<7> [420.426341] xe 0000:00:02.0: [drm] [PLANE:41:plane 2A] fb: [NOFB], visible: no
<7> [420.426342] xe 0000:00:02.0: [drm] [PLANE:50:plane 3A] fb: [NOFB], visible: no
<7> [420.426344] xe 0000:00:02.0: [drm] [PLANE:59:plane 4A] fb: [NOFB], visible: no
<7> [420.426345] xe 0000:00:02.0: [drm] [PLANE:68:plane 5A] fb: [NOFB], visible: no
<7> [420.426347] xe 0000:00:02.0: [drm] [PLANE:77:cursor A] fb: [NOFB], visible: no
<7> [420.426423] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR1
<7> [420.435409] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 turning VDD on
<7> [420.435763] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006f
<7> [420.440413] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]]
<7> [420.647618] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:189:eDP-1] set backlight PWM = 0
<7> [420.648954] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A
<7> [420.659842] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 turn panel power off
<7> [420.660434] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 wait for panel power off time
<7> [420.660853] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060
<7> [420.744249] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete
<7> [420.744810] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A
<7> [420.745215] xe 0000:00:02.0: [drm:__intel_fbc_disable [xe]] Disabling FBC on [PLANE:32:plane 1A]
<7> [420.746059] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:188:DDI A/PHY A]
<7> [420.746352] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:197:DDI TC1/PHY TC1]
<7> [420.746577] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:199:DP-MST A]
<7> [420.746780] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:200:DP-MST B]
<7> [420.746957] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:201:DP-MST C]
<7> [420.747103] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:209:DDI TC2/PHY TC2]
<7> [420.747309] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:211:DP-MST A]
<7> [420.747441] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:212:DP-MST B]
<7> [420.747561] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DP-MST C]
<7> [420.747663] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DDI TC3/PHY TC3]
<7> [420.747759] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:219:DP-MST A]
<7> [420.747847] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:220:DP-MST B]
<7> [420.747928] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:221:DP-MST C]