igt@kms_flip@flip-vs-expired-vblank@b-vga1 on shard-snb@IGTPW

Detail	Value
Duration	0.99 seconds
Hostname	shard-snb4
Igt-Version	IGT-Version: 2.4-g3437934c1 (x86_64) (Linux: 7.0.0-CI_DRM_18350-g898b5aa235c5+ x86_64)
Out	Starting dynamic subtest: B-VGA1 1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-VGA1: FAIL (0.986s)
Err	Starting dynamic subtest: B-VGA1 (kms_flip:2766) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2766) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-VGA1 failed. ** DEBUG (kms_flip:2766) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x100000000000001, size=0) (kms_flip:2766) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2766) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2766) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=4096) (kms_flip:2766) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:2766) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x100000000000001, size=0) (kms_flip:2766) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2766) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2766) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=4096) (kms_flip:2766) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:2766) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2766) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2766) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS (kms_flip:2766) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2766) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2766) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS (kms_flip:2766) igt_kms-INFO: 1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa (kms_flip:2766) DEBUG: No stale events found (kms_flip:2766) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 (kms_flip:2766) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 (kms_flip:2766) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 315.136047 current_received_ts = 315.135498 current_seq = 11376 count = 0 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 7us (kms_flip:2766) DEBUG: name = flip last_ts = 315.136047 last_received_ts = 315.135498 last_seq = 11376 current_ts = 315.152771 current_received_ts = 315.152191 current_seq = 11377 count = 1 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.152771 last_received_ts = 315.152191 last_seq = 11377 current_ts = 315.169495 current_received_ts = 315.168915 current_seq = 11378 count = 2 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 7us (kms_flip:2766) DEBUG: name = flip last_ts = 315.169495 last_received_ts = 315.168915 last_seq = 11378 current_ts = 315.186188 current_received_ts = 315.185638 current_seq = 11379 count = 3 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.186188 last_received_ts = 315.185638 last_seq = 11379 current_ts = 315.202911 current_received_ts = 315.202332 current_seq = 11380 count = 4 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.202911 last_received_ts = 315.202332 last_seq = 11380 current_ts = 315.219635 current_received_ts = 315.219116 current_seq = 11381 count = 5 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 9us (kms_flip:2766) DEBUG: name = flip last_ts = 315.219635 last_received_ts = 315.219116 last_seq = 11381 current_ts = 315.236359 current_received_ts = 315.235809 current_seq = 11382 count = 6 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.236359 last_received_ts = 315.235809 last_seq = 11382 current_ts = 315.253052 current_received_ts = 315.252502 current_seq = 11383 count = 7 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.253052 last_received_ts = 315.252502 last_seq = 11383 current_ts = 315.269775 current_received_ts = 315.269226 current_seq = 11384 count = 8 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.269775 last_received_ts = 315.269226 last_seq = 11384 current_ts = 315.286499 current_received_ts = 315.285950 current_seq = 11385 count = 9 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.286499 last_received_ts = 315.285950 last_seq = 11385 current_ts = 315.303223 current_received_ts = 315.302643 current_seq = 11386 count = 10 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.303223 last_received_ts = 315.302643 last_seq = 11386 current_ts = 315.319946 current_received_ts = 315.319366 current_seq = 11387 count = 11 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.319946 last_received_ts = 315.319366 last_seq = 11387 current_ts = 315.336639 current_received_ts = 315.336090 current_seq = 11388 count = 12 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.336639 last_received_ts = 315.336090 last_seq = 11388 current_ts = 315.353363 current_received_ts = 315.352814 current_seq = 11389 count = 13 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.353363 last_received_ts = 315.352814 last_seq = 11389 current_ts = 315.370087 current_received_ts = 315.369507 current_seq = 11390 count = 14 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.370087 last_received_ts = 315.369507 last_seq = 11390 current_ts = 315.386810 current_received_ts = 315.386230 current_seq = 11391 count = 15 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 7us (kms_flip:2766) DEBUG: name = flip last_ts = 315.386810 last_received_ts = 315.386230 last_seq = 11391 current_ts = 315.403503 current_received_ts = 315.402954 current_seq = 11392 count = 16 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 7us (kms_flip:2766) DEBUG: name = flip last_ts = 315.403503 last_received_ts = 315.402954 last_seq = 11392 current_ts = 315.420227 current_received_ts = 315.419678 current_seq = 11393 count = 17 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 9us (kms_flip:2766) DEBUG: name = flip last_ts = 315.420227 last_received_ts = 315.419678 last_seq = 11393 current_ts = 315.436951 current_received_ts = 315.436371 current_seq = 11394 count = 18 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.436951 last_received_ts = 315.436371 last_seq = 11394 current_ts = 315.453674 current_received_ts = 315.453125 current_seq = 11395 count = 19 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.453674 last_received_ts = 315.453125 last_seq = 11395 current_ts = 315.470367 current_received_ts = 315.469849 current_seq = 11396 count = 20 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.470367 last_received_ts = 315.469849 last_seq = 11396 current_ts = 315.487091 current_received_ts = 315.486542 current_seq = 11397 count = 21 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.487091 last_received_ts = 315.486542 last_seq = 11397 current_ts = 315.503815 current_received_ts = 315.503235 current_seq = 11398 count = 22 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.503815 last_received_ts = 315.503235 last_seq = 11398 current_ts = 315.520538 current_received_ts = 315.519958 current_seq = 11399 count = 23 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.520538 last_received_ts = 315.519958 last_seq = 11399 current_ts = 315.537262 current_received_ts = 315.536682 current_seq = 11400 count = 24 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 7us (kms_flip:2766) DEBUG: name = flip last_ts = 315.537262 last_received_ts = 315.536682 last_seq = 11400 current_ts = 315.553955 current_received_ts = 315.553375 current_seq = 11401 count = 25 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.553955 last_received_ts = 315.553375 last_seq = 11401 current_ts = 315.570679 current_received_ts = 315.570129 current_seq = 11402 count = 26 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.570679 last_received_ts = 315.570129 last_seq = 11402 current_ts = 315.587402 current_received_ts = 315.586823 current_seq = 11403 count = 27 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.587402 last_received_ts = 315.586823 last_seq = 11403 current_ts = 315.604126 current_received_ts = 315.603577 current_seq = 11404 count = 28 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.604126 last_received_ts = 315.603577 last_seq = 11404 current_ts = 315.620850 current_received_ts = 315.620270 current_seq = 11405 count = 29 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 7us (kms_flip:2766) DEBUG: name = flip last_ts = 315.620850 last_received_ts = 315.620270 last_seq = 11405 current_ts = 315.637543 current_received_ts = 315.636993 current_seq = 11406 count = 30 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 9us (kms_flip:2766) DEBUG: name = flip last_ts = 315.637543 last_received_ts = 315.636993 last_seq = 11406 current_ts = 315.654266 current_received_ts = 315.653717 current_seq = 11407 count = 31 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.654266 last_received_ts = 315.653717 last_seq = 11407 current_ts = 315.670990 current_received_ts = 315.670441 current_seq = 11408 count = 32 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 7us (kms_flip:2766) DEBUG: name = flip last_ts = 315.670990 last_received_ts = 315.670441 last_seq = 11408 current_ts = 315.687683 current_received_ts = 315.687164 current_seq = 11409 count = 33 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.687683 last_received_ts = 315.687164 last_seq = 11409 current_ts = 315.704407 current_received_ts = 315.703827 current_seq = 11410 count = 34 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 9us (kms_flip:2766) DEBUG: name = flip last_ts = 315.704407 last_received_ts = 315.703827 last_seq = 11410 current_ts = 315.721130 current_received_ts = 315.720581 current_seq = 11411 count = 35 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.721130 last_received_ts = 315.720581 last_seq = 11411 current_ts = 315.737854 current_received_ts = 315.737274 current_seq = 11412 count = 36 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 7us (kms_flip:2766) DEBUG: name = flip last_ts = 315.737854 last_received_ts = 315.737274 last_seq = 11412 current_ts = 315.754578 current_received_ts = 315.753967 current_seq = 11413 count = 37 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.754578 last_received_ts = 315.753967 last_seq = 11413 current_ts = 315.771271 current_received_ts = 315.770691 current_seq = 11414 count = 38 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.771271 last_received_ts = 315.770691 last_seq = 11414 current_ts = 315.787994 current_received_ts = 315.787415 current_seq = 11415 count = 39 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 7us (kms_flip:2766) DEBUG: name = flip last_ts = 315.787994 last_received_ts = 315.787415 last_seq = 11415 current_ts = 315.804718 current_received_ts = 315.804169 current_seq = 11416 count = 40 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.804718 last_received_ts = 315.804169 last_seq = 11416 current_ts = 315.821442 current_received_ts = 315.820862 current_seq = 11417 count = 41 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 7us (kms_flip:2766) DEBUG: name = flip last_ts = 315.821442 last_received_ts = 315.820862 last_seq = 11417 current_ts = 315.838135 current_received_ts = 315.837585 current_seq = 11418 count = 42 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 7us (kms_flip:2766) DEBUG: name = flip last_ts = 315.838135 last_received_ts = 315.837585 last_seq = 11418 current_ts = 315.854858 current_received_ts = 315.854309 current_seq = 11419 count = 43 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 8us (kms_flip:2766) DEBUG: name = flip last_ts = 315.854858 last_received_ts = 315.854309 last_seq = 11419 current_ts = 315.871582 current_received_ts = 315.871063 current_seq = 11420 count = 44 seq_step = 1 (kms_flip:2766) DEBUG: Vblank took 599us (kms_flip:2766) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2766) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2766) igt_core-INFO: Stack trace: (kms_flip:2766) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2766) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:2766) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:2766) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() (kms_flip:2766) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:2766) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2766) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2766) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-VGA1: FAIL (0.986s)
Dmesg	<6> [314.612869] [IGT] kms_flip: starting dynamic subtest B-VGA1 <7> [314.613366] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:90] <7> [314.613503] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:91] <7> [314.650603] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:53:pipe A] <7> [314.650810] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [314.651378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [314.651825] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [314.652335] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in has_pch_encoder (expected yes, found no) <7> [314.652822] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in fdi_lanes (expected 1, found 0) <7> [314.653324] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in fdi_m_n (expected tu 64 data 6039797/8388608 link 125829/524288, found tu 0, data 0/0 link 0/0) <7> [314.653831] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000) <7> [314.654210] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [314.654477] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0) <7> [314.654744] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0) <7> [314.655112] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0) <7> [314.655410] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0) <7> [314.655667] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0) <7> [314.655913] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0) <7> [314.656175] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0) <7> [314.656441] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0) <7> [314.656691] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0) <7> [314.657001] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0) <7> [314.657249] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0) <7> [314.657479] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0) <7> [314.657708] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0) <7> [314.657937] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0) <7> [314.658203] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0) <7> [314.658519] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0) <7> [314.658775] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0) <7> [314.659066] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0) <7> [314.659307] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0) <7> [314.659537] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0) <7> [314.659766] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0) <7> [314.660042] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0) <7> [314.660322] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0) <7> [314.660568] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0) <7> [314.660804] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [314.661068] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [314.661327] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [314.661610] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [314.661873] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0) <7> [314.662145] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0) <7> [314.662402] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in port_clock (expected 64800, found 0) <7> [314.662638] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:53:pipe A] fastset requirement not met, forcing full modeset <7> [314.662874] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:53:pipe A] releasing PCH DPLL A <7> [314.663218] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:53:pipe A] min cdclk: 72000 kHz -> 0 kHz <7> [314.663489] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:53:pipe A] enable: no [modeset] <7> [314.663740] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:primary A] fb: [NOFB], visible: no <7> [314.664096] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [314.677634] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found <7> [314.678173] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found <7> [314.678681] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found <7> [314.695415] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:53:pipe A] <7> [314.695963] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A <7> [314.696737] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT] <7> [314.697246] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D] <7> [314.697715] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D] <7> [314.698225] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:73:VGA-1] <7> [314.698640] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:53:pipe A] <7> [314.698917] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:72:pipe B] <7> [314.699044] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:72:pipe B] <7> [314.699071] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:73:VGA-1] <7> [314.699167] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:73:VGA-1] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36) <7> [314.699420] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:72:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [314.699657] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1 <7> [314.699887] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [314.700165] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [314.700438] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [314.700706] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes) <7> [314.700957] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1) <7> [314.701314] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in fdi_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6039797/8388608 link 125829/524288) <7> [314.701554] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002) <7> [314.701827] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [314.702102] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024) <7> [314.702349] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344) <7> [314.702585] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024) <7> [314.702821] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344) <7> [314.703084] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048) <7> [314.703357] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184) <7> [314.703620] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768) <7> [314.703867] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768) <7> [314.704132] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771) <7> [314.704380] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777) <7> [314.704624] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806) <7> [314.704915] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806) <7> [314.705188] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024) <7> [314.705437] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344) <7> [314.705666] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024) <7> [314.705895] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344) <7> [314.706206] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048) <7> [314.706482] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184) <7> [314.706741] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768) <7> [314.707025] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768) <7> [314.707272] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771) <7> [314.707502] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777) <7> [314.707747] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806) <7> [314.708066] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806) <7> [314.708306] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [314.708536] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [314.708764] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [314.709031] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in dpll_hw_state <7> [314.709317] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [314.709584] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06 <7> [314.709834] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [314.710115] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09 <7> [314.710364] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [314.710593] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800) <7> [314.710874] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800) <7> [314.711189] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in port_clock (expected 0, found 64800) <7> [314.711428] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:72:pipe B] fastset requirement not met, forcing full modeset <7> [314.711708] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:72:pipe B] min cdclk: 0 kHz -> 72000 kHz <7> [314.711945] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:72:pipe B] allocated PCH DPLL A <7> [314.712199] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:72:pipe B] reserving PCH DPLL A <7> [314.712480] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:72:pipe B] enable: yes [modeset] <7> [314.712757] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB <7> [314.713040] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [314.713286] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [314.713514] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [314.713741] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [314.714043] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [314.714294] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fdi: lanes: 1; data_m: 6039797, data_n: 8388608, link_m: 125829, link_n: 524288, tu: 64 <7> [314.714523] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0 <7> [314.714752] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1 <7> [314.715013] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [314.715250] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0 <7> [314.715478] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0 <7> [314.715706] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [314.715933] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa <7> [314.716210] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa <7> [314.716440] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa <7> [314.716669] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1024x768": 60 64800 1024 1048 1184 1344 768 771 777 806 0x40 0xa <7> [314.716898] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa <7> [314.717182] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pixel rate 64800, min cdclk 72000, min voltage level 0 <7> [314.717191] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on <7> [314.717575] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0 <7> [314.717805] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1024x768+0+0 <7> [314.718081] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [314.718326] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [314.718626] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [314.718853] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09 <7> [314.719112] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [314.719357] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [314.719584] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [314.719811] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [314.720076] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [314.720337] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [314.720565] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:primary B] fb: [FB:90] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [314.720802] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [314.721075] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0 <7> [314.722282] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on <7> [314.722523] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT] <7> [314.722757] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D] <7> [314.723002] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D] <7> [314.723789] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [314.724882] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100 <7> [314.725156] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done. <7> [314.726053] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x600 <7> [314.726294] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done. <7> [314.726516] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done. <7> [314.726752] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:72:pipe B] <7> [314.727014] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A <7> [314.779037] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:73:VGA-1] <7> [314.779600] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:72:pipe B] <6> [315.600044] [IGT] kms_flip: finished subtest B-VGA1, FAIL

