igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a3 on shard-dg2@CI_DRM

Detail	Value
Duration	2.12 seconds
Hostname	shard-dg2-1
Igt-Version	IGT-Version: 2.3-ge61a8b4ea (x86_64) (Linux: 6.19.0-rc5-CI_DRM_17806-geb2f46812a9a+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A3 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1889 run_test() #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045() #4 ../tests/kms_flip.c:2045 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-HDMI-A3: FAIL (2.124s)
Err	Starting dynamic subtest: B-HDMI-A3 (kms_flip:2105) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2105) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-HDMI-A3 failed. ** DEBUG (kms_flip:2105) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0) (kms_flip:2105) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2105) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2105) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680) (kms_flip:2105) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:2105) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0) (kms_flip:2105) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2105) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2105) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680) (kms_flip:2105) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) (kms_flip:2105) intel_allocator_reloc-DEBUG: Using reloc allocator (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) (kms_flip:2105) intel_allocator_reloc-DEBUG: Using reloc allocator (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) (kms_flip:2105) intel_allocator_reloc-DEBUG: Using reloc allocator (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) (kms_flip:2105) intel_allocator_reloc-DEBUG: Using reloc allocator (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2105) igt_kms-INFO: 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 (kms_flip:2105) DEBUG: No stale events found (kms_flip:2105) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 (kms_flip:2105) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 (kms_flip:2105) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 144.936005 current_received_ts = 144.935532 current_seq = 4 count = 0 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 35us (kms_flip:2105) DEBUG: name = flip last_ts = 144.936005 last_received_ts = 144.935532 last_seq = 4 current_ts = 144.952652 current_received_ts = 144.952240 current_seq = 5 count = 1 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 37us (kms_flip:2105) DEBUG: name = flip last_ts = 144.952652 last_received_ts = 144.952240 last_seq = 5 current_ts = 144.969330 current_received_ts = 144.968872 current_seq = 6 count = 2 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 44us (kms_flip:2105) DEBUG: name = flip last_ts = 144.969330 last_received_ts = 144.968872 last_seq = 6 current_ts = 144.986008 current_received_ts = 144.985565 current_seq = 7 count = 3 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 35us (kms_flip:2105) DEBUG: name = flip last_ts = 144.986008 last_received_ts = 144.985565 last_seq = 7 current_ts = 145.002670 current_received_ts = 145.002365 current_seq = 8 count = 4 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 36us (kms_flip:2105) DEBUG: name = flip last_ts = 145.002670 last_received_ts = 145.002365 last_seq = 8 current_ts = 145.019333 current_received_ts = 145.018936 current_seq = 9 count = 5 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 41us (kms_flip:2105) DEBUG: name = flip last_ts = 145.019333 last_received_ts = 145.018936 last_seq = 9 current_ts = 145.035995 current_received_ts = 145.035721 current_seq = 10 count = 6 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.035995 last_received_ts = 145.035721 last_seq = 10 current_ts = 145.052673 current_received_ts = 145.052322 current_seq = 11 count = 7 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.052673 last_received_ts = 145.052322 last_seq = 11 current_ts = 145.069336 current_received_ts = 145.069122 current_seq = 12 count = 8 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.069336 last_received_ts = 145.069122 last_seq = 12 current_ts = 145.085999 current_received_ts = 145.085648 current_seq = 13 count = 9 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.085999 last_received_ts = 145.085648 last_seq = 13 current_ts = 145.102676 current_received_ts = 145.102325 current_seq = 14 count = 10 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.102676 last_received_ts = 145.102325 last_seq = 14 current_ts = 145.119339 current_received_ts = 145.119019 current_seq = 15 count = 11 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 57us (kms_flip:2105) DEBUG: name = flip last_ts = 145.119339 last_received_ts = 145.119019 last_seq = 15 current_ts = 145.136017 current_received_ts = 145.135620 current_seq = 16 count = 12 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.136017 last_received_ts = 145.135620 last_seq = 16 current_ts = 145.152679 current_received_ts = 145.152328 current_seq = 17 count = 13 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.152679 last_received_ts = 145.152328 last_seq = 17 current_ts = 145.169342 current_received_ts = 145.168991 current_seq = 18 count = 14 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 57us (kms_flip:2105) DEBUG: name = flip last_ts = 145.169342 last_received_ts = 145.168991 last_seq = 18 current_ts = 145.186020 current_received_ts = 145.185745 current_seq = 19 count = 15 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.186020 last_received_ts = 145.185745 last_seq = 19 current_ts = 145.202682 current_received_ts = 145.202454 current_seq = 20 count = 16 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.202682 last_received_ts = 145.202454 last_seq = 20 current_ts = 145.219360 current_received_ts = 145.219147 current_seq = 21 count = 17 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.219360 last_received_ts = 145.219147 last_seq = 21 current_ts = 145.236023 current_received_ts = 145.235748 current_seq = 22 count = 18 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.236023 last_received_ts = 145.235748 last_seq = 22 current_ts = 145.252686 current_received_ts = 145.252335 current_seq = 23 count = 19 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.252686 last_received_ts = 145.252335 last_seq = 23 current_ts = 145.269348 current_received_ts = 145.269028 current_seq = 24 count = 20 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 57us (kms_flip:2105) DEBUG: name = flip last_ts = 145.269348 last_received_ts = 145.269028 last_seq = 24 current_ts = 145.286026 current_received_ts = 145.285751 current_seq = 25 count = 21 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.286026 last_received_ts = 145.285751 last_seq = 25 current_ts = 145.302689 current_received_ts = 145.302460 current_seq = 26 count = 22 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.302689 last_received_ts = 145.302460 last_seq = 26 current_ts = 145.319351 current_received_ts = 145.319122 current_seq = 27 count = 23 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.319351 last_received_ts = 145.319122 last_seq = 27 current_ts = 145.336014 current_received_ts = 145.335648 current_seq = 28 count = 24 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.336014 last_received_ts = 145.335648 last_seq = 28 current_ts = 145.352692 current_received_ts = 145.352325 current_seq = 29 count = 25 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.352692 last_received_ts = 145.352325 last_seq = 29 current_ts = 145.369354 current_received_ts = 145.369156 current_seq = 30 count = 26 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.369354 last_received_ts = 145.369156 last_seq = 30 current_ts = 145.386017 current_received_ts = 145.385681 current_seq = 31 count = 27 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.386017 last_received_ts = 145.385681 last_seq = 31 current_ts = 145.402695 current_received_ts = 145.402328 current_seq = 32 count = 28 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.402695 last_received_ts = 145.402328 last_seq = 32 current_ts = 145.419357 current_received_ts = 145.419174 current_seq = 33 count = 29 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.419357 last_received_ts = 145.419174 last_seq = 33 current_ts = 145.436035 current_received_ts = 145.435638 current_seq = 34 count = 30 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.436035 last_received_ts = 145.435638 last_seq = 34 current_ts = 145.452698 current_received_ts = 145.452332 current_seq = 35 count = 31 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.452698 last_received_ts = 145.452332 last_seq = 35 current_ts = 145.469360 current_received_ts = 145.469162 current_seq = 36 count = 32 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.469360 last_received_ts = 145.469162 last_seq = 36 current_ts = 145.486038 current_received_ts = 145.485657 current_seq = 37 count = 33 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.486038 last_received_ts = 145.485657 last_seq = 37 current_ts = 145.502701 current_received_ts = 145.502319 current_seq = 38 count = 34 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.502701 last_received_ts = 145.502319 last_seq = 38 current_ts = 145.519363 current_received_ts = 145.519073 current_seq = 39 count = 35 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.519363 last_received_ts = 145.519073 last_seq = 39 current_ts = 145.536041 current_received_ts = 145.535706 current_seq = 40 count = 36 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.536041 last_received_ts = 145.535706 last_seq = 40 current_ts = 145.552704 current_received_ts = 145.552322 current_seq = 41 count = 37 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.552704 last_received_ts = 145.552322 last_seq = 41 current_ts = 145.569366 current_received_ts = 145.568939 current_seq = 42 count = 38 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 82us (kms_flip:2105) DEBUG: name = flip last_ts = 145.569366 last_received_ts = 145.568939 last_seq = 42 current_ts = 145.586044 current_received_ts = 145.585587 current_seq = 43 count = 39 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 50us (kms_flip:2105) DEBUG: name = flip last_ts = 145.586044 last_received_ts = 145.585587 last_seq = 43 current_ts = 145.602707 current_received_ts = 145.602310 current_seq = 44 count = 40 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 53us (kms_flip:2105) DEBUG: name = flip last_ts = 145.602707 last_received_ts = 145.602310 last_seq = 44 current_ts = 145.619370 current_received_ts = 145.619064 current_seq = 45 count = 41 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.619370 last_received_ts = 145.619064 last_seq = 45 current_ts = 145.636047 current_received_ts = 145.635712 current_seq = 46 count = 42 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.636047 last_received_ts = 145.635712 last_seq = 46 current_ts = 145.652710 current_received_ts = 145.652466 current_seq = 47 count = 43 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.652710 last_received_ts = 145.652466 last_seq = 47 current_ts = 145.669373 current_received_ts = 145.669067 current_seq = 48 count = 44 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.669373 last_received_ts = 145.669067 last_seq = 48 current_ts = 145.686050 current_received_ts = 145.685791 current_seq = 49 count = 45 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.686050 last_received_ts = 145.685791 last_seq = 49 current_ts = 145.702713 current_received_ts = 145.702332 current_seq = 50 count = 46 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.702713 last_received_ts = 145.702332 last_seq = 50 current_ts = 145.719391 current_received_ts = 145.719162 current_seq = 51 count = 47 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.719391 last_received_ts = 145.719162 last_seq = 51 current_ts = 145.736053 current_received_ts = 145.735703 current_seq = 52 count = 48 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.736053 last_received_ts = 145.735703 last_seq = 52 current_ts = 145.752716 current_received_ts = 145.752335 current_seq = 53 count = 49 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.752716 last_received_ts = 145.752335 last_seq = 53 current_ts = 145.769394 current_received_ts = 145.769073 current_seq = 54 count = 50 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 54us (kms_flip:2105) DEBUG: name = flip last_ts = 145.769394 last_received_ts = 145.769073 last_seq = 54 current_ts = 145.786057 current_received_ts = 145.785706 current_seq = 55 count = 51 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.786057 last_received_ts = 145.785706 last_seq = 55 current_ts = 145.802719 current_received_ts = 145.802322 current_seq = 56 count = 52 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.802719 last_received_ts = 145.802322 last_seq = 56 current_ts = 145.819397 current_received_ts = 145.819168 current_seq = 57 count = 53 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.819397 last_received_ts = 145.819168 last_seq = 57 current_ts = 145.836060 current_received_ts = 145.835709 current_seq = 58 count = 54 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.836060 last_received_ts = 145.835709 last_seq = 58 current_ts = 145.852722 current_received_ts = 145.852341 current_seq = 59 count = 55 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.852722 last_received_ts = 145.852341 last_seq = 59 current_ts = 145.869385 current_received_ts = 145.869080 current_seq = 60 count = 56 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.869385 last_received_ts = 145.869080 last_seq = 60 current_ts = 145.886063 current_received_ts = 145.885727 current_seq = 61 count = 57 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.886063 last_received_ts = 145.885727 last_seq = 61 current_ts = 145.902725 current_received_ts = 145.902344 current_seq = 62 count = 58 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 145.902725 last_received_ts = 145.902344 last_seq = 62 current_ts = 145.919388 current_received_ts = 145.919083 current_seq = 63 count = 59 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 54us (kms_flip:2105) DEBUG: name = flip last_ts = 145.919388 last_received_ts = 145.919083 last_seq = 63 current_ts = 145.936066 current_received_ts = 145.935806 current_seq = 64 count = 60 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.936066 last_received_ts = 145.935806 last_seq = 64 current_ts = 145.952728 current_received_ts = 145.952454 current_seq = 65 count = 61 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.952728 last_received_ts = 145.952454 last_seq = 65 current_ts = 145.969406 current_received_ts = 145.969070 current_seq = 66 count = 62 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.969406 last_received_ts = 145.969070 last_seq = 66 current_ts = 145.986069 current_received_ts = 145.985825 current_seq = 67 count = 63 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 145.986069 last_received_ts = 145.985825 last_seq = 67 current_ts = 146.002731 current_received_ts = 146.002472 current_seq = 68 count = 64 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 146.002731 last_received_ts = 146.002472 last_seq = 68 current_ts = 146.019409 current_received_ts = 146.019089 current_seq = 69 count = 65 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 146.019409 last_received_ts = 146.019089 last_seq = 69 current_ts = 146.036072 current_received_ts = 146.035812 current_seq = 70 count = 66 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 146.036072 last_received_ts = 146.035812 last_seq = 70 current_ts = 146.052734 current_received_ts = 146.052338 current_seq = 71 count = 67 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.052734 last_received_ts = 146.052338 last_seq = 71 current_ts = 146.069412 current_received_ts = 146.069183 current_seq = 72 count = 68 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.069412 last_received_ts = 146.069183 last_seq = 72 current_ts = 146.086075 current_received_ts = 146.085815 current_seq = 73 count = 69 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.086075 last_received_ts = 146.085815 last_seq = 73 current_ts = 146.102753 current_received_ts = 146.102341 current_seq = 74 count = 70 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.102753 last_received_ts = 146.102341 last_seq = 74 current_ts = 146.119415 current_received_ts = 146.119186 current_seq = 75 count = 71 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.119415 last_received_ts = 146.119186 last_seq = 75 current_ts = 146.136078 current_received_ts = 146.135834 current_seq = 76 count = 72 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 54us (kms_flip:2105) DEBUG: name = flip last_ts = 146.136078 last_received_ts = 146.135834 last_seq = 76 current_ts = 146.152740 current_received_ts = 146.152451 current_seq = 77 count = 73 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.152740 last_received_ts = 146.152451 last_seq = 77 current_ts = 146.169418 current_received_ts = 146.169205 current_seq = 78 count = 74 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.169418 last_received_ts = 146.169205 last_seq = 78 current_ts = 146.186081 current_received_ts = 146.185837 current_seq = 79 count = 75 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.186081 last_received_ts = 146.185837 last_seq = 79 current_ts = 146.202744 current_received_ts = 146.202454 current_seq = 80 count = 76 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.202744 last_received_ts = 146.202454 last_seq = 80 current_ts = 146.219421 current_received_ts = 146.219101 current_seq = 81 count = 77 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.219421 last_received_ts = 146.219101 last_seq = 81 current_ts = 146.236084 current_received_ts = 146.235733 current_seq = 82 count = 78 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.236084 last_received_ts = 146.235733 last_seq = 82 current_ts = 146.252762 current_received_ts = 146.252365 current_seq = 83 count = 79 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 146.252762 last_received_ts = 146.252365 last_seq = 83 current_ts = 146.269424 current_received_ts = 146.269104 current_seq = 84 count = 80 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 146.269424 last_received_ts = 146.269104 last_seq = 84 current_ts = 146.286087 current_received_ts = 146.285751 current_seq = 85 count = 81 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 146.286087 last_received_ts = 146.285751 last_seq = 85 current_ts = 146.302765 current_received_ts = 146.302429 current_seq = 86 count = 82 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.302765 last_received_ts = 146.302429 last_seq = 86 current_ts = 146.319427 current_received_ts = 146.319107 current_seq = 87 count = 83 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 146.319427 last_received_ts = 146.319107 last_seq = 87 current_ts = 146.336105 current_received_ts = 146.335846 current_seq = 88 count = 84 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.336105 last_received_ts = 146.335846 last_seq = 88 current_ts = 146.352768 current_received_ts = 146.352356 current_seq = 89 count = 85 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.352768 last_received_ts = 146.352356 last_seq = 89 current_ts = 146.369431 current_received_ts = 146.369110 current_seq = 90 count = 86 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.369431 last_received_ts = 146.369110 last_seq = 90 current_ts = 146.386093 current_received_ts = 146.385773 current_seq = 91 count = 87 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.386093 last_received_ts = 146.385773 last_seq = 91 current_ts = 146.402771 current_received_ts = 146.402359 current_seq = 92 count = 88 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.402771 last_received_ts = 146.402359 last_seq = 92 current_ts = 146.419449 current_received_ts = 146.419128 current_seq = 93 count = 89 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 57us (kms_flip:2105) DEBUG: name = flip last_ts = 146.419449 last_received_ts = 146.419128 last_seq = 93 current_ts = 146.436096 current_received_ts = 146.435760 current_seq = 94 count = 90 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 146.436096 last_received_ts = 146.435760 last_seq = 94 current_ts = 146.452774 current_received_ts = 146.452377 current_seq = 95 count = 91 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 55us (kms_flip:2105) DEBUG: name = flip last_ts = 146.452774 last_received_ts = 146.452377 last_seq = 95 current_ts = 146.469437 current_received_ts = 146.469116 current_seq = 96 count = 92 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 146.469437 last_received_ts = 146.469116 last_seq = 96 current_ts = 146.486099 current_received_ts = 146.485764 current_seq = 97 count = 93 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 56us (kms_flip:2105) DEBUG: name = flip last_ts = 146.486099 last_received_ts = 146.485764 last_seq = 97 current_ts = 146.502777 current_received_ts = 146.502319 current_seq = 98 count = 94 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 51us (kms_flip:2105) DEBUG: name = flip last_ts = 146.502777 last_received_ts = 146.502319 last_seq = 98 current_ts = 146.519440 current_received_ts = 146.518951 current_seq = 99 count = 95 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 74us (kms_flip:2105) DEBUG: name = flip last_ts = 146.519440 last_received_ts = 146.518951 last_seq = 99 current_ts = 146.536118 current_received_ts = 146.535614 current_seq = 100 count = 96 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 48us (kms_flip:2105) DEBUG: name = flip last_ts = 146.536118 last_received_ts = 146.535614 last_seq = 100 current_ts = 146.552780 current_received_ts = 146.552292 current_seq = 101 count = 97 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 47us (kms_flip:2105) DEBUG: name = flip last_ts = 146.552780 last_received_ts = 146.552292 last_seq = 101 current_ts = 146.569458 current_received_ts = 146.568970 current_seq = 102 count = 98 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 70us (kms_flip:2105) DEBUG: name = flip last_ts = 146.569458 last_received_ts = 146.568970 last_seq = 102 current_ts = 146.586121 current_received_ts = 146.585617 current_seq = 103 count = 99 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 48us (kms_flip:2105) DEBUG: name = flip last_ts = 146.586121 last_received_ts = 146.585617 last_seq = 103 current_ts = 146.602783 current_received_ts = 146.602295 current_seq = 104 count = 100 seq_step = 1 (kms_flip:2105) DEBUG: Vblank took 530us (kms_flip:2105) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2105) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2105) igt_core-INFO: Stack trace: (kms_flip:2105) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2105) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:2105) igt_core-INFO: #2 ../tests/kms_flip.c:1889 run_test() (kms_flip:2105) igt_core-INFO: #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045() (kms_flip:2105) igt_core-INFO: #4 ../tests/kms_flip.c:2045 main() (kms_flip:2105) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2105) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2105) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A3: FAIL (2.124s)
Dmesg	<6> [145.086274] [IGT] kms_flip: starting dynamic subtest B-HDMI-A3 <7> [145.086850] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:560] <7> [145.087069] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:561] <7> [145.087530] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [145.088390] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [145.118264] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [145.118864] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [145.128746] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [145.129349] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [145.151818] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [145.153212] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [145.179813] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:149:pipe A] <7> [145.179920] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [145.180121] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [145.180295] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [145.180469] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [145.180643] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [145.180817] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [145.180999] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [145.181175] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [145.181349] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [145.181523] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [145.181697] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [145.181915] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [145.182090] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [145.182264] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [145.182437] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [145.182610] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [145.182785] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [145.183032] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [145.183206] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [145.183380] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [145.183554] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [145.183727] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [145.183942] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [145.184117] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [145.184292] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [145.184467] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [145.184642] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [145.184816] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [145.185062] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [145.185237] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [145.185412] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [145.185587] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [145.185762] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [145.186007] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [145.186182] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [145.186356] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [145.186532] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in port_clock (expected 148500, found 0) <7> [145.186707] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:149:pipe A] fastset requirement not met, forcing full modeset <7> [145.186971] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0xf), mbus joined? no->no <7> [145.187141] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:149:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [145.187334] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:143:cursor A] ddb (1963 - 2048) -> ( 0 - 0), size 85 -> 0 <7> [145.187532] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:149:pipe A] min cdclk: 74250 kHz -> 0 kHz <7> [145.187706] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz <7> [145.187918] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [145.188093] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:149:pipe A] enable: no [modeset] <7> [145.188267] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:33:plane 1A] fb: [NOFB], visible: no <7> [145.188441] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 2A] fb: [NOFB], visible: no <7> [145.188615] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:93:plane 3A] fb: [NOFB], visible: no <7> [145.188788] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:123:plane 4A] fb: [NOFB], visible: no <7> [145.189004] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:133:plane 5A] fb: [NOFB], visible: no <7> [145.189178] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:143:cursor A] fb: [NOFB], visible: no <7> [145.189555] i915 0000:03:00.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [145.203034] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_D <7> [145.203273] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:505:DDI A/PHY A] <7> [145.203445] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DP-MST A] <7> [145.203617] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:508:DP-MST B] <7> [145.203789] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST C] <7> [145.204010] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST D] <7> [145.204182] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DDI B/PHY B] <7> [145.204352] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST A] <7> [145.204523] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST B] <7> [145.204694] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST C] <7> [145.204940] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST D] <7> [145.205182] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:533:DDI C/PHY C] <7> [145.205353] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DP-MST A] <7> [145.205523] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST B] <7> [145.205693] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST C] <7> [145.205905] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST D] <7> [145.206076] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:545:DDI D/PHY D] <7> [145.206266] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DP-MST A] <7> [145.206438] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST B] <7> [145.206609] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST C] <7> [145.206780] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST D] <7> [145.206990] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:554:HDMI-A-3] <7> [145.207199] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [145.207476] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_A <7> [145.207712] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [145.207967] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:149:pipe A] <7> [145.208323] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:267:pipe B] <7> [145.208475] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:385:pipe C] <7> [145.208617] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:503:pipe D] <7> [145.208759] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:267:pipe B] <7> [145.208788] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:554:HDMI-A-3] <7> [145.208899] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CONNECTOR:554:HDMI-A-3] Limiting display bpp to 24 (EDID bpp 0, max requested bpp 36, max platform bpp 36) <7> [145.209083] i915 0000:03:00.0: [drm:intel_hdmi_compute_clock [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [145.209245] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:267:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [145.209421] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:545:DDI D/PHY D] [CRTC:267:pipe B] <7> [145.209587] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [145.209761] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [145.209981] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [145.210156] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [145.210331] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [145.210506] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [145.210681] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [145.210891] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [145.211065] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [145.211239] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [145.211413] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [145.211587] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [145.211760] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [145.211973] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [145.212147] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [145.212320] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [145.212495] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [145.212669] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [145.212869] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [145.213057] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [145.213231] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [145.213405] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [145.213579] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [145.213753] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [145.213966] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [145.214140] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [145.214315] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [145.214488] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [145.214663] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [145.214860] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [145.215078] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [145.215252] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [145.215426] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [145.215600] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [145.215773] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [145.216033] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [145.216208] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in port_clock (expected 0, found 148500) <7> [145.216383] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:267:pipe B] fastset requirement not met, forcing full modeset <7> [145.216577] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0xf), mbus joined? no->no <7> [145.216747] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:267:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2 <7> [145.216981] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:151:plane 1B] ddb ( 0 - 0) -> ( 0 - 1963), size 0 -> 1963 <7> [145.217150] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:261:cursor B] ddb ( 0 - 0) -> (1963 - 2048), size 0 -> 85 <7> [145.217320] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,*twm, swm, stwm <7> [145.217489] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 4, 5, 9, 11, 17, 25, 0, 0, 0 <7> [145.217657] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 62, 78, 139, 169, 261, 383, 137, 0, 0 <7> [145.217832] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 123, 184, 245, 245, 367, 489, 138, 0, 0 <7> [145.218045] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:267:pipe B] data rate 594000 num active planes 1 <7> [145.218220] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 50000 required 624 <7> [145.218393] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [145.218578] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:267:pipe B] min cdclk: 0 kHz -> 74250 kHz <7> [145.218765] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz <7> [145.218977] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [145.219150] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:267:pipe B] enable: yes [modeset] <7> [145.219325] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [145.219498] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [145.219672] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [145.219884] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [145.220093] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [145.220266] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [145.220439] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0 <7> [145.220613] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [145.220785] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [145.220999] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 45 vsync start: 41, vsync end: 36 <7> [145.221173] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1080, vmax vblank: 1080, vmin vtotal: 1125, vmax vtotal: 1125 <7> [145.221347] i915 0000:03:00.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> [145.221520] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [145.221695] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [145.221908] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [145.222083] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5 <7> [145.222258] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [145.222433] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port clock: 148500, pipe src: 1920x1080+0+0, pixel rate 148500, min cdclk 74250 <7> [145.222607] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] linetime: 119, ips linetime: 0 <7> [145.222781] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [145.222993] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [145.223167] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [145.223340] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x24414, dpll_md: 0x18000000, fp0: 0x8801ef8, fp1: 0x2b000440 <7> [145.223514] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [145.223688] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [145.223903] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [145.224078] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [145.224251] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [145.224424] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [145.224598] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [145.224772] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [145.224986] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [145.225160] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [145.225332] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [145.225505] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [145.225679] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [145.225894] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:151:plane 1B] fb: [FB:560] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [145.225970] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DC_off <7> [145.226102] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [145.226202] i915 0000:03:00.0: [drm:gen9_enable_dc5 [i915]] Enabling DC5 <7> [145.226275] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [145.226382] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 01 <7> [145.226449] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:181:plane 2B] fb: [NOFB], visible: no <7> [145.226624] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:211:plane 3B] fb: [NOFB], visible: no <7> [145.226797] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:241:plane 4B] fb: [NOFB], visible: no <7> [145.227007] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:251:plane 5B] fb: [NOFB], visible: no <7> [145.227180] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:261:cursor B] fb: [NOFB], visible: no <7> [145.227756] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DC_off <7> [145.228099] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 01 to 00 <7> [145.228460] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [145.228657] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_B <7> [145.228922] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:505:DDI A/PHY A] <7> [145.229093] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DP-MST A] <7> [145.229265] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:508:DP-MST B] <7> [145.229436] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST C] <7> [145.229607] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST D] <7> [145.229779] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DDI B/PHY B] <7> [145.229991] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST A] <7> [145.230164] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST B] <7> [145.230335] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST C] <7> [145.230507] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST D] <7> [145.230679] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:533:DDI C/PHY C] <7> [145.230889] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DP-MST A] <7> [145.231061] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST B] <7> [145.231233] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST C] <7> [145.231404] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST D] <7> [145.231576] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:545:DDI D/PHY D] <7> [145.231748] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DP-MST A] <7> [145.231958] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST B] <7> [145.232130] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST C] <7> [145.232301] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST D] <7> [145.232473] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [145.232876] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_D <7> [145.233212] i915 0000:03:00.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [145.252442] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:554:HDMI-A-3] <7> [145.252756] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:267:pipe B] <6> [147.210115] [IGT] kms_flip: finished subtest B-HDMI-A3, FAIL

