igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a1 on shard-glk@IGTPW

Detail	Value
Duration	2.58 seconds
Hostname	shard-glk2
Igt-Version	IGT-Version: 2.4-ga22943872 (x86_64) (Linux: 7.1.0-rc2-CI_DRM_18452-g680a4832a818+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A1 1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-HDMI-A1: FAIL (2.582s)
Err	Starting dynamic subtest: B-HDMI-A1 (kms_flip:4770) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:4770) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-HDMI-A1 failed. ** DEBUG (kms_flip:4770) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0) (kms_flip:4770) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:4770) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:4770) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680) (kms_flip:4770) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:4770) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0) (kms_flip:4770) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:4770) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:4770) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680) (kms_flip:4770) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:4770) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:4770) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:4770) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS (kms_flip:4770) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:4770) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:4770) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS (kms_flip:4770) igt_kms-INFO: 1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 (kms_flip:4770) DEBUG: No stale events found (kms_flip:4770) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 (kms_flip:4770) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 (kms_flip:4770) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 659.961487 current_received_ts = 659.961060 current_seq = 18336 count = 0 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 9us (kms_flip:4770) DEBUG: name = flip last_ts = 659.961487 last_received_ts = 659.961060 last_seq = 18336 current_ts = 659.978149 current_received_ts = 659.977722 current_seq = 18337 count = 1 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 7us (kms_flip:4770) DEBUG: name = flip last_ts = 659.978149 last_received_ts = 659.977722 last_seq = 18337 current_ts = 659.994812 current_received_ts = 659.994324 current_seq = 18338 count = 2 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 6us (kms_flip:4770) DEBUG: name = flip last_ts = 659.994812 last_received_ts = 659.994324 last_seq = 18338 current_ts = 660.011475 current_received_ts = 660.011047 current_seq = 18339 count = 3 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 7us (kms_flip:4770) DEBUG: name = flip last_ts = 660.011475 last_received_ts = 660.011047 last_seq = 18339 current_ts = 660.028137 current_received_ts = 660.028076 current_seq = 18340 count = 4 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 660.028137 last_received_ts = 660.028076 last_seq = 18340 current_ts = 660.044800 current_received_ts = 660.044617 current_seq = 18341 count = 5 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.044800 last_received_ts = 660.044617 last_seq = 18341 current_ts = 660.061462 current_received_ts = 660.061157 current_seq = 18342 count = 6 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 22us (kms_flip:4770) DEBUG: name = flip last_ts = 660.061462 last_received_ts = 660.061157 last_seq = 18342 current_ts = 660.078125 current_received_ts = 660.078064 current_seq = 18343 count = 7 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 660.078125 last_received_ts = 660.078064 last_seq = 18343 current_ts = 660.094788 current_received_ts = 660.094666 current_seq = 18344 count = 8 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.094788 last_received_ts = 660.094666 last_seq = 18344 current_ts = 660.111450 current_received_ts = 660.111328 current_seq = 18345 count = 9 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 660.111450 last_received_ts = 660.111328 last_seq = 18345 current_ts = 660.128113 current_received_ts = 660.127991 current_seq = 18346 count = 10 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 18us (kms_flip:4770) DEBUG: name = flip last_ts = 660.128113 last_received_ts = 660.127991 last_seq = 18346 current_ts = 660.144836 current_received_ts = 660.144592 current_seq = 18347 count = 11 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 660.144836 last_received_ts = 660.144592 last_seq = 18347 current_ts = 660.161438 current_received_ts = 660.161316 current_seq = 18348 count = 12 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 18us (kms_flip:4770) DEBUG: name = flip last_ts = 660.161438 last_received_ts = 660.161316 last_seq = 18348 current_ts = 660.178162 current_received_ts = 660.178101 current_seq = 18349 count = 13 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.178162 last_received_ts = 660.178101 last_seq = 18349 current_ts = 660.194824 current_received_ts = 660.194702 current_seq = 18350 count = 14 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 660.194824 last_received_ts = 660.194702 last_seq = 18350 current_ts = 660.211487 current_received_ts = 660.211365 current_seq = 18351 count = 15 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 660.211487 last_received_ts = 660.211365 last_seq = 18351 current_ts = 660.228149 current_received_ts = 660.228088 current_seq = 18352 count = 16 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 660.228149 last_received_ts = 660.228088 last_seq = 18352 current_ts = 660.244812 current_received_ts = 660.244690 current_seq = 18353 count = 17 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 660.244812 last_received_ts = 660.244690 last_seq = 18353 current_ts = 660.261475 current_received_ts = 660.261353 current_seq = 18354 count = 18 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 660.261475 last_received_ts = 660.261353 last_seq = 18354 current_ts = 660.278137 current_received_ts = 660.278076 current_seq = 18355 count = 19 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 660.278137 last_received_ts = 660.278076 last_seq = 18355 current_ts = 660.294800 current_received_ts = 660.294678 current_seq = 18356 count = 20 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 660.294800 last_received_ts = 660.294678 last_seq = 18356 current_ts = 660.311462 current_received_ts = 660.311340 current_seq = 18357 count = 21 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 660.311462 last_received_ts = 660.311340 last_seq = 18357 current_ts = 660.328125 current_received_ts = 660.328064 current_seq = 18358 count = 22 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 660.328125 last_received_ts = 660.328064 last_seq = 18358 current_ts = 660.344788 current_received_ts = 660.344666 current_seq = 18359 count = 23 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.344788 last_received_ts = 660.344666 last_seq = 18359 current_ts = 660.361450 current_received_ts = 660.361328 current_seq = 18360 count = 24 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 19us (kms_flip:4770) DEBUG: name = flip last_ts = 660.361450 last_received_ts = 660.361328 last_seq = 18360 current_ts = 660.378174 current_received_ts = 660.377930 current_seq = 18361 count = 25 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 660.378174 last_received_ts = 660.377930 last_seq = 18361 current_ts = 660.394836 current_received_ts = 660.394653 current_seq = 18362 count = 26 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 660.394836 last_received_ts = 660.394653 last_seq = 18362 current_ts = 660.411499 current_received_ts = 660.411316 current_seq = 18363 count = 27 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 23us (kms_flip:4770) DEBUG: name = flip last_ts = 660.411499 last_received_ts = 660.411316 last_seq = 18363 current_ts = 660.428162 current_received_ts = 660.427979 current_seq = 18364 count = 28 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 660.428162 last_received_ts = 660.427979 last_seq = 18364 current_ts = 660.444824 current_received_ts = 660.444641 current_seq = 18365 count = 29 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.444824 last_received_ts = 660.444641 last_seq = 18365 current_ts = 660.461487 current_received_ts = 660.461365 current_seq = 18366 count = 30 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 23us (kms_flip:4770) DEBUG: name = flip last_ts = 660.461487 last_received_ts = 660.461365 last_seq = 18366 current_ts = 660.478149 current_received_ts = 660.477783 current_seq = 18367 count = 31 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.478149 last_received_ts = 660.477783 last_seq = 18367 current_ts = 660.494812 current_received_ts = 660.494568 current_seq = 18368 count = 32 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.494812 last_received_ts = 660.494568 last_seq = 18368 current_ts = 660.511475 current_received_ts = 660.511292 current_seq = 18369 count = 33 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.511475 last_received_ts = 660.511292 last_seq = 18369 current_ts = 660.528137 current_received_ts = 660.528076 current_seq = 18370 count = 34 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 660.528137 last_received_ts = 660.528076 last_seq = 18370 current_ts = 660.544800 current_received_ts = 660.544617 current_seq = 18371 count = 35 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 660.544800 last_received_ts = 660.544617 last_seq = 18371 current_ts = 660.561462 current_received_ts = 660.561340 current_seq = 18372 count = 36 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 23us (kms_flip:4770) DEBUG: name = flip last_ts = 660.561462 last_received_ts = 660.561340 last_seq = 18372 current_ts = 660.578125 current_received_ts = 660.578064 current_seq = 18373 count = 37 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.578125 last_received_ts = 660.578064 last_seq = 18373 current_ts = 660.594788 current_received_ts = 660.594666 current_seq = 18374 count = 38 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 660.594788 last_received_ts = 660.594666 last_seq = 18374 current_ts = 660.611450 current_received_ts = 660.611328 current_seq = 18375 count = 39 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 660.611450 last_received_ts = 660.611328 last_seq = 18375 current_ts = 660.628174 current_received_ts = 660.627991 current_seq = 18376 count = 40 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 660.628174 last_received_ts = 660.627991 last_seq = 18376 current_ts = 660.644836 current_received_ts = 660.645325 current_seq = 18377 count = 41 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 35us (kms_flip:4770) DEBUG: name = flip last_ts = 660.644836 last_received_ts = 660.645325 last_seq = 18377 current_ts = 660.661499 current_received_ts = 660.661011 current_seq = 18378 count = 42 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 22us (kms_flip:4770) DEBUG: name = flip last_ts = 660.661499 last_received_ts = 660.661011 last_seq = 18378 current_ts = 660.678162 current_received_ts = 660.677979 current_seq = 18379 count = 43 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 660.678162 last_received_ts = 660.677979 last_seq = 18379 current_ts = 660.694824 current_received_ts = 660.694641 current_seq = 18380 count = 44 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.694824 last_received_ts = 660.694641 last_seq = 18380 current_ts = 660.711487 current_received_ts = 660.711365 current_seq = 18381 count = 45 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 660.711487 last_received_ts = 660.711365 last_seq = 18381 current_ts = 660.728149 current_received_ts = 660.727966 current_seq = 18382 count = 46 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 28us (kms_flip:4770) DEBUG: name = flip last_ts = 660.728149 last_received_ts = 660.727966 last_seq = 18382 current_ts = 660.744812 current_received_ts = 660.744629 current_seq = 18383 count = 47 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.744812 last_received_ts = 660.744629 last_seq = 18383 current_ts = 660.761475 current_received_ts = 660.761292 current_seq = 18384 count = 48 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 20us (kms_flip:4770) DEBUG: name = flip last_ts = 660.761475 last_received_ts = 660.761292 last_seq = 18384 current_ts = 660.778137 current_received_ts = 660.777954 current_seq = 18385 count = 49 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 660.778137 last_received_ts = 660.777954 last_seq = 18385 current_ts = 660.794800 current_received_ts = 660.794678 current_seq = 18386 count = 50 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 660.794800 last_received_ts = 660.794678 last_seq = 18386 current_ts = 660.811462 current_received_ts = 660.811279 current_seq = 18387 count = 51 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.811462 last_received_ts = 660.811279 last_seq = 18387 current_ts = 660.828125 current_received_ts = 660.828003 current_seq = 18388 count = 52 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.828125 last_received_ts = 660.828003 last_seq = 18388 current_ts = 660.844788 current_received_ts = 660.844666 current_seq = 18389 count = 53 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 660.844788 last_received_ts = 660.844666 last_seq = 18389 current_ts = 660.861511 current_received_ts = 660.861267 current_seq = 18390 count = 54 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.861511 last_received_ts = 660.861267 last_seq = 18390 current_ts = 660.878174 current_received_ts = 660.878113 current_seq = 18391 count = 55 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.878174 last_received_ts = 660.878113 last_seq = 18391 current_ts = 660.894836 current_received_ts = 660.894714 current_seq = 18392 count = 56 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.894836 last_received_ts = 660.894714 last_seq = 18392 current_ts = 660.911499 current_received_ts = 660.911316 current_seq = 18393 count = 57 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 23us (kms_flip:4770) DEBUG: name = flip last_ts = 660.911499 last_received_ts = 660.911316 last_seq = 18393 current_ts = 660.928162 current_received_ts = 660.927979 current_seq = 18394 count = 58 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.928162 last_received_ts = 660.927979 last_seq = 18394 current_ts = 660.944824 current_received_ts = 660.944580 current_seq = 18395 count = 59 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.944824 last_received_ts = 660.944580 last_seq = 18395 current_ts = 660.961487 current_received_ts = 660.961304 current_seq = 18396 count = 60 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 20us (kms_flip:4770) DEBUG: name = flip last_ts = 660.961487 last_received_ts = 660.961304 last_seq = 18396 current_ts = 660.978149 current_received_ts = 660.977966 current_seq = 18397 count = 61 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 660.978149 last_received_ts = 660.977966 last_seq = 18397 current_ts = 660.994812 current_received_ts = 660.994629 current_seq = 18398 count = 62 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 23us (kms_flip:4770) DEBUG: name = flip last_ts = 660.994812 last_received_ts = 660.994629 last_seq = 18398 current_ts = 661.011475 current_received_ts = 661.011108 current_seq = 18399 count = 63 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 661.011475 last_received_ts = 661.011108 last_seq = 18399 current_ts = 661.028137 current_received_ts = 661.027893 current_seq = 18400 count = 64 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 120us (kms_flip:4770) DEBUG: name = flip last_ts = 661.028137 last_received_ts = 661.027893 last_seq = 18400 current_ts = 661.044800 current_received_ts = 661.044678 current_seq = 18401 count = 65 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 661.044800 last_received_ts = 661.044678 last_seq = 18401 current_ts = 661.061462 current_received_ts = 661.061279 current_seq = 18402 count = 66 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 661.061462 last_received_ts = 661.061279 last_seq = 18402 current_ts = 661.078125 current_received_ts = 661.078125 current_seq = 18403 count = 67 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 23us (kms_flip:4770) DEBUG: name = flip last_ts = 661.078125 last_received_ts = 661.078125 last_seq = 18403 current_ts = 661.094788 current_received_ts = 661.094604 current_seq = 18404 count = 68 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 661.094788 last_received_ts = 661.094604 last_seq = 18404 current_ts = 661.111511 current_received_ts = 661.111328 current_seq = 18405 count = 69 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 661.111511 last_received_ts = 661.111328 last_seq = 18405 current_ts = 661.128174 current_received_ts = 661.128113 current_seq = 18406 count = 70 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 661.128174 last_received_ts = 661.128113 last_seq = 18406 current_ts = 661.144836 current_received_ts = 661.144714 current_seq = 18407 count = 71 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 661.144836 last_received_ts = 661.144714 last_seq = 18407 current_ts = 661.161499 current_received_ts = 661.161377 current_seq = 18408 count = 72 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 661.161499 last_received_ts = 661.161377 last_seq = 18408 current_ts = 661.178162 current_received_ts = 661.178101 current_seq = 18409 count = 73 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 661.178162 last_received_ts = 661.178101 last_seq = 18409 current_ts = 661.194824 current_received_ts = 661.194702 current_seq = 18410 count = 74 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 23us (kms_flip:4770) DEBUG: name = flip last_ts = 661.194824 last_received_ts = 661.194702 last_seq = 18410 current_ts = 661.211487 current_received_ts = 661.211304 current_seq = 18411 count = 75 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 661.211487 last_received_ts = 661.211304 last_seq = 18411 current_ts = 661.228149 current_received_ts = 661.228088 current_seq = 18412 count = 76 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 661.228149 last_received_ts = 661.228088 last_seq = 18412 current_ts = 661.244812 current_received_ts = 661.244690 current_seq = 18413 count = 77 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 661.244812 last_received_ts = 661.244690 last_seq = 18413 current_ts = 661.261475 current_received_ts = 661.261353 current_seq = 18414 count = 78 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 661.261475 last_received_ts = 661.261353 last_seq = 18414 current_ts = 661.278137 current_received_ts = 661.278076 current_seq = 18415 count = 79 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 19us (kms_flip:4770) DEBUG: name = flip last_ts = 661.278137 last_received_ts = 661.278076 last_seq = 18415 current_ts = 661.294800 current_received_ts = 661.294678 current_seq = 18416 count = 80 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 661.294800 last_received_ts = 661.294678 last_seq = 18416 current_ts = 661.311462 current_received_ts = 661.311279 current_seq = 18417 count = 81 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 661.311462 last_received_ts = 661.311279 last_seq = 18417 current_ts = 661.328186 current_received_ts = 661.328003 current_seq = 18418 count = 82 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 661.328186 last_received_ts = 661.328003 last_seq = 18418 current_ts = 661.344849 current_received_ts = 661.344666 current_seq = 18419 count = 83 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 661.344849 last_received_ts = 661.344666 last_seq = 18419 current_ts = 661.361511 current_received_ts = 661.361389 current_seq = 18420 count = 84 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 20us (kms_flip:4770) DEBUG: name = flip last_ts = 661.361511 last_received_ts = 661.361389 last_seq = 18420 current_ts = 661.378174 current_received_ts = 661.378052 current_seq = 18421 count = 85 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 21us (kms_flip:4770) DEBUG: name = flip last_ts = 661.378174 last_received_ts = 661.378052 last_seq = 18421 current_ts = 661.394836 current_received_ts = 661.394653 current_seq = 18422 count = 86 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 661.394836 last_received_ts = 661.394653 last_seq = 18422 current_ts = 661.411499 current_received_ts = 661.411316 current_seq = 18423 count = 87 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 661.411499 last_received_ts = 661.411316 last_seq = 18423 current_ts = 661.428162 current_received_ts = 661.427979 current_seq = 18424 count = 88 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 23us (kms_flip:4770) DEBUG: name = flip last_ts = 661.428162 last_received_ts = 661.427979 last_seq = 18424 current_ts = 661.444824 current_received_ts = 661.444641 current_seq = 18425 count = 89 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 661.444824 last_received_ts = 661.444641 last_seq = 18425 current_ts = 661.461487 current_received_ts = 661.461304 current_seq = 18426 count = 90 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 661.461487 last_received_ts = 661.461304 last_seq = 18426 current_ts = 661.478149 current_received_ts = 661.478088 current_seq = 18427 count = 91 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 661.478149 last_received_ts = 661.478088 last_seq = 18427 current_ts = 661.494812 current_received_ts = 661.494629 current_seq = 18428 count = 92 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 661.494812 last_received_ts = 661.494629 last_seq = 18428 current_ts = 661.511475 current_received_ts = 661.511292 current_seq = 18429 count = 93 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 661.511475 last_received_ts = 661.511292 last_seq = 18429 current_ts = 661.528137 current_received_ts = 661.528076 current_seq = 18430 count = 94 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 661.528137 last_received_ts = 661.528076 last_seq = 18430 current_ts = 661.544861 current_received_ts = 661.544678 current_seq = 18431 count = 95 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 661.544861 last_received_ts = 661.544678 last_seq = 18431 current_ts = 661.561523 current_received_ts = 661.561279 current_seq = 18432 count = 96 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 26us (kms_flip:4770) DEBUG: name = flip last_ts = 661.561523 last_received_ts = 661.561279 last_seq = 18432 current_ts = 661.578186 current_received_ts = 661.578064 current_seq = 18433 count = 97 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 661.578186 last_received_ts = 661.578064 last_seq = 18433 current_ts = 661.594849 current_received_ts = 661.594666 current_seq = 18434 count = 98 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 27us (kms_flip:4770) DEBUG: name = flip last_ts = 661.594849 last_received_ts = 661.594666 last_seq = 18434 current_ts = 661.611511 current_received_ts = 661.611328 current_seq = 18435 count = 99 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 661.611511 last_received_ts = 661.611328 last_seq = 18435 current_ts = 661.628174 current_received_ts = 661.627991 current_seq = 18436 count = 100 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 24us (kms_flip:4770) DEBUG: name = flip last_ts = 661.628174 last_received_ts = 661.627991 last_seq = 18436 current_ts = 661.644836 current_received_ts = 661.644653 current_seq = 18437 count = 101 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 25us (kms_flip:4770) DEBUG: name = flip last_ts = 661.644836 last_received_ts = 661.644653 last_seq = 18437 current_ts = 661.661499 current_received_ts = 661.660950 current_seq = 18438 count = 102 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 17us (kms_flip:4770) DEBUG: name = flip last_ts = 661.661499 last_received_ts = 661.660950 last_seq = 18438 current_ts = 661.678162 current_received_ts = 661.678040 current_seq = 18439 count = 103 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 12us (kms_flip:4770) DEBUG: name = flip last_ts = 661.678162 last_received_ts = 661.678040 last_seq = 18439 current_ts = 661.694824 current_received_ts = 661.694275 current_seq = 18440 count = 104 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 12us (kms_flip:4770) DEBUG: name = flip last_ts = 661.694824 last_received_ts = 661.694275 last_seq = 18440 current_ts = 661.711487 current_received_ts = 661.710938 current_seq = 18441 count = 105 seq_step = 1 (kms_flip:4770) DEBUG: Vblank took 601us (kms_flip:4770) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:4770) CRITICAL: Failed assertion: end - start < 500 (kms_flip:4770) igt_core-INFO: Stack trace: (kms_flip:4770) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:4770) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:4770) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:4770) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() (kms_flip:4770) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:4770) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:4770) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:4770) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A1: FAIL (2.582s)
Dmesg	<6> [659.847448] [IGT] kms_flip: starting dynamic subtest B-HDMI-A1 <7> [659.849165] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:180] <7> [659.849633] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:182] <7> [659.907370] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A] <7> [659.907873] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [659.909651] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [659.911318] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [659.911929] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [659.912753] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000) <7> [659.913398] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [659.913873] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [659.914487] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [659.914928] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [659.915541] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [659.915956] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [659.916556] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [659.916948] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [659.917657] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [659.918317] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [659.918717] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [659.919103] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [659.919694] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [659.920078] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [659.920632] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [659.921106] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [659.921748] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [659.922462] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [659.922876] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [659.923474] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [659.923867] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [659.924666] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [659.925381] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [659.925774] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [659.926357] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [659.926745] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [659.927380] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [659.927773] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [659.928300] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [659.928798] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [659.929328] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_infoframe (expected yes, found no) <7> [659.929742] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [659.930248] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [659.930633] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [659.931022] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in port_clock (expected 222750, found 0) <7> [659.931637] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [659.932081] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000) <7> [659.932571] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in avi infoframe <7> [659.932964] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [659.933437] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [659.933443] i915 0000:00:02.0: colorspace: RGB <7> [659.933447] i915 0000:00:02.0: scan mode: Underscan <7> [659.933450] i915 0000:00:02.0: colorimetry: No Data <7> [659.933453] i915 0000:00:02.0: picture aspect: No Data <7> [659.933456] i915 0000:00:02.0: active aspect: Same as Picture <7> [659.933460] i915 0000:00:02.0: itc: No Data <7> [659.933463] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [659.933466] i915 0000:00:02.0: quantization range: Full <7> [659.933469] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [659.933472] i915 0000:00:02.0: video code: 0 <7> [659.933475] i915 0000:00:02.0: ycc quantization range: Full <7> [659.933478] i915 0000:00:02.0: hdmi content type: Graphics <7> [659.933482] i915 0000:00:02.0: pixel repeat: 0 <7> [659.933485] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [659.933489] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [659.933870] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in spd infoframe <7> [659.934387] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [659.934861] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [659.934866] i915 0000:00:02.0: vendor: Intel <7> [659.934870] i915 0000:00:02.0: product: Integrated gfx <7> [659.934873] i915 0000:00:02.0: source device information: PC General (0x9) <7> [659.934877] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [659.935458] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hdmi infoframe <7> [659.935909] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [659.936436] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [659.936441] i915 0000:00:02.0: empty frame <7> [659.936444] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [659.936872] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:78:pipe A] fastset requirement not met, forcing full modeset <7> [659.937397] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:78:pipe A] releasing PORT PLL B <7> [659.937847] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:78:pipe A] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [659.938454] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:72:cursor A] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0 <7> [659.938926] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:78:pipe A] min cdclk: 192000 kHz -> 0 kHz <7> [659.939572] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [659.939965] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz <7> [659.940472] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4 <7> [659.940862] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:78:pipe A] enable: no [modeset] <7> [659.941325] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:36:plane 1A] fb: [NOFB], visible: no <7> [659.941708] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:45:plane 2A] fb: [NOFB], visible: no <7> [659.942092] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:plane 3A] fb: [NOFB], visible: no <7> [659.942575] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 4A] fb: [NOFB], visible: no <7> [659.942966] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:72:cursor A] fb: [NOFB], visible: no <7> [659.943760] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:166:HDMI-A-1][ENCODER:165:DDI B/PHY B] Disable audio codec on [CRTC:78:pipe A] <7> [659.973510] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [659.974113] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [659.991197] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time <7> [660.092539] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [660.093804] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x1, on? 1) for [CRTC:78:pipe A] <7> [660.096888] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL B <7> [660.097619] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 79200 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 4 <7> [660.098098] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [660.098695] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [660.099106] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:166:HDMI-A-1] <7> [660.100284] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-b <7> [660.100739] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [660.101342] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:78:pipe A] <7> [660.102587] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [660.102947] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C] <7> [660.103403] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [660.103463] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:166:HDMI-A-1] <7> [660.103650] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 12 bpc for HDMI output (pipe bpp: 36) <7> [660.104379] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [660.104782] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:165:DDI B/PHY B] [CRTC:121:pipe B] <7> [660.105266] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [660.105652] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [660.106038] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [660.107023] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [660.107543] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d) <7> [660.107953] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [660.108502] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [660.108889] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [660.109407] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [660.109792] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [660.110348] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [660.110764] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [660.111291] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [660.111694] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [660.112075] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [660.112556] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [660.112941] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [660.113435] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [660.113818] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [660.114288] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [660.114672] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [660.115075] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [660.115756] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [660.116426] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [660.116873] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [660.117459] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [660.117855] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [660.118360] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [660.118767] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [660.119253] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [660.119664] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [660.120050] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [660.120608] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [660.120998] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [660.121524] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [660.121941] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_infoframe (expected no, found yes) <7> [660.122435] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [660.122825] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [660.123304] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [660.123689] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in port_clock (expected 0, found 222750) <7> [660.124071] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [660.124594] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006) <7> [660.124985] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in avi infoframe <7> [660.125458] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [660.125840] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [660.126752] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [660.126758] i915 0000:00:02.0: colorspace: RGB <7> [660.126762] i915 0000:00:02.0: scan mode: Underscan <7> [660.126766] i915 0000:00:02.0: colorimetry: No Data <7> [660.126769] i915 0000:00:02.0: picture aspect: No Data <7> [660.126772] i915 0000:00:02.0: active aspect: Same as Picture <7> [660.126776] i915 0000:00:02.0: itc: No Data <7> [660.126779] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [660.126782] i915 0000:00:02.0: quantization range: Full <7> [660.126785] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [660.126789] i915 0000:00:02.0: video code: 0 <7> [660.126792] i915 0000:00:02.0: ycc quantization range: Full <7> [660.126795] i915 0000:00:02.0: hdmi content type: Graphics <7> [660.126798] i915 0000:00:02.0: pixel repeat: 0 <7> [660.126801] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [660.126806] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in spd infoframe <7> [660.127459] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [660.127873] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [660.128364] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [660.128369] i915 0000:00:02.0: vendor: Intel <7> [660.128372] i915 0000:00:02.0: product: Integrated gfx <7> [660.128376] i915 0000:00:02.0: source device information: PC General (0x9) <7> [660.128380] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hdmi infoframe <7> [660.128801] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [660.129301] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [660.129715] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [660.129719] i915 0000:00:02.0: empty frame <7> [660.129725] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] fastset requirement not met, forcing full modeset <7> [660.130349] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:121:pipe B] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x2 <7> [660.130803] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:79:plane 1B] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988 <7> [660.131369] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:115:cursor B] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32 <7> [660.131810] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79: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> [660.132327] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0 <7> [660.132717] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0 <7> [660.133096] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 17, 17, 17, 34, 34, 34, 34, 34, 31, 0, 0 <7> [660.133576] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb_uv 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [660.134021] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:121:pipe B] min cdclk: 0 kHz -> 192000 kHz <7> [660.134611] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [660.134999] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz <7> [660.135472] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13 <7> [660.135861] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:121:pipe B] using pre-allocated PORT PLL B <7> [660.137183] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:121:pipe B] reserving PORT PLL B <7> [660.137758] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:121:pipe B] enable: yes [modeset] <7> [660.138377] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [660.138792] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 36, dithering: 0 <7> [660.139354] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [660.139739] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [660.140303] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [660.140724] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [660.141102] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [660.141626] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6 <7> [660.142024] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [660.142029] i915 0000:00:02.0: colorspace: RGB <7> [660.142032] i915 0000:00:02.0: scan mode: Underscan <7> [660.142036] i915 0000:00:02.0: colorimetry: No Data <7> [660.142039] i915 0000:00:02.0: picture aspect: No Data <7> [660.142042] i915 0000:00:02.0: active aspect: Same as Picture <7> [660.142045] i915 0000:00:02.0: itc: No Data <7> [660.142048] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [660.142051] i915 0000:00:02.0: quantization range: Full <7> [660.142054] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [660.142058] i915 0000:00:02.0: video code: 0 <7> [660.142061] i915 0000:00:02.0: ycc quantization range: Full <7> [660.142064] i915 0000:00:02.0: hdmi content type: Graphics <7> [660.142067] i915 0000:00:02.0: pixel repeat: 0 <7> [660.142070] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [660.142075] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [660.142078] i915 0000:00:02.0: vendor: Intel <7> [660.142082] i915 0000:00:02.0: product: Integrated gfx <7> [660.142085] i915 0000:00:02.0: source device information: PC General (0x9) <7> [660.142089] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [660.142092] i915 0000:00:02.0: empty frame <7> [660.142096] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 07 00 66 10 00 01 00 00 00 00 00 00 00 00 <7> [660.142697] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 05 e3 cd 0c 32 38 45 38 35 30 09 07 07 00 00 00 <7> [660.143083] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [660.143560] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [660.143941] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0 <7> [660.144410] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0 <7> [660.144793] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [660.145267] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [660.145648] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [660.146033] i915 0000:00:02.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=1083-1088 vt=1125, flags=0x9 <7> [660.147054] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x40 0x9 <7> [660.147575] i915 0000:00:02.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=1083-1088 vt=1125, flags=0x9 <7> [660.147986] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pixel rate 148500, min cdclk 192000, min voltage level 0 <7> [660.148480] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [660.148902] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [660.149403] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [660.149786] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [660.150323] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [660.150726] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [660.151112] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: ebb0: 0x6200, ebb4: 0x2000,pll0: 0x21, pll1: 0x100, pll2: 0x1a6666, pll3: 0x10000, pll6: 0x30904, pll8: 0x8, pll9: 0xa, pll10: 0x8003c00, pcsdw12: 0x4d <7> [660.151643] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [660.152042] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [660.152517] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [660.152897] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [660.153405] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [660.153790] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [660.154260] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [660.154640] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:79:plane 1B] fb: [FB:180] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [660.155021] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [660.157034] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [660.157769] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:88:plane 2B] fb: [NOFB], visible: no <7> [660.158240] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:97:plane 3B] fb: [NOFB], visible: no <7> [660.158644] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:106:plane 4B] fb: [NOFB], visible: no <7> [660.159025] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:115:cursor B] fb: [NOFB], visible: no <7> [660.160200] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [660.160669] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-b <7> [660.161518] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 316800 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 13 <7> [660.161982] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [660.162495] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [660.163089] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL B (active 0x2, on? 0) for [CRTC:121:pipe B] <7> [660.163532] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL B <7> [660.164317] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B <7> [660.164819] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [660.200051] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:166:HDMI-A-1][ENCODER:165:DDI B/PHY B] Enable audio codec on [CRTC:121:pipe B], 32 bytes ELD <7> [660.213724] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10 <7> [660.216720] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000) <7> [660.217236] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <7> [660.217816] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:166:HDMI-A-1] <7> [660.218671] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:121:pipe B] <7> [660.225288] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL <7> [660.225308] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled <6> [662.430731] [IGT] kms_flip: finished subtest B-HDMI-A1, FAIL