Detail

Value

Duration

0.99 seconds

Hostname

shard-snb4

Igt-Version

IGT-Version: 2.4-g3437934c1 (x86_64) (Linux: 7.0.0-CI_DRM_18350-g898b5aa235c5+ x86_64)

Out

Starting dynamic subtest: B-VGA1
  1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-VGA1: FAIL (0.986s)

Err

Starting dynamic subtest: B-VGA1
(kms_flip:2766) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2766) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:2766) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
(kms_flip:2766) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2766) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2766) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=4096)
(kms_flip:2766) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2766) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
(kms_flip:2766) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2766) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2766) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=4096)
(kms_flip:2766) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2766) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2766) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2766) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:2766) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2766) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2766) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:2766) igt_kms-INFO:   1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 
(kms_flip:2766) DEBUG: No stale events found
(kms_flip:2766) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2766) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2766) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 315.136047
current_received_ts = 315.135498
current_seq = 11376
count = 0
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 7us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.136047
last_received_ts = 315.135498
last_seq = 11376
current_ts = 315.152771
current_received_ts = 315.152191
current_seq = 11377
count = 1
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.152771
last_received_ts = 315.152191
last_seq = 11377
current_ts = 315.169495
current_received_ts = 315.168915
current_seq = 11378
count = 2
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 7us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.169495
last_received_ts = 315.168915
last_seq = 11378
current_ts = 315.186188
current_received_ts = 315.185638
current_seq = 11379
count = 3
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.186188
last_received_ts = 315.185638
last_seq = 11379
current_ts = 315.202911
current_received_ts = 315.202332
current_seq = 11380
count = 4
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.202911
last_received_ts = 315.202332
last_seq = 11380
current_ts = 315.219635
current_received_ts = 315.219116
current_seq = 11381
count = 5
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 9us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.219635
last_received_ts = 315.219116
last_seq = 11381
current_ts = 315.236359
current_received_ts = 315.235809
current_seq = 11382
count = 6
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.236359
last_received_ts = 315.235809
last_seq = 11382
current_ts = 315.253052
current_received_ts = 315.252502
current_seq = 11383
count = 7
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.253052
last_received_ts = 315.252502
last_seq = 11383
current_ts = 315.269775
current_received_ts = 315.269226
current_seq = 11384
count = 8
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.269775
last_received_ts = 315.269226
last_seq = 11384
current_ts = 315.286499
current_received_ts = 315.285950
current_seq = 11385
count = 9
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.286499
last_received_ts = 315.285950
last_seq = 11385
current_ts = 315.303223
current_received_ts = 315.302643
current_seq = 11386
count = 10
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.303223
last_received_ts = 315.302643
last_seq = 11386
current_ts = 315.319946
current_received_ts = 315.319366
current_seq = 11387
count = 11
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.319946
last_received_ts = 315.319366
last_seq = 11387
current_ts = 315.336639
current_received_ts = 315.336090
current_seq = 11388
count = 12
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.336639
last_received_ts = 315.336090
last_seq = 11388
current_ts = 315.353363
current_received_ts = 315.352814
current_seq = 11389
count = 13
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.353363
last_received_ts = 315.352814
last_seq = 11389
current_ts = 315.370087
current_received_ts = 315.369507
current_seq = 11390
count = 14
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.370087
last_received_ts = 315.369507
last_seq = 11390
current_ts = 315.386810
current_received_ts = 315.386230
current_seq = 11391
count = 15
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 7us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.386810
last_received_ts = 315.386230
last_seq = 11391
current_ts = 315.403503
current_received_ts = 315.402954
current_seq = 11392
count = 16
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 7us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.403503
last_received_ts = 315.402954
last_seq = 11392
current_ts = 315.420227
current_received_ts = 315.419678
current_seq = 11393
count = 17
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 9us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.420227
last_received_ts = 315.419678
last_seq = 11393
current_ts = 315.436951
current_received_ts = 315.436371
current_seq = 11394
count = 18
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.436951
last_received_ts = 315.436371
last_seq = 11394
current_ts = 315.453674
current_received_ts = 315.453125
current_seq = 11395
count = 19
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.453674
last_received_ts = 315.453125
last_seq = 11395
current_ts = 315.470367
current_received_ts = 315.469849
current_seq = 11396
count = 20
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.470367
last_received_ts = 315.469849
last_seq = 11396
current_ts = 315.487091
current_received_ts = 315.486542
current_seq = 11397
count = 21
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.487091
last_received_ts = 315.486542
last_seq = 11397
current_ts = 315.503815
current_received_ts = 315.503235
current_seq = 11398
count = 22
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.503815
last_received_ts = 315.503235
last_seq = 11398
current_ts = 315.520538
current_received_ts = 315.519958
current_seq = 11399
count = 23
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.520538
last_received_ts = 315.519958
last_seq = 11399
current_ts = 315.537262
current_received_ts = 315.536682
current_seq = 11400
count = 24
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 7us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.537262
last_received_ts = 315.536682
last_seq = 11400
current_ts = 315.553955
current_received_ts = 315.553375
current_seq = 11401
count = 25
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.553955
last_received_ts = 315.553375
last_seq = 11401
current_ts = 315.570679
current_received_ts = 315.570129
current_seq = 11402
count = 26
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.570679
last_received_ts = 315.570129
last_seq = 11402
current_ts = 315.587402
current_received_ts = 315.586823
current_seq = 11403
count = 27
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.587402
last_received_ts = 315.586823
last_seq = 11403
current_ts = 315.604126
current_received_ts = 315.603577
current_seq = 11404
count = 28
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.604126
last_received_ts = 315.603577
last_seq = 11404
current_ts = 315.620850
current_received_ts = 315.620270
current_seq = 11405
count = 29
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 7us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.620850
last_received_ts = 315.620270
last_seq = 11405
current_ts = 315.637543
current_received_ts = 315.636993
current_seq = 11406
count = 30
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 9us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.637543
last_received_ts = 315.636993
last_seq = 11406
current_ts = 315.654266
current_received_ts = 315.653717
current_seq = 11407
count = 31
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.654266
last_received_ts = 315.653717
last_seq = 11407
current_ts = 315.670990
current_received_ts = 315.670441
current_seq = 11408
count = 32
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 7us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.670990
last_received_ts = 315.670441
last_seq = 11408
current_ts = 315.687683
current_received_ts = 315.687164
current_seq = 11409
count = 33
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.687683
last_received_ts = 315.687164
last_seq = 11409
current_ts = 315.704407
current_received_ts = 315.703827
current_seq = 11410
count = 34
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 9us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.704407
last_received_ts = 315.703827
last_seq = 11410
current_ts = 315.721130
current_received_ts = 315.720581
current_seq = 11411
count = 35
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.721130
last_received_ts = 315.720581
last_seq = 11411
current_ts = 315.737854
current_received_ts = 315.737274
current_seq = 11412
count = 36
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 7us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.737854
last_received_ts = 315.737274
last_seq = 11412
current_ts = 315.754578
current_received_ts = 315.753967
current_seq = 11413
count = 37
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.754578
last_received_ts = 315.753967
last_seq = 11413
current_ts = 315.771271
current_received_ts = 315.770691
current_seq = 11414
count = 38
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.771271
last_received_ts = 315.770691
last_seq = 11414
current_ts = 315.787994
current_received_ts = 315.787415
current_seq = 11415
count = 39
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 7us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.787994
last_received_ts = 315.787415
last_seq = 11415
current_ts = 315.804718
current_received_ts = 315.804169
current_seq = 11416
count = 40
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.804718
last_received_ts = 315.804169
last_seq = 11416
current_ts = 315.821442
current_received_ts = 315.820862
current_seq = 11417
count = 41
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 7us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.821442
last_received_ts = 315.820862
last_seq = 11417
current_ts = 315.838135
current_received_ts = 315.837585
current_seq = 11418
count = 42
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 7us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.838135
last_received_ts = 315.837585
last_seq = 11418
current_ts = 315.854858
current_received_ts = 315.854309
current_seq = 11419
count = 43
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 8us
(kms_flip:2766) DEBUG: name = flip
last_ts = 315.854858
last_received_ts = 315.854309
last_seq = 11419
current_ts = 315.871582
current_received_ts = 315.871063
current_seq = 11420
count = 44
seq_step = 1
(kms_flip:2766) DEBUG: Vblank took 599us
(kms_flip:2766) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2766) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2766) igt_core-INFO: Stack trace:
(kms_flip:2766) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2766) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:2766) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:2766) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
(kms_flip:2766) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:2766) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2766) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2766) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (0.986s)