Detail

Value

Duration

2.12 seconds

Hostname

shard-dg2-1

Igt-Version

IGT-Version: 2.3-ge61a8b4ea (x86_64) (Linux: 6.19.0-rc5-CI_DRM_17806-geb2f46812a9a+ x86_64)

Out

Starting dynamic subtest: B-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1889 run_test()
  #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045()
  #4 ../tests/kms_flip.c:2045 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A3: FAIL (2.124s)

Err

Starting dynamic subtest: B-HDMI-A3
(kms_flip:2105) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2105) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2105) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
(kms_flip:2105) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2105) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2105) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:2105) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2105) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
(kms_flip:2105) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2105) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2105) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:2105) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2105) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2105) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2105) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2105) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2105) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2105) DEBUG: No stale events found
(kms_flip:2105) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2105) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2105) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 144.936005
current_received_ts = 144.935532
current_seq = 4
count = 0
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 35us
(kms_flip:2105) DEBUG: name = flip
last_ts = 144.936005
last_received_ts = 144.935532
last_seq = 4
current_ts = 144.952652
current_received_ts = 144.952240
current_seq = 5
count = 1
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 37us
(kms_flip:2105) DEBUG: name = flip
last_ts = 144.952652
last_received_ts = 144.952240
last_seq = 5
current_ts = 144.969330
current_received_ts = 144.968872
current_seq = 6
count = 2
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 44us
(kms_flip:2105) DEBUG: name = flip
last_ts = 144.969330
last_received_ts = 144.968872
last_seq = 6
current_ts = 144.986008
current_received_ts = 144.985565
current_seq = 7
count = 3
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 35us
(kms_flip:2105) DEBUG: name = flip
last_ts = 144.986008
last_received_ts = 144.985565
last_seq = 7
current_ts = 145.002670
current_received_ts = 145.002365
current_seq = 8
count = 4
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 36us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.002670
last_received_ts = 145.002365
last_seq = 8
current_ts = 145.019333
current_received_ts = 145.018936
current_seq = 9
count = 5
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 41us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.019333
last_received_ts = 145.018936
last_seq = 9
current_ts = 145.035995
current_received_ts = 145.035721
current_seq = 10
count = 6
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.035995
last_received_ts = 145.035721
last_seq = 10
current_ts = 145.052673
current_received_ts = 145.052322
current_seq = 11
count = 7
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.052673
last_received_ts = 145.052322
last_seq = 11
current_ts = 145.069336
current_received_ts = 145.069122
current_seq = 12
count = 8
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.069336
last_received_ts = 145.069122
last_seq = 12
current_ts = 145.085999
current_received_ts = 145.085648
current_seq = 13
count = 9
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.085999
last_received_ts = 145.085648
last_seq = 13
current_ts = 145.102676
current_received_ts = 145.102325
current_seq = 14
count = 10
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.102676
last_received_ts = 145.102325
last_seq = 14
current_ts = 145.119339
current_received_ts = 145.119019
current_seq = 15
count = 11
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 57us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.119339
last_received_ts = 145.119019
last_seq = 15
current_ts = 145.136017
current_received_ts = 145.135620
current_seq = 16
count = 12
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.136017
last_received_ts = 145.135620
last_seq = 16
current_ts = 145.152679
current_received_ts = 145.152328
current_seq = 17
count = 13
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.152679
last_received_ts = 145.152328
last_seq = 17
current_ts = 145.169342
current_received_ts = 145.168991
current_seq = 18
count = 14
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 57us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.169342
last_received_ts = 145.168991
last_seq = 18
current_ts = 145.186020
current_received_ts = 145.185745
current_seq = 19
count = 15
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.186020
last_received_ts = 145.185745
last_seq = 19
current_ts = 145.202682
current_received_ts = 145.202454
current_seq = 20
count = 16
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.202682
last_received_ts = 145.202454
last_seq = 20
current_ts = 145.219360
current_received_ts = 145.219147
current_seq = 21
count = 17
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.219360
last_received_ts = 145.219147
last_seq = 21
current_ts = 145.236023
current_received_ts = 145.235748
current_seq = 22
count = 18
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.236023
last_received_ts = 145.235748
last_seq = 22
current_ts = 145.252686
current_received_ts = 145.252335
current_seq = 23
count = 19
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.252686
last_received_ts = 145.252335
last_seq = 23
current_ts = 145.269348
current_received_ts = 145.269028
current_seq = 24
count = 20
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 57us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.269348
last_received_ts = 145.269028
last_seq = 24
current_ts = 145.286026
current_received_ts = 145.285751
current_seq = 25
count = 21
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.286026
last_received_ts = 145.285751
last_seq = 25
current_ts = 145.302689
current_received_ts = 145.302460
current_seq = 26
count = 22
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.302689
last_received_ts = 145.302460
last_seq = 26
current_ts = 145.319351
current_received_ts = 145.319122
current_seq = 27
count = 23
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.319351
last_received_ts = 145.319122
last_seq = 27
current_ts = 145.336014
current_received_ts = 145.335648
current_seq = 28
count = 24
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.336014
last_received_ts = 145.335648
last_seq = 28
current_ts = 145.352692
current_received_ts = 145.352325
current_seq = 29
count = 25
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.352692
last_received_ts = 145.352325
last_seq = 29
current_ts = 145.369354
current_received_ts = 145.369156
current_seq = 30
count = 26
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.369354
last_received_ts = 145.369156
last_seq = 30
current_ts = 145.386017
current_received_ts = 145.385681
current_seq = 31
count = 27
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.386017
last_received_ts = 145.385681
last_seq = 31
current_ts = 145.402695
current_received_ts = 145.402328
current_seq = 32
count = 28
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.402695
last_received_ts = 145.402328
last_seq = 32
current_ts = 145.419357
current_received_ts = 145.419174
current_seq = 33
count = 29
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.419357
last_received_ts = 145.419174
last_seq = 33
current_ts = 145.436035
current_received_ts = 145.435638
current_seq = 34
count = 30
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.436035
last_received_ts = 145.435638
last_seq = 34
current_ts = 145.452698
current_received_ts = 145.452332
current_seq = 35
count = 31
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.452698
last_received_ts = 145.452332
last_seq = 35
current_ts = 145.469360
current_received_ts = 145.469162
current_seq = 36
count = 32
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.469360
last_received_ts = 145.469162
last_seq = 36
current_ts = 145.486038
current_received_ts = 145.485657
current_seq = 37
count = 33
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.486038
last_received_ts = 145.485657
last_seq = 37
current_ts = 145.502701
current_received_ts = 145.502319
current_seq = 38
count = 34
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.502701
last_received_ts = 145.502319
last_seq = 38
current_ts = 145.519363
current_received_ts = 145.519073
current_seq = 39
count = 35
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.519363
last_received_ts = 145.519073
last_seq = 39
current_ts = 145.536041
current_received_ts = 145.535706
current_seq = 40
count = 36
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.536041
last_received_ts = 145.535706
last_seq = 40
current_ts = 145.552704
current_received_ts = 145.552322
current_seq = 41
count = 37
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.552704
last_received_ts = 145.552322
last_seq = 41
current_ts = 145.569366
current_received_ts = 145.568939
current_seq = 42
count = 38
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 82us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.569366
last_received_ts = 145.568939
last_seq = 42
current_ts = 145.586044
current_received_ts = 145.585587
current_seq = 43
count = 39
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 50us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.586044
last_received_ts = 145.585587
last_seq = 43
current_ts = 145.602707
current_received_ts = 145.602310
current_seq = 44
count = 40
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 53us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.602707
last_received_ts = 145.602310
last_seq = 44
current_ts = 145.619370
current_received_ts = 145.619064
current_seq = 45
count = 41
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.619370
last_received_ts = 145.619064
last_seq = 45
current_ts = 145.636047
current_received_ts = 145.635712
current_seq = 46
count = 42
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.636047
last_received_ts = 145.635712
last_seq = 46
current_ts = 145.652710
current_received_ts = 145.652466
current_seq = 47
count = 43
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.652710
last_received_ts = 145.652466
last_seq = 47
current_ts = 145.669373
current_received_ts = 145.669067
current_seq = 48
count = 44
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.669373
last_received_ts = 145.669067
last_seq = 48
current_ts = 145.686050
current_received_ts = 145.685791
current_seq = 49
count = 45
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.686050
last_received_ts = 145.685791
last_seq = 49
current_ts = 145.702713
current_received_ts = 145.702332
current_seq = 50
count = 46
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.702713
last_received_ts = 145.702332
last_seq = 50
current_ts = 145.719391
current_received_ts = 145.719162
current_seq = 51
count = 47
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.719391
last_received_ts = 145.719162
last_seq = 51
current_ts = 145.736053
current_received_ts = 145.735703
current_seq = 52
count = 48
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.736053
last_received_ts = 145.735703
last_seq = 52
current_ts = 145.752716
current_received_ts = 145.752335
current_seq = 53
count = 49
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.752716
last_received_ts = 145.752335
last_seq = 53
current_ts = 145.769394
current_received_ts = 145.769073
current_seq = 54
count = 50
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 54us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.769394
last_received_ts = 145.769073
last_seq = 54
current_ts = 145.786057
current_received_ts = 145.785706
current_seq = 55
count = 51
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.786057
last_received_ts = 145.785706
last_seq = 55
current_ts = 145.802719
current_received_ts = 145.802322
current_seq = 56
count = 52
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.802719
last_received_ts = 145.802322
last_seq = 56
current_ts = 145.819397
current_received_ts = 145.819168
current_seq = 57
count = 53
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.819397
last_received_ts = 145.819168
last_seq = 57
current_ts = 145.836060
current_received_ts = 145.835709
current_seq = 58
count = 54
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.836060
last_received_ts = 145.835709
last_seq = 58
current_ts = 145.852722
current_received_ts = 145.852341
current_seq = 59
count = 55
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.852722
last_received_ts = 145.852341
last_seq = 59
current_ts = 145.869385
current_received_ts = 145.869080
current_seq = 60
count = 56
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.869385
last_received_ts = 145.869080
last_seq = 60
current_ts = 145.886063
current_received_ts = 145.885727
current_seq = 61
count = 57
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.886063
last_received_ts = 145.885727
last_seq = 61
current_ts = 145.902725
current_received_ts = 145.902344
current_seq = 62
count = 58
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.902725
last_received_ts = 145.902344
last_seq = 62
current_ts = 145.919388
current_received_ts = 145.919083
current_seq = 63
count = 59
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 54us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.919388
last_received_ts = 145.919083
last_seq = 63
current_ts = 145.936066
current_received_ts = 145.935806
current_seq = 64
count = 60
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.936066
last_received_ts = 145.935806
last_seq = 64
current_ts = 145.952728
current_received_ts = 145.952454
current_seq = 65
count = 61
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.952728
last_received_ts = 145.952454
last_seq = 65
current_ts = 145.969406
current_received_ts = 145.969070
current_seq = 66
count = 62
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.969406
last_received_ts = 145.969070
last_seq = 66
current_ts = 145.986069
current_received_ts = 145.985825
current_seq = 67
count = 63
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 145.986069
last_received_ts = 145.985825
last_seq = 67
current_ts = 146.002731
current_received_ts = 146.002472
current_seq = 68
count = 64
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.002731
last_received_ts = 146.002472
last_seq = 68
current_ts = 146.019409
current_received_ts = 146.019089
current_seq = 69
count = 65
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.019409
last_received_ts = 146.019089
last_seq = 69
current_ts = 146.036072
current_received_ts = 146.035812
current_seq = 70
count = 66
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.036072
last_received_ts = 146.035812
last_seq = 70
current_ts = 146.052734
current_received_ts = 146.052338
current_seq = 71
count = 67
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.052734
last_received_ts = 146.052338
last_seq = 71
current_ts = 146.069412
current_received_ts = 146.069183
current_seq = 72
count = 68
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.069412
last_received_ts = 146.069183
last_seq = 72
current_ts = 146.086075
current_received_ts = 146.085815
current_seq = 73
count = 69
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.086075
last_received_ts = 146.085815
last_seq = 73
current_ts = 146.102753
current_received_ts = 146.102341
current_seq = 74
count = 70
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.102753
last_received_ts = 146.102341
last_seq = 74
current_ts = 146.119415
current_received_ts = 146.119186
current_seq = 75
count = 71
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.119415
last_received_ts = 146.119186
last_seq = 75
current_ts = 146.136078
current_received_ts = 146.135834
current_seq = 76
count = 72
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 54us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.136078
last_received_ts = 146.135834
last_seq = 76
current_ts = 146.152740
current_received_ts = 146.152451
current_seq = 77
count = 73
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.152740
last_received_ts = 146.152451
last_seq = 77
current_ts = 146.169418
current_received_ts = 146.169205
current_seq = 78
count = 74
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.169418
last_received_ts = 146.169205
last_seq = 78
current_ts = 146.186081
current_received_ts = 146.185837
current_seq = 79
count = 75
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.186081
last_received_ts = 146.185837
last_seq = 79
current_ts = 146.202744
current_received_ts = 146.202454
current_seq = 80
count = 76
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.202744
last_received_ts = 146.202454
last_seq = 80
current_ts = 146.219421
current_received_ts = 146.219101
current_seq = 81
count = 77
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.219421
last_received_ts = 146.219101
last_seq = 81
current_ts = 146.236084
current_received_ts = 146.235733
current_seq = 82
count = 78
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.236084
last_received_ts = 146.235733
last_seq = 82
current_ts = 146.252762
current_received_ts = 146.252365
current_seq = 83
count = 79
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.252762
last_received_ts = 146.252365
last_seq = 83
current_ts = 146.269424
current_received_ts = 146.269104
current_seq = 84
count = 80
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.269424
last_received_ts = 146.269104
last_seq = 84
current_ts = 146.286087
current_received_ts = 146.285751
current_seq = 85
count = 81
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.286087
last_received_ts = 146.285751
last_seq = 85
current_ts = 146.302765
current_received_ts = 146.302429
current_seq = 86
count = 82
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.302765
last_received_ts = 146.302429
last_seq = 86
current_ts = 146.319427
current_received_ts = 146.319107
current_seq = 87
count = 83
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.319427
last_received_ts = 146.319107
last_seq = 87
current_ts = 146.336105
current_received_ts = 146.335846
current_seq = 88
count = 84
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.336105
last_received_ts = 146.335846
last_seq = 88
current_ts = 146.352768
current_received_ts = 146.352356
current_seq = 89
count = 85
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.352768
last_received_ts = 146.352356
last_seq = 89
current_ts = 146.369431
current_received_ts = 146.369110
current_seq = 90
count = 86
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.369431
last_received_ts = 146.369110
last_seq = 90
current_ts = 146.386093
current_received_ts = 146.385773
current_seq = 91
count = 87
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.386093
last_received_ts = 146.385773
last_seq = 91
current_ts = 146.402771
current_received_ts = 146.402359
current_seq = 92
count = 88
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.402771
last_received_ts = 146.402359
last_seq = 92
current_ts = 146.419449
current_received_ts = 146.419128
current_seq = 93
count = 89
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 57us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.419449
last_received_ts = 146.419128
last_seq = 93
current_ts = 146.436096
current_received_ts = 146.435760
current_seq = 94
count = 90
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.436096
last_received_ts = 146.435760
last_seq = 94
current_ts = 146.452774
current_received_ts = 146.452377
current_seq = 95
count = 91
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 55us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.452774
last_received_ts = 146.452377
last_seq = 95
current_ts = 146.469437
current_received_ts = 146.469116
current_seq = 96
count = 92
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.469437
last_received_ts = 146.469116
last_seq = 96
current_ts = 146.486099
current_received_ts = 146.485764
current_seq = 97
count = 93
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 56us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.486099
last_received_ts = 146.485764
last_seq = 97
current_ts = 146.502777
current_received_ts = 146.502319
current_seq = 98
count = 94
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 51us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.502777
last_received_ts = 146.502319
last_seq = 98
current_ts = 146.519440
current_received_ts = 146.518951
current_seq = 99
count = 95
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 74us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.519440
last_received_ts = 146.518951
last_seq = 99
current_ts = 146.536118
current_received_ts = 146.535614
current_seq = 100
count = 96
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 48us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.536118
last_received_ts = 146.535614
last_seq = 100
current_ts = 146.552780
current_received_ts = 146.552292
current_seq = 101
count = 97
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 47us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.552780
last_received_ts = 146.552292
last_seq = 101
current_ts = 146.569458
current_received_ts = 146.568970
current_seq = 102
count = 98
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 70us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.569458
last_received_ts = 146.568970
last_seq = 102
current_ts = 146.586121
current_received_ts = 146.585617
current_seq = 103
count = 99
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 48us
(kms_flip:2105) DEBUG: name = flip
last_ts = 146.586121
last_received_ts = 146.585617
last_seq = 103
current_ts = 146.602783
current_received_ts = 146.602295
current_seq = 104
count = 100
seq_step = 1
(kms_flip:2105) DEBUG: Vblank took 530us
(kms_flip:2105) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2105) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2105) igt_core-INFO: Stack trace:
(kms_flip:2105) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2105) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:2105) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:2105) igt_core-INFO:   #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045()
(kms_flip:2105) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:2105) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2105) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2105) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A3: FAIL (2.124s)