Detail

Value

Duration

2.58 seconds

Hostname

shard-glk2

Igt-Version

IGT-Version: 2.4-ga22943872 (x86_64) (Linux: 7.1.0-rc2-CI_DRM_18452-g680a4832a818+ x86_64)

Out

Starting dynamic subtest: B-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A1: FAIL (2.582s)

Err

Starting dynamic subtest: B-HDMI-A1
(kms_flip:4770) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:4770) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:4770) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
(kms_flip:4770) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:4770) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:4770) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:4770) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:4770) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
(kms_flip:4770) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:4770) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:4770) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:4770) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:4770) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:4770) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:4770) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:4770) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:4770) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:4770) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:4770) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:4770) DEBUG: No stale events found
(kms_flip:4770) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:4770) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:4770) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 659.961487
current_received_ts = 659.961060
current_seq = 18336
count = 0
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 9us
(kms_flip:4770) DEBUG: name = flip
last_ts = 659.961487
last_received_ts = 659.961060
last_seq = 18336
current_ts = 659.978149
current_received_ts = 659.977722
current_seq = 18337
count = 1
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 7us
(kms_flip:4770) DEBUG: name = flip
last_ts = 659.978149
last_received_ts = 659.977722
last_seq = 18337
current_ts = 659.994812
current_received_ts = 659.994324
current_seq = 18338
count = 2
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 6us
(kms_flip:4770) DEBUG: name = flip
last_ts = 659.994812
last_received_ts = 659.994324
last_seq = 18338
current_ts = 660.011475
current_received_ts = 660.011047
current_seq = 18339
count = 3
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 7us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.011475
last_received_ts = 660.011047
last_seq = 18339
current_ts = 660.028137
current_received_ts = 660.028076
current_seq = 18340
count = 4
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.028137
last_received_ts = 660.028076
last_seq = 18340
current_ts = 660.044800
current_received_ts = 660.044617
current_seq = 18341
count = 5
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.044800
last_received_ts = 660.044617
last_seq = 18341
current_ts = 660.061462
current_received_ts = 660.061157
current_seq = 18342
count = 6
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 22us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.061462
last_received_ts = 660.061157
last_seq = 18342
current_ts = 660.078125
current_received_ts = 660.078064
current_seq = 18343
count = 7
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.078125
last_received_ts = 660.078064
last_seq = 18343
current_ts = 660.094788
current_received_ts = 660.094666
current_seq = 18344
count = 8
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.094788
last_received_ts = 660.094666
last_seq = 18344
current_ts = 660.111450
current_received_ts = 660.111328
current_seq = 18345
count = 9
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.111450
last_received_ts = 660.111328
last_seq = 18345
current_ts = 660.128113
current_received_ts = 660.127991
current_seq = 18346
count = 10
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 18us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.128113
last_received_ts = 660.127991
last_seq = 18346
current_ts = 660.144836
current_received_ts = 660.144592
current_seq = 18347
count = 11
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.144836
last_received_ts = 660.144592
last_seq = 18347
current_ts = 660.161438
current_received_ts = 660.161316
current_seq = 18348
count = 12
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 18us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.161438
last_received_ts = 660.161316
last_seq = 18348
current_ts = 660.178162
current_received_ts = 660.178101
current_seq = 18349
count = 13
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.178162
last_received_ts = 660.178101
last_seq = 18349
current_ts = 660.194824
current_received_ts = 660.194702
current_seq = 18350
count = 14
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.194824
last_received_ts = 660.194702
last_seq = 18350
current_ts = 660.211487
current_received_ts = 660.211365
current_seq = 18351
count = 15
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.211487
last_received_ts = 660.211365
last_seq = 18351
current_ts = 660.228149
current_received_ts = 660.228088
current_seq = 18352
count = 16
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.228149
last_received_ts = 660.228088
last_seq = 18352
current_ts = 660.244812
current_received_ts = 660.244690
current_seq = 18353
count = 17
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.244812
last_received_ts = 660.244690
last_seq = 18353
current_ts = 660.261475
current_received_ts = 660.261353
current_seq = 18354
count = 18
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.261475
last_received_ts = 660.261353
last_seq = 18354
current_ts = 660.278137
current_received_ts = 660.278076
current_seq = 18355
count = 19
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.278137
last_received_ts = 660.278076
last_seq = 18355
current_ts = 660.294800
current_received_ts = 660.294678
current_seq = 18356
count = 20
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.294800
last_received_ts = 660.294678
last_seq = 18356
current_ts = 660.311462
current_received_ts = 660.311340
current_seq = 18357
count = 21
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.311462
last_received_ts = 660.311340
last_seq = 18357
current_ts = 660.328125
current_received_ts = 660.328064
current_seq = 18358
count = 22
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.328125
last_received_ts = 660.328064
last_seq = 18358
current_ts = 660.344788
current_received_ts = 660.344666
current_seq = 18359
count = 23
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.344788
last_received_ts = 660.344666
last_seq = 18359
current_ts = 660.361450
current_received_ts = 660.361328
current_seq = 18360
count = 24
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 19us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.361450
last_received_ts = 660.361328
last_seq = 18360
current_ts = 660.378174
current_received_ts = 660.377930
current_seq = 18361
count = 25
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.378174
last_received_ts = 660.377930
last_seq = 18361
current_ts = 660.394836
current_received_ts = 660.394653
current_seq = 18362
count = 26
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.394836
last_received_ts = 660.394653
last_seq = 18362
current_ts = 660.411499
current_received_ts = 660.411316
current_seq = 18363
count = 27
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 23us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.411499
last_received_ts = 660.411316
last_seq = 18363
current_ts = 660.428162
current_received_ts = 660.427979
current_seq = 18364
count = 28
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.428162
last_received_ts = 660.427979
last_seq = 18364
current_ts = 660.444824
current_received_ts = 660.444641
current_seq = 18365
count = 29
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.444824
last_received_ts = 660.444641
last_seq = 18365
current_ts = 660.461487
current_received_ts = 660.461365
current_seq = 18366
count = 30
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 23us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.461487
last_received_ts = 660.461365
last_seq = 18366
current_ts = 660.478149
current_received_ts = 660.477783
current_seq = 18367
count = 31
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.478149
last_received_ts = 660.477783
last_seq = 18367
current_ts = 660.494812
current_received_ts = 660.494568
current_seq = 18368
count = 32
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.494812
last_received_ts = 660.494568
last_seq = 18368
current_ts = 660.511475
current_received_ts = 660.511292
current_seq = 18369
count = 33
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.511475
last_received_ts = 660.511292
last_seq = 18369
current_ts = 660.528137
current_received_ts = 660.528076
current_seq = 18370
count = 34
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.528137
last_received_ts = 660.528076
last_seq = 18370
current_ts = 660.544800
current_received_ts = 660.544617
current_seq = 18371
count = 35
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.544800
last_received_ts = 660.544617
last_seq = 18371
current_ts = 660.561462
current_received_ts = 660.561340
current_seq = 18372
count = 36
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 23us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.561462
last_received_ts = 660.561340
last_seq = 18372
current_ts = 660.578125
current_received_ts = 660.578064
current_seq = 18373
count = 37
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.578125
last_received_ts = 660.578064
last_seq = 18373
current_ts = 660.594788
current_received_ts = 660.594666
current_seq = 18374
count = 38
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.594788
last_received_ts = 660.594666
last_seq = 18374
current_ts = 660.611450
current_received_ts = 660.611328
current_seq = 18375
count = 39
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.611450
last_received_ts = 660.611328
last_seq = 18375
current_ts = 660.628174
current_received_ts = 660.627991
current_seq = 18376
count = 40
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.628174
last_received_ts = 660.627991
last_seq = 18376
current_ts = 660.644836
current_received_ts = 660.645325
current_seq = 18377
count = 41
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 35us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.644836
last_received_ts = 660.645325
last_seq = 18377
current_ts = 660.661499
current_received_ts = 660.661011
current_seq = 18378
count = 42
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 22us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.661499
last_received_ts = 660.661011
last_seq = 18378
current_ts = 660.678162
current_received_ts = 660.677979
current_seq = 18379
count = 43
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.678162
last_received_ts = 660.677979
last_seq = 18379
current_ts = 660.694824
current_received_ts = 660.694641
current_seq = 18380
count = 44
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.694824
last_received_ts = 660.694641
last_seq = 18380
current_ts = 660.711487
current_received_ts = 660.711365
current_seq = 18381
count = 45
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.711487
last_received_ts = 660.711365
last_seq = 18381
current_ts = 660.728149
current_received_ts = 660.727966
current_seq = 18382
count = 46
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 28us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.728149
last_received_ts = 660.727966
last_seq = 18382
current_ts = 660.744812
current_received_ts = 660.744629
current_seq = 18383
count = 47
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.744812
last_received_ts = 660.744629
last_seq = 18383
current_ts = 660.761475
current_received_ts = 660.761292
current_seq = 18384
count = 48
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 20us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.761475
last_received_ts = 660.761292
last_seq = 18384
current_ts = 660.778137
current_received_ts = 660.777954
current_seq = 18385
count = 49
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.778137
last_received_ts = 660.777954
last_seq = 18385
current_ts = 660.794800
current_received_ts = 660.794678
current_seq = 18386
count = 50
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.794800
last_received_ts = 660.794678
last_seq = 18386
current_ts = 660.811462
current_received_ts = 660.811279
current_seq = 18387
count = 51
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.811462
last_received_ts = 660.811279
last_seq = 18387
current_ts = 660.828125
current_received_ts = 660.828003
current_seq = 18388
count = 52
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.828125
last_received_ts = 660.828003
last_seq = 18388
current_ts = 660.844788
current_received_ts = 660.844666
current_seq = 18389
count = 53
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.844788
last_received_ts = 660.844666
last_seq = 18389
current_ts = 660.861511
current_received_ts = 660.861267
current_seq = 18390
count = 54
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.861511
last_received_ts = 660.861267
last_seq = 18390
current_ts = 660.878174
current_received_ts = 660.878113
current_seq = 18391
count = 55
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.878174
last_received_ts = 660.878113
last_seq = 18391
current_ts = 660.894836
current_received_ts = 660.894714
current_seq = 18392
count = 56
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.894836
last_received_ts = 660.894714
last_seq = 18392
current_ts = 660.911499
current_received_ts = 660.911316
current_seq = 18393
count = 57
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 23us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.911499
last_received_ts = 660.911316
last_seq = 18393
current_ts = 660.928162
current_received_ts = 660.927979
current_seq = 18394
count = 58
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.928162
last_received_ts = 660.927979
last_seq = 18394
current_ts = 660.944824
current_received_ts = 660.944580
current_seq = 18395
count = 59
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.944824
last_received_ts = 660.944580
last_seq = 18395
current_ts = 660.961487
current_received_ts = 660.961304
current_seq = 18396
count = 60
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 20us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.961487
last_received_ts = 660.961304
last_seq = 18396
current_ts = 660.978149
current_received_ts = 660.977966
current_seq = 18397
count = 61
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.978149
last_received_ts = 660.977966
last_seq = 18397
current_ts = 660.994812
current_received_ts = 660.994629
current_seq = 18398
count = 62
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 23us
(kms_flip:4770) DEBUG: name = flip
last_ts = 660.994812
last_received_ts = 660.994629
last_seq = 18398
current_ts = 661.011475
current_received_ts = 661.011108
current_seq = 18399
count = 63
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.011475
last_received_ts = 661.011108
last_seq = 18399
current_ts = 661.028137
current_received_ts = 661.027893
current_seq = 18400
count = 64
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 120us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.028137
last_received_ts = 661.027893
last_seq = 18400
current_ts = 661.044800
current_received_ts = 661.044678
current_seq = 18401
count = 65
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.044800
last_received_ts = 661.044678
last_seq = 18401
current_ts = 661.061462
current_received_ts = 661.061279
current_seq = 18402
count = 66
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.061462
last_received_ts = 661.061279
last_seq = 18402
current_ts = 661.078125
current_received_ts = 661.078125
current_seq = 18403
count = 67
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 23us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.078125
last_received_ts = 661.078125
last_seq = 18403
current_ts = 661.094788
current_received_ts = 661.094604
current_seq = 18404
count = 68
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.094788
last_received_ts = 661.094604
last_seq = 18404
current_ts = 661.111511
current_received_ts = 661.111328
current_seq = 18405
count = 69
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.111511
last_received_ts = 661.111328
last_seq = 18405
current_ts = 661.128174
current_received_ts = 661.128113
current_seq = 18406
count = 70
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.128174
last_received_ts = 661.128113
last_seq = 18406
current_ts = 661.144836
current_received_ts = 661.144714
current_seq = 18407
count = 71
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.144836
last_received_ts = 661.144714
last_seq = 18407
current_ts = 661.161499
current_received_ts = 661.161377
current_seq = 18408
count = 72
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.161499
last_received_ts = 661.161377
last_seq = 18408
current_ts = 661.178162
current_received_ts = 661.178101
current_seq = 18409
count = 73
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.178162
last_received_ts = 661.178101
last_seq = 18409
current_ts = 661.194824
current_received_ts = 661.194702
current_seq = 18410
count = 74
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 23us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.194824
last_received_ts = 661.194702
last_seq = 18410
current_ts = 661.211487
current_received_ts = 661.211304
current_seq = 18411
count = 75
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.211487
last_received_ts = 661.211304
last_seq = 18411
current_ts = 661.228149
current_received_ts = 661.228088
current_seq = 18412
count = 76
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.228149
last_received_ts = 661.228088
last_seq = 18412
current_ts = 661.244812
current_received_ts = 661.244690
current_seq = 18413
count = 77
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.244812
last_received_ts = 661.244690
last_seq = 18413
current_ts = 661.261475
current_received_ts = 661.261353
current_seq = 18414
count = 78
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.261475
last_received_ts = 661.261353
last_seq = 18414
current_ts = 661.278137
current_received_ts = 661.278076
current_seq = 18415
count = 79
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 19us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.278137
last_received_ts = 661.278076
last_seq = 18415
current_ts = 661.294800
current_received_ts = 661.294678
current_seq = 18416
count = 80
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.294800
last_received_ts = 661.294678
last_seq = 18416
current_ts = 661.311462
current_received_ts = 661.311279
current_seq = 18417
count = 81
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.311462
last_received_ts = 661.311279
last_seq = 18417
current_ts = 661.328186
current_received_ts = 661.328003
current_seq = 18418
count = 82
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.328186
last_received_ts = 661.328003
last_seq = 18418
current_ts = 661.344849
current_received_ts = 661.344666
current_seq = 18419
count = 83
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.344849
last_received_ts = 661.344666
last_seq = 18419
current_ts = 661.361511
current_received_ts = 661.361389
current_seq = 18420
count = 84
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 20us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.361511
last_received_ts = 661.361389
last_seq = 18420
current_ts = 661.378174
current_received_ts = 661.378052
current_seq = 18421
count = 85
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 21us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.378174
last_received_ts = 661.378052
last_seq = 18421
current_ts = 661.394836
current_received_ts = 661.394653
current_seq = 18422
count = 86
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.394836
last_received_ts = 661.394653
last_seq = 18422
current_ts = 661.411499
current_received_ts = 661.411316
current_seq = 18423
count = 87
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.411499
last_received_ts = 661.411316
last_seq = 18423
current_ts = 661.428162
current_received_ts = 661.427979
current_seq = 18424
count = 88
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 23us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.428162
last_received_ts = 661.427979
last_seq = 18424
current_ts = 661.444824
current_received_ts = 661.444641
current_seq = 18425
count = 89
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.444824
last_received_ts = 661.444641
last_seq = 18425
current_ts = 661.461487
current_received_ts = 661.461304
current_seq = 18426
count = 90
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.461487
last_received_ts = 661.461304
last_seq = 18426
current_ts = 661.478149
current_received_ts = 661.478088
current_seq = 18427
count = 91
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.478149
last_received_ts = 661.478088
last_seq = 18427
current_ts = 661.494812
current_received_ts = 661.494629
current_seq = 18428
count = 92
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.494812
last_received_ts = 661.494629
last_seq = 18428
current_ts = 661.511475
current_received_ts = 661.511292
current_seq = 18429
count = 93
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.511475
last_received_ts = 661.511292
last_seq = 18429
current_ts = 661.528137
current_received_ts = 661.528076
current_seq = 18430
count = 94
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.528137
last_received_ts = 661.528076
last_seq = 18430
current_ts = 661.544861
current_received_ts = 661.544678
current_seq = 18431
count = 95
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.544861
last_received_ts = 661.544678
last_seq = 18431
current_ts = 661.561523
current_received_ts = 661.561279
current_seq = 18432
count = 96
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 26us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.561523
last_received_ts = 661.561279
last_seq = 18432
current_ts = 661.578186
current_received_ts = 661.578064
current_seq = 18433
count = 97
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.578186
last_received_ts = 661.578064
last_seq = 18433
current_ts = 661.594849
current_received_ts = 661.594666
current_seq = 18434
count = 98
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 27us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.594849
last_received_ts = 661.594666
last_seq = 18434
current_ts = 661.611511
current_received_ts = 661.611328
current_seq = 18435
count = 99
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.611511
last_received_ts = 661.611328
last_seq = 18435
current_ts = 661.628174
current_received_ts = 661.627991
current_seq = 18436
count = 100
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 24us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.628174
last_received_ts = 661.627991
last_seq = 18436
current_ts = 661.644836
current_received_ts = 661.644653
current_seq = 18437
count = 101
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 25us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.644836
last_received_ts = 661.644653
last_seq = 18437
current_ts = 661.661499
current_received_ts = 661.660950
current_seq = 18438
count = 102
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 17us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.661499
last_received_ts = 661.660950
last_seq = 18438
current_ts = 661.678162
current_received_ts = 661.678040
current_seq = 18439
count = 103
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 12us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.678162
last_received_ts = 661.678040
last_seq = 18439
current_ts = 661.694824
current_received_ts = 661.694275
current_seq = 18440
count = 104
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 12us
(kms_flip:4770) DEBUG: name = flip
last_ts = 661.694824
last_received_ts = 661.694275
last_seq = 18440
current_ts = 661.711487
current_received_ts = 661.710938
current_seq = 18441
count = 105
seq_step = 1
(kms_flip:4770) DEBUG: Vblank took 601us
(kms_flip:4770) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:4770) CRITICAL: Failed assertion: end - start < 500
(kms_flip:4770) igt_core-INFO: Stack trace:
(kms_flip:4770) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:4770) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:4770) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:4770) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
(kms_flip:4770) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:4770) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:4770) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:4770) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (2.582s)