Dmesg

<6> [314.612869] [IGT] kms_flip: starting dynamic subtest B-VGA1

<7> [314.613366] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:90]

<7> [314.613503] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:91]

<7> [314.650603] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:53:pipe A]

<7> [314.650810] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.enable (expected yes, found no)

<7> [314.651378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.active (expected yes, found no)

<7> [314.651825] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)

<7> [314.652335] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in has_pch_encoder (expected yes, found no)

<7> [314.652822] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in fdi_lanes (expected 1, found 0)

<7> [314.653324] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in fdi_m_n (expected tu 64 data 6039797/8388608 link 125829/524288, found tu 0, data 0/0 link 0/0)

<7> [314.653831] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)

<7> [314.654210] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)

<7> [314.654477] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)

<7> [314.654744] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)

<7> [314.655112] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)

<7> [314.655410] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)

<7> [314.655667] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)

<7> [314.655913] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)

<7> [314.656175] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)

<7> [314.656441] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)

<7> [314.656691] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)

<7> [314.657001] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)

<7> [314.657249] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)

<7> [314.657479] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)

<7> [314.657708] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)

<7> [314.657937] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)

<7> [314.658203] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)

<7> [314.658519] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)

<7> [314.658775] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)

<7> [314.659066] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)

<7> [314.659307] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)