Dmesg

<6> [145.086274] [IGT] kms_flip: starting dynamic subtest B-HDMI-A3

<7> [145.086850] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:560]

<7> [145.087069] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:561]

<7> [145.087530] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [145.088390] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [145.118264] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [145.118864] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [145.128746] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [145.129349] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [145.151818] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [145.153212] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [145.179813] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:149:pipe A]

<7> [145.179920] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.enable (expected yes, found no)

<7> [145.180121] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.active (expected yes, found no)

<7> [145.180295] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)

<7> [145.180469] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in lane_count (expected 4, found 0)

<7> [145.180643] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000)

<7> [145.180817] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)

<7> [145.180999] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0)

<7> [145.181175] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0)

<7> [145.181349] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0)

<7> [145.181523] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0)

<7> [145.181697] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0)

<7> [145.181915] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0)

<7> [145.182090] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0)

<7> [145.182264] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0)

<7> [145.182437] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0)

<7> [145.182610] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0)

<7> [145.182785] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0)

<7> [145.183032] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0)

<7> [145.183206] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0)

<7> [145.183380] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0)

<7> [145.183554] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0)

<7> [145.183727] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0)

<7> [145.183942] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0)

<7> [145.184117] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0)

<7> [145.184292] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0)

<7> [145.184467] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0)