Dmesg

<6> [659.847448] [IGT] kms_flip: starting dynamic subtest B-HDMI-A1

<7> [659.849165] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:180]

<7> [659.849633] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:182]

<7> [659.907370] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A]

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

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

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

<7> [659.911929] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_count (expected 4, found 0)

<7> [659.912753] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [659.931637] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000)

<7> [659.932081] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000)

<7> [659.932571] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in avi infoframe

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

<7> [659.933437] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [659.933443] i915 0000:00:02.0: colorspace: RGB

<7> [659.933447] i915 0000:00:02.0: scan mode: Underscan

<7> [659.933450] i915 0000:00:02.0: colorimetry: No Data

<7> [659.933453] i915 0000:00:02.0: picture aspect: No Data

<7> [659.933456] i915 0000:00:02.0: active aspect: Same as Picture

<7> [659.933460] i915 0000:00:02.0: itc: No Data

<7> [659.933463] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [659.933466] i915 0000:00:02.0: quantization range: Full

<7> [659.933469] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [659.933472] i915 0000:00:02.0: video code: 0

<7> [659.933475] i915 0000:00:02.0: ycc quantization range: Full

<7> [659.933478] i915 0000:00:02.0: hdmi content type: Graphics

<7> [659.933482] i915 0000:00:02.0: pixel repeat: 0