<7> [314.659537] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)

<7> [314.659766] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)

<7> [314.660042] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)

<7> [314.660322] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)

<7> [314.660568] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)

<7> [314.660804] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)

<7> [314.661068] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)

<7> [314.661327] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)

<7> [314.661610] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)

<7> [314.661873] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)

<7> [314.662145] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)

<7> [314.662402] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in port_clock (expected 64800, found 0)

<7> [314.662638] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:53:pipe A] fastset requirement not met, forcing full modeset

<7> [314.662874] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:53:pipe A] releasing PCH DPLL A

<7> [314.663218] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:53:pipe A] min cdclk: 72000 kHz -> 0 kHz

<7> [314.663489] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:53:pipe A] enable: no [modeset]

<7> [314.663740] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:primary A] fb: [NOFB], visible: no

<7> [314.664096] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A

<7> [314.677634] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found

<7> [314.678173] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found

<7> [314.678681] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found

<7> [314.695415] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:53:pipe A]

<7> [314.695963] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A

<7> [314.696737] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT]

<7> [314.697246] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D]

<7> [314.697715] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D]

<7> [314.698225] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:73:VGA-1]

<7> [314.698640] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:53:pipe A]

<7> [314.698917] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:72:pipe B]

<7> [314.699044] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:72:pipe B]