<7> [145.184642] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0)

<7> [145.184816] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0)

<7> [145.185062] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0)

<7> [145.185237] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0)

<7> [145.185412] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)

<7> [145.185587] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0)

<7> [145.185762] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0)

<7> [145.186007] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)

<7> [145.186182] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0)

<7> [145.186356] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0)

<7> [145.186532] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in port_clock (expected 148500, found 0)

<7> [145.186707] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:149:pipe A] fastset requirement not met, forcing full modeset

<7> [145.186971] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0xf), mbus joined? no->no

<7> [145.187141] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:149:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0

<7> [145.187334] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:143:cursor A] ddb (1963 - 2048) -> ( 0 - 0), size 85 -> 0

<7> [145.187532] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:149:pipe A] min cdclk: 74250 kHz -> 0 kHz

<7> [145.187706] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz

<7> [145.187918] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0

<7> [145.188093] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:149:pipe A] enable: no [modeset]

<7> [145.188267] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:33:plane 1A] fb: [NOFB], visible: no

<7> [145.188441] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 2A] fb: [NOFB], visible: no

<7> [145.188615] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:93:plane 3A] fb: [NOFB], visible: no

<7> [145.188788] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:123:plane 4A] fb: [NOFB], visible: no

<7> [145.189004] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:133:plane 5A] fb: [NOFB], visible: no