<7> [659.933485] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

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

<7> [659.933870] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in spd infoframe

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

<7> [659.934861] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [659.934866] i915 0000:00:02.0: vendor: Intel

<7> [659.934870] i915 0000:00:02.0: product: Integrated gfx

<7> [659.934873] i915 0000:00:02.0: source device information: PC General (0x9)

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

<7> [659.935458] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hdmi infoframe

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

<7> [659.936436] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [659.936441] i915 0000:00:02.0: empty frame

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

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

<7> [659.937397] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:78:pipe A] releasing PORT PLL B

<7> [659.937847] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:78:pipe A] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x1 -> 0x0

<7> [659.938454] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:72:cursor A] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0

<7> [659.938926] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:78:pipe A] min cdclk: 192000 kHz -> 0 kHz

<7> [659.939572] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change

<7> [659.939965] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz

<7> [659.940472] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4

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

<7> [659.941325] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:36:plane 1A] fb: [NOFB], visible: no

<7> [659.941708] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:45:plane 2A] fb: [NOFB], visible: no

<7> [659.942092] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:plane 3A] fb: [NOFB], visible: no

<7> [659.942575] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 4A] fb: [NOFB], visible: no

<7> [659.942966] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:72:cursor A] fb: [NOFB], visible: no

<7> [659.943760] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:166:HDMI-A-1][ENCODER:165:DDI B/PHY B] Disable audio codec on [CRTC:78:pipe A]