<7> [314.699071] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:73:VGA-1]

<7> [314.699167] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:73:VGA-1] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)

<7> [314.699420] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:72:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0

<7> [314.699657] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1

<7> [314.699887] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.enable (expected no, found yes)

<7> [314.700165] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.active (expected no, found yes)

<7> [314.700438] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)

<7> [314.700706] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)

<7> [314.700957] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)

<7> [314.701314] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in fdi_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6039797/8388608 link 125829/524288)

<7> [314.701554] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)

<7> [314.701827] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)

<7> [314.702102] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)

<7> [314.702349] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)

<7> [314.702585] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)

<7> [314.702821] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)

<7> [314.703084] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)

<7> [314.703357] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)

<7> [314.703620] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)

<7> [314.703867] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)

<7> [314.704132] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)

<7> [314.704380] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)

<7> [314.704624] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)

<7> [314.704915] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)

<7> [314.705188] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)

<7> [314.705437] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)

<7> [314.705666] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)

<7> [314.705895] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)

<7> [314.706206] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)

<7> [314.706482] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)

<7> [314.706741] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)

<7> [314.707025] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)

<7> [314.707272] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)

<7> [314.707502] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)

<7> [314.707747] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)

<7> [314.708066] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)

<7> [314.708306] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)

<7> [314.708536] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)