<7> [145.189178] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:143:cursor A] fb: [NOFB], visible: no

<7> [145.189555] i915 0000:03:00.0: [drm:intel_disable_transcoder [i915]] disabling pipe A

<7> [145.203034] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_D

<7> [145.203273] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:505:DDI A/PHY A]

<7> [145.203445] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DP-MST A]

<7> [145.203617] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:508:DP-MST B]

<7> [145.203789] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST C]

<7> [145.204010] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST D]

<7> [145.204182] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DDI B/PHY B]

<7> [145.204352] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST A]

<7> [145.204523] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST B]

<7> [145.204694] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST C]

<7> [145.204940] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST D]

<7> [145.205182] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:533:DDI C/PHY C]

<7> [145.205353] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DP-MST A]

<7> [145.205523] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST B]

<7> [145.205693] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST C]

<7> [145.205905] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST D]

<7> [145.206076] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:545:DDI D/PHY D]

<7> [145.206266] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DP-MST A]

<7> [145.206438] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST B]

<7> [145.206609] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST C]

<7> [145.206780] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST D]

<7> [145.206990] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:554:HDMI-A-3]

<7> [145.207199] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1

<7> [145.207476] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_A

<7> [145.207712] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_2

<7> [145.207967] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:149:pipe A]