<7> [659.973510] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B

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

<7> [659.991197] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time

<7> [660.092539] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B

<7> [660.093804] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x1, on? 1) for [CRTC:78:pipe A]

<7> [660.096888] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL B

<7> [660.097619] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 79200 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 4

<7> [660.098098] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B]

<7> [660.098695] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C]

<7> [660.099106] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:166:HDMI-A-1]

<7> [660.100284] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-b

<7> [660.100739] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2

<7> [660.101342] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:78:pipe A]

<7> [660.102587] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B]

<7> [660.102947] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C]

<7> [660.103403] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B]

<7> [660.103463] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:166:HDMI-A-1]

<7> [660.103650] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 12 bpc for HDMI output (pipe bpp: 36)

<7> [660.104379] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] hw max bpp: 36, pipe bpp: 36, dithering: 0

<7> [660.104782] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:165:DDI B/PHY B] [CRTC:121:pipe B]

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

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

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

<7> [660.107023] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_count (expected 0, found 4)

<7> [660.107543] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [660.124071] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071)

<7> [660.124594] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006)

<7> [660.124985] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in avi infoframe

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

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

<7> [660.126752] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [660.126758] i915 0000:00:02.0: colorspace: RGB

<7> [660.126762] i915 0000:00:02.0: scan mode: Underscan