<7> [314.708764] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)

<7> [314.709031] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in dpll_hw_state

<7> [314.709317] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [314.709584] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06

<7> [314.709834] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [314.710115] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09

<7> [314.710364] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)

<7> [314.710593] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)

<7> [314.710874] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)

<7> [314.711189] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)

<7> [314.711428] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:72:pipe B] fastset requirement not met, forcing full modeset

<7> [314.711708] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:72:pipe B] min cdclk: 0 kHz -> 72000 kHz

<7> [314.711945] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:72:pipe B] allocated PCH DPLL A

<7> [314.712199] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:72:pipe B] reserving PCH DPLL A

<7> [314.712480] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:72:pipe B] enable: yes [modeset]

<7> [314.712757] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB

<7> [314.713040] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0

<7> [314.713286] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>

<7> [314.713514] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0

<7> [314.713741] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0

<7> [314.714043] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0

<7> [314.714294] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fdi: lanes: 1; data_m: 6039797, data_n: 8388608, link_m: 125829, link_n: 524288, tu: 64

<7> [314.714523] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0

<7> [314.714752] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1

<7> [314.715013] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0

<7> [314.715250] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0

<7> [314.715478] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0

<7> [314.715706] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

<7> [314.715933] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa

<7> [314.716210] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa

<7> [314.716440] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa

<7> [314.716669] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1024x768": 60 64800 1024 1048 1184 1344 768 771 777 806 0x40 0xa

<7> [314.716898] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa

<7> [314.717182] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pixel rate 64800, min cdclk 72000, min voltage level 0

<7> [314.717191] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on

<7> [314.717575] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0

<7> [314.717805] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1024x768+0+0

<7> [314.718081] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no

<7> [314.718326] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0

<7> [314.718626] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0

<7> [314.718853] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09

<7> [314.719112] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

<7> [314.719357] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries

<7> [314.719584] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000

<7> [314.719811] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [314.720076] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [314.720337] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [314.720565] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:primary B] fb: [FB:90] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes

<7> [314.720802] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0

<7> [314.721075] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0

<7> [314.722282] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on

<7> [314.722523] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT]

<7> [314.722757] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D]

<7> [314.723002] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D]

<7> [314.723789] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B

<7> [314.724882] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100

<7> [314.725156] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.

<7> [314.726053] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x600

<7> [314.726294] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.

<7> [314.726516] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.

<7> [314.726752] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:72:pipe B]

<7> [314.727014] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A

<7> [314.779037] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:73:VGA-1]

<7> [314.779600] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:72:pipe B]

<6> [315.600044] [IGT] kms_flip: finished subtest B-VGA1, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank@b-vga1