<7> [145.208323] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:267:pipe B]

<7> [145.208475] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:385:pipe C]

<7> [145.208617] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:503:pipe D]

<7> [145.208759] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:267:pipe B]

<7> [145.208788] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:554:HDMI-A-3]

<7> [145.208899] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CONNECTOR:554:HDMI-A-3] Limiting display bpp to 24 (EDID bpp 0, max requested bpp 36, max platform bpp 36)

<7> [145.209083] i915 0000:03:00.0: [drm:intel_hdmi_compute_clock [i915]] picking 8 bpc for HDMI output (pipe bpp: 24)

<7> [145.209245] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:267:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0

<7> [145.209421] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:545:DDI D/PHY D] [CRTC:267:pipe B]

<7> [145.209587] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.enable (expected no, found yes)

<7> [145.209761] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.active (expected no, found yes)

<7> [145.209981] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)

<7> [145.210156] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in lane_count (expected 0, found 4)

<7> [145.210331] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040)

<7> [145.210506] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)

<7> [145.210681] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920)

<7> [145.210891] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200)

<7> [145.211065] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920)

<7> [145.211239] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200)

<7> [145.211413] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008)

<7> [145.211587] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052)

<7> [145.211760] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080)

<7> [145.211973] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080)

<7> [145.212147] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084)