<7> [660.126766] i915 0000:00:02.0: colorimetry: No Data

<7> [660.126769] i915 0000:00:02.0: picture aspect: No Data

<7> [660.126772] i915 0000:00:02.0: active aspect: Same as Picture

<7> [660.126776] i915 0000:00:02.0: itc: No Data

<7> [660.126779] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [660.126782] i915 0000:00:02.0: quantization range: Full

<7> [660.126785] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [660.126789] i915 0000:00:02.0: video code: 0

<7> [660.126792] i915 0000:00:02.0: ycc quantization range: Full

<7> [660.126795] i915 0000:00:02.0: hdmi content type: Graphics

<7> [660.126798] i915 0000:00:02.0: pixel repeat: 0

<7> [660.126801] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [660.126806] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in spd infoframe

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

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

<7> [660.128364] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [660.128369] i915 0000:00:02.0: vendor: Intel

<7> [660.128372] i915 0000:00:02.0: product: Integrated gfx

<7> [660.128376] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [660.128380] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hdmi infoframe

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

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

<7> [660.129715] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [660.129719] i915 0000:00:02.0: empty frame

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

<7> [660.130349] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:121:pipe B] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x2

<7> [660.130803] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:79:plane 1B] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988

<7> [660.131369] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:115:cursor B] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32