<7> [145.212320] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089)

<7> [145.212495] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125)

<7> [145.212669] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125)

<7> [145.212869] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920)

<7> [145.213057] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200)

<7> [145.213231] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920)

<7> [145.213405] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200)

<7> [145.213579] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008)

<7> [145.213753] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052)

<7> [145.213966] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080)

<7> [145.214140] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080)

<7> [145.214315] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084)

<7> [145.214488] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089)

<7> [145.214663] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125)

<7> [145.214860] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125)

<7> [145.215078] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)

<7> [145.215252] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1)

<7> [145.215426] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4)

<7> [145.215600] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)

<7> [145.215773] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500)

<7> [145.216033] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500)

<7> [145.216208] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in port_clock (expected 0, found 148500)

<7> [145.216383] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:267:pipe B] fastset requirement not met, forcing full modeset

<7> [145.216577] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0xf), mbus joined? no->no

<7> [145.216747] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:267:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2

<7> [145.216981] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:151:plane 1B] ddb ( 0 - 0) -> ( 0 - 1963), size 0 -> 1963

<7> [145.217150] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:261:cursor B] ddb ( 0 - 0) -> (1963 - 2048), size 0 -> 85

<7> [145.217320] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5,*wm6,*wm7,*twm, swm, stwm

<7> [145.217489] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 4, 5, 9, 11, 17, 25, 0, 0, 0