<7> [660.131810] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79: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> [660.132327] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0

<7> [660.132717] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0

<7> [660.133096] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 17, 17, 17, 34, 34, 34, 34, 34, 31, 0, 0

<7> [660.133576] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb_uv 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [660.134021] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:121:pipe B] min cdclk: 0 kHz -> 192000 kHz

<7> [660.134611] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change

<7> [660.134999] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz

<7> [660.135472] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13

<7> [660.135861] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:121:pipe B] using pre-allocated PORT PLL B

<7> [660.137183] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:121:pipe B] reserving PORT PLL B

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

<7> [660.138377] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB

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

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

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

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

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

<7> [660.141102] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71

<7> [660.141626] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6

<7> [660.142024] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [660.142029] i915 0000:00:02.0: colorspace: RGB

<7> [660.142032] i915 0000:00:02.0: scan mode: Underscan

<7> [660.142036] i915 0000:00:02.0: colorimetry: No Data

<7> [660.142039] i915 0000:00:02.0: picture aspect: No Data

<7> [660.142042] i915 0000:00:02.0: active aspect: Same as Picture

<7> [660.142045] i915 0000:00:02.0: itc: No Data

<7> [660.142048] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [660.142051] i915 0000:00:02.0: quantization range: Full

<7> [660.142054] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [660.142058] i915 0000:00:02.0: video code: 0

<7> [660.142061] i915 0000:00:02.0: ycc quantization range: Full

<7> [660.142064] i915 0000:00:02.0: hdmi content type: Graphics

<7> [660.142067] i915 0000:00:02.0: pixel repeat: 0

<7> [660.142070] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [660.142075] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [660.142078] i915 0000:00:02.0: vendor: Intel

<7> [660.142082] i915 0000:00:02.0: product: Integrated gfx

<7> [660.142085] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [660.142089] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [660.142092] i915 0000:00:02.0: empty frame

<7> [660.142096] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 07 00 66 10 00 01 00 00 00 00 00 00 00 00

<7> [660.142697] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 05 e3 cd 0c 32 38 45 38 35 30 09 07 07 00 00 00

<7> [660.143083] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

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

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

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

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

<7> [660.145267] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9

<7> [660.145648] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9

<7> [660.146033] i915 0000:00:02.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=1083-1088 vt=1125, flags=0x9

<7> [660.147054] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x40 0x9

<7> [660.147575] i915 0000:00:02.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=1083-1088 vt=1125, flags=0x9

<7> [660.147986] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pixel rate 148500, min cdclk 192000, min voltage level 0

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

<7> [660.148902] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0

<7> [660.149403] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0

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

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

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

<7> [660.151112] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: ebb0: 0x6200, ebb4: 0x2000,pll0: 0x21, pll1: 0x100, pll2: 0x1a6666, pll3: 0x10000, pll6: 0x30904, pll8: 0x8, pll9: 0xa, pll10: 0x8003c00, pcsdw12: 0x4d

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

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

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

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

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

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

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

<7> [660.154640] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:79:plane 1B] fb: [FB:180] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes

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

<7> [660.157034] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0

<7> [660.157769] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:88:plane 2B] fb: [NOFB], visible: no

<7> [660.158240] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:97:plane 3B] fb: [NOFB], visible: no

<7> [660.158644] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:106:plane 4B] fb: [NOFB], visible: no

<7> [660.159025] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:115:cursor B] fb: [NOFB], visible: no

<7> [660.160200] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2

<7> [660.160669] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-b

<7> [660.161518] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 316800 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 13

<7> [660.161982] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B]

<7> [660.162495] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C]

<7> [660.163089] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL B (active 0x2, on? 0) for [CRTC:121:pipe B]

<7> [660.163532] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL B

<7> [660.164317] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B

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

<7> [660.200051] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:166:HDMI-A-1][ENCODER:165:DDI B/PHY B] Enable audio codec on [CRTC:121:pipe B], 32 bytes ELD

<7> [660.213724] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10

<7> [660.216720] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000)

<7> [660.217236] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N

<7> [660.217816] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:166:HDMI-A-1]

<7> [660.218671] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:121:pipe B]

<7> [660.225288] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL

<7> [660.225308] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled

<6> [662.430731] [IGT] kms_flip: finished subtest B-HDMI-A1, FAIL

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