<7> [145.217657] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 62, 78, 139, 169, 261, 383, 137, 0, 0

<7> [145.217832] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 123, 184, 245, 245, 367, 489, 138, 0, 0

<7> [145.218045] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:267:pipe B] data rate 594000 num active planes 1

<7> [145.218220] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 50000 required 624

<7> [145.218393] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1

<7> [145.218578] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:267:pipe B] min cdclk: 0 kHz -> 74250 kHz

<7> [145.218765] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz

<7> [145.218977] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0

<7> [145.219150] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:267:pipe B] enable: yes [modeset]

<7> [145.219325] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB

<7> [145.219498] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0

<7> [145.219672] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>

<7> [145.219884] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0

<7> [145.220093] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0

<7> [145.220266] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0

<7> [145.220439] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0

<7> [145.220613] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

<7> [145.220785] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0

<7> [145.220999] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 45 vsync start: 41, vsync end: 36

<7> [145.221173] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1080, vmax vblank: 1080, vmin vtotal: 1125, vmax vtotal: 1125

<7> [145.221347] i915 0000:03:00.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> [145.221520] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5

<7> [145.221695] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5

<7> [145.221908] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [145.222083] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5

<7> [145.222258] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [145.222433] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port clock: 148500, pipe src: 1920x1080+0+0, pixel rate 148500, min cdclk 74250

<7> [145.222607] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] linetime: 119, ips linetime: 0

<7> [145.222781] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0

<7> [145.222993] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no

<7> [145.223167] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0

<7> [145.223340] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x24414, dpll_md: 0x18000000, fp0: 0x8801ef8, fp1: 0x2b000440

<7> [145.223514] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

<7> [145.223688] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries

<7> [145.223903] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000

<7> [145.224078] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [145.224251] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [145.224424] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [145.224598] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000

<7> [145.224772] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000

<7> [145.224986] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [145.225160] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [145.225332] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [145.225505] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000

<7> [145.225679] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0

<7> [145.225894] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:151:plane 1B] fb: [FB:560] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes

<7> [145.225970] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DC_off

<7> [145.226102] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0

<7> [145.226202] i915 0000:03:00.0: [drm:gen9_enable_dc5 [i915]] Enabling DC5

<7> [145.226275] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0

<7> [145.226382] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 01

<7> [145.226449] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:181:plane 2B] fb: [NOFB], visible: no

<7> [145.226624] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:211:plane 3B] fb: [NOFB], visible: no

<7> [145.226797] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:241:plane 4B] fb: [NOFB], visible: no

<7> [145.227007] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:251:plane 5B] fb: [NOFB], visible: no

<7> [145.227180] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:261:cursor B] fb: [NOFB], visible: no

<7> [145.227756] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DC_off

<7> [145.228099] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 01 to 00

<7> [145.228460] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_2

<7> [145.228657] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_B

<7> [145.228922] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:505:DDI A/PHY A]

<7> [145.229093] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DP-MST A]

<7> [145.229265] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:508:DP-MST B]

<7> [145.229436] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST C]

<7> [145.229607] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST D]

<7> [145.229779] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DDI B/PHY B]

<7> [145.229991] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST A]

<7> [145.230164] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST B]

<7> [145.230335] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST C]

<7> [145.230507] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST D]

<7> [145.230679] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:533:DDI C/PHY C]

<7> [145.230889] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DP-MST A]

<7> [145.231061] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST B]

<7> [145.231233] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST C]

<7> [145.231404] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST D]

<7> [145.231576] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:545:DDI D/PHY D]

<7> [145.231748] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DP-MST A]

<7> [145.231958] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST B]

<7> [145.232130] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST C]

<7> [145.232301] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST D]

<7> [145.232473] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3

<7> [145.232876] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_D

<7> [145.233212] i915 0000:03:00.0: [drm:intel_enable_transcoder [i915]] enabling pipe B

<7> [145.252442] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:554:HDMI-A-3]

<7> [145.252756] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:267:pipe B]

<6> [147.210115] [IGT] kms_flip: finished subtest B-HDMI-A3, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a3