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

Detail	Value
Duration	3.63 seconds
Hostname	shard-glk9
Igt-Version	IGT-Version: 2.4-g0a40de522 (x86_64) (Linux: 7.0.0-rc6-CI_DRM_18263-g35dad892ec87+ 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:925 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1891 run_test() #3 ../tests/kms_flip.c:2126 __igt_unique____real_main2047() #4 ../tests/kms_flip.c:2047 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-HDMI-A1: FAIL (3.627s)
Err	Starting dynamic subtest: B-HDMI-A1 (kms_flip:2400) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:2400) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-HDMI-A1 failed. ** DEBUG (kms_flip:2400) DEBUG: name = flip last_ts = 356.977112 last_received_ts = 356.976929 last_seq = 14423 current_ts = 356.993805 current_received_ts = 356.993591 current_seq = 14424 count = 30 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 356.993805 last_received_ts = 356.993591 last_seq = 14424 current_ts = 357.010468 current_received_ts = 357.010315 current_seq = 14425 count = 31 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.010468 last_received_ts = 357.010315 last_seq = 14425 current_ts = 357.027130 current_received_ts = 357.026978 current_seq = 14426 count = 32 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 19us (kms_flip:2400) DEBUG: name = flip last_ts = 357.027130 last_received_ts = 357.026978 last_seq = 14426 current_ts = 357.043793 current_received_ts = 357.043640 current_seq = 14427 count = 33 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.043793 last_received_ts = 357.043640 last_seq = 14427 current_ts = 357.060455 current_received_ts = 357.060333 current_seq = 14428 count = 34 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 357.060455 last_received_ts = 357.060333 last_seq = 14428 current_ts = 357.077118 current_received_ts = 357.076996 current_seq = 14429 count = 35 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.077118 last_received_ts = 357.076996 last_seq = 14429 current_ts = 357.093781 current_received_ts = 357.093658 current_seq = 14430 count = 36 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.093781 last_received_ts = 357.093658 last_seq = 14430 current_ts = 357.110474 current_received_ts = 357.110321 current_seq = 14431 count = 37 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 357.110474 last_received_ts = 357.110321 last_seq = 14431 current_ts = 357.127136 current_received_ts = 357.126984 current_seq = 14432 count = 38 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.127136 last_received_ts = 357.126984 last_seq = 14432 current_ts = 357.143799 current_received_ts = 357.143585 current_seq = 14433 count = 39 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.143799 last_received_ts = 357.143585 last_seq = 14433 current_ts = 357.160461 current_received_ts = 357.160278 current_seq = 14434 count = 40 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.160461 last_received_ts = 357.160278 last_seq = 14434 current_ts = 357.177124 current_received_ts = 357.177094 current_seq = 14435 count = 41 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.177124 last_received_ts = 357.177094 last_seq = 14435 current_ts = 357.193787 current_received_ts = 357.193634 current_seq = 14436 count = 42 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 357.193787 last_received_ts = 357.193634 last_seq = 14436 current_ts = 357.210449 current_received_ts = 357.210327 current_seq = 14437 count = 43 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.210449 last_received_ts = 357.210327 last_seq = 14437 current_ts = 357.227112 current_received_ts = 357.227081 current_seq = 14438 count = 44 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 22us (kms_flip:2400) DEBUG: name = flip last_ts = 357.227112 last_received_ts = 357.227081 last_seq = 14438 current_ts = 357.243805 current_received_ts = 357.243652 current_seq = 14439 count = 45 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.243805 last_received_ts = 357.243652 last_seq = 14439 current_ts = 357.260437 current_received_ts = 357.260223 current_seq = 14440 count = 46 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.260437 last_received_ts = 357.260223 last_seq = 14440 current_ts = 357.277130 current_received_ts = 357.276947 current_seq = 14441 count = 47 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 100us (kms_flip:2400) DEBUG: name = flip last_ts = 357.277130 last_received_ts = 357.276947 last_seq = 14441 current_ts = 357.293793 current_received_ts = 357.293610 current_seq = 14442 count = 48 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.293793 last_received_ts = 357.293610 last_seq = 14442 current_ts = 357.310455 current_received_ts = 357.310333 current_seq = 14443 count = 49 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 24us (kms_flip:2400) DEBUG: name = flip last_ts = 357.310455 last_received_ts = 357.310333 last_seq = 14443 current_ts = 357.327118 current_received_ts = 357.326996 current_seq = 14444 count = 50 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.327118 last_received_ts = 357.326996 last_seq = 14444 current_ts = 357.343781 current_received_ts = 357.343658 current_seq = 14445 count = 51 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.343781 last_received_ts = 357.343658 last_seq = 14445 current_ts = 357.360443 current_received_ts = 357.360321 current_seq = 14446 count = 52 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 24us (kms_flip:2400) DEBUG: name = flip last_ts = 357.360443 last_received_ts = 357.360321 last_seq = 14446 current_ts = 357.377136 current_received_ts = 357.376984 current_seq = 14447 count = 53 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.377136 last_received_ts = 357.376984 last_seq = 14447 current_ts = 357.393799 current_received_ts = 357.393646 current_seq = 14448 count = 54 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.393799 last_received_ts = 357.393646 last_seq = 14448 current_ts = 357.410461 current_received_ts = 357.410339 current_seq = 14449 count = 55 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 357.410461 last_received_ts = 357.410339 last_seq = 14449 current_ts = 357.427124 current_received_ts = 357.426971 current_seq = 14450 count = 56 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 20us (kms_flip:2400) DEBUG: name = flip last_ts = 357.427124 last_received_ts = 357.426971 last_seq = 14450 current_ts = 357.443787 current_received_ts = 357.443634 current_seq = 14451 count = 57 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.443787 last_received_ts = 357.443634 last_seq = 14451 current_ts = 357.460449 current_received_ts = 357.460297 current_seq = 14452 count = 58 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.460449 last_received_ts = 357.460297 last_seq = 14452 current_ts = 357.477142 current_received_ts = 357.477203 current_seq = 14453 count = 59 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 24us (kms_flip:2400) DEBUG: name = flip last_ts = 357.477142 last_received_ts = 357.477203 last_seq = 14453 current_ts = 357.493805 current_received_ts = 357.493622 current_seq = 14454 count = 60 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 357.493805 last_received_ts = 357.493622 last_seq = 14454 current_ts = 357.510468 current_received_ts = 357.510254 current_seq = 14455 count = 61 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.510468 last_received_ts = 357.510254 last_seq = 14455 current_ts = 357.527130 current_received_ts = 357.526947 current_seq = 14456 count = 62 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 357.527130 last_received_ts = 357.526947 last_seq = 14456 current_ts = 357.543793 current_received_ts = 357.543640 current_seq = 14457 count = 63 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 357.543793 last_received_ts = 357.543640 last_seq = 14457 current_ts = 357.560455 current_received_ts = 357.560303 current_seq = 14458 count = 64 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.560455 last_received_ts = 357.560303 last_seq = 14458 current_ts = 357.577118 current_received_ts = 357.576965 current_seq = 14459 count = 65 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.577118 last_received_ts = 357.576965 last_seq = 14459 current_ts = 357.593781 current_received_ts = 357.593689 current_seq = 14460 count = 66 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.593781 last_received_ts = 357.593689 last_seq = 14460 current_ts = 357.610443 current_received_ts = 357.610352 current_seq = 14461 count = 67 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 24us (kms_flip:2400) DEBUG: name = flip last_ts = 357.610443 last_received_ts = 357.610352 last_seq = 14461 current_ts = 357.627136 current_received_ts = 357.627075 current_seq = 14462 count = 68 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.627136 last_received_ts = 357.627075 last_seq = 14462 current_ts = 357.643799 current_received_ts = 357.643646 current_seq = 14463 count = 69 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.643799 last_received_ts = 357.643646 last_seq = 14463 current_ts = 357.660461 current_received_ts = 357.660339 current_seq = 14464 count = 70 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 357.660461 last_received_ts = 357.660339 last_seq = 14464 current_ts = 357.677124 current_received_ts = 357.676971 current_seq = 14465 count = 71 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.677124 last_received_ts = 357.676971 last_seq = 14465 current_ts = 357.693787 current_received_ts = 357.693604 current_seq = 14466 count = 72 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.693787 last_received_ts = 357.693604 last_seq = 14466 current_ts = 357.710449 current_received_ts = 357.710327 current_seq = 14467 count = 73 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.710449 last_received_ts = 357.710327 last_seq = 14467 current_ts = 357.727112 current_received_ts = 357.726929 current_seq = 14468 count = 74 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 18us (kms_flip:2400) DEBUG: name = flip last_ts = 357.727112 last_received_ts = 357.726929 last_seq = 14468 current_ts = 357.743774 current_received_ts = 357.743591 current_seq = 14469 count = 75 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.743774 last_received_ts = 357.743591 last_seq = 14469 current_ts = 357.760468 current_received_ts = 357.760315 current_seq = 14470 count = 76 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.760468 last_received_ts = 357.760315 last_seq = 14470 current_ts = 357.777130 current_received_ts = 357.776947 current_seq = 14471 count = 77 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 78us (kms_flip:2400) DEBUG: name = flip last_ts = 357.777130 last_received_ts = 357.776947 last_seq = 14471 current_ts = 357.793793 current_received_ts = 357.793610 current_seq = 14472 count = 78 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.793793 last_received_ts = 357.793610 last_seq = 14472 current_ts = 357.810455 current_received_ts = 357.810303 current_seq = 14473 count = 79 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.810455 last_received_ts = 357.810303 last_seq = 14473 current_ts = 357.827118 current_received_ts = 357.826965 current_seq = 14474 count = 80 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 20us (kms_flip:2400) DEBUG: name = flip last_ts = 357.827118 last_received_ts = 357.826965 last_seq = 14474 current_ts = 357.843781 current_received_ts = 357.843658 current_seq = 14475 count = 81 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.843781 last_received_ts = 357.843658 last_seq = 14475 current_ts = 357.860443 current_received_ts = 357.860291 current_seq = 14476 count = 82 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.860443 last_received_ts = 357.860291 last_seq = 14476 current_ts = 357.877136 current_received_ts = 357.877228 current_seq = 14477 count = 83 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.877136 last_received_ts = 357.877228 last_seq = 14477 current_ts = 357.893799 current_received_ts = 357.893646 current_seq = 14478 count = 84 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.893799 last_received_ts = 357.893646 last_seq = 14478 current_ts = 357.910461 current_received_ts = 357.910309 current_seq = 14479 count = 85 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 357.910461 last_received_ts = 357.910309 last_seq = 14479 current_ts = 357.927124 current_received_ts = 357.926971 current_seq = 14480 count = 86 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.927124 last_received_ts = 357.926971 last_seq = 14480 current_ts = 357.943787 current_received_ts = 357.943665 current_seq = 14481 count = 87 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 357.943787 last_received_ts = 357.943665 last_seq = 14481 current_ts = 357.960449 current_received_ts = 357.960266 current_seq = 14482 count = 88 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 357.960449 last_received_ts = 357.960266 last_seq = 14482 current_ts = 357.977112 current_received_ts = 357.977081 current_seq = 14483 count = 89 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.977112 last_received_ts = 357.977081 last_seq = 14483 current_ts = 357.993774 current_received_ts = 357.993591 current_seq = 14484 count = 90 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 357.993774 last_received_ts = 357.993591 last_seq = 14484 current_ts = 358.010468 current_received_ts = 358.010254 current_seq = 14485 count = 91 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.010468 last_received_ts = 358.010254 last_seq = 14485 current_ts = 358.027130 current_received_ts = 358.027130 current_seq = 14486 count = 92 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.027130 last_received_ts = 358.027130 last_seq = 14486 current_ts = 358.043793 current_received_ts = 358.043610 current_seq = 14487 count = 93 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 28us (kms_flip:2400) DEBUG: name = flip last_ts = 358.043793 last_received_ts = 358.043610 last_seq = 14487 current_ts = 358.060455 current_received_ts = 358.060242 current_seq = 14488 count = 94 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.060455 last_received_ts = 358.060242 last_seq = 14488 current_ts = 358.077118 current_received_ts = 358.076996 current_seq = 14489 count = 95 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.077118 last_received_ts = 358.076996 last_seq = 14489 current_ts = 358.093781 current_received_ts = 358.093597 current_seq = 14490 count = 96 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.093781 last_received_ts = 358.093597 last_seq = 14490 current_ts = 358.110443 current_received_ts = 358.110321 current_seq = 14491 count = 97 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.110443 last_received_ts = 358.110321 last_seq = 14491 current_ts = 358.127136 current_received_ts = 358.127075 current_seq = 14492 count = 98 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 358.127136 last_received_ts = 358.127075 last_seq = 14492 current_ts = 358.143799 current_received_ts = 358.143585 current_seq = 14493 count = 99 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.143799 last_received_ts = 358.143585 last_seq = 14493 current_ts = 358.160461 current_received_ts = 358.160248 current_seq = 14494 count = 100 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.160461 last_received_ts = 358.160248 last_seq = 14494 current_ts = 358.177124 current_received_ts = 358.176941 current_seq = 14495 count = 101 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 78us (kms_flip:2400) DEBUG: name = flip last_ts = 358.177124 last_received_ts = 358.176941 last_seq = 14495 current_ts = 358.193787 current_received_ts = 358.193604 current_seq = 14496 count = 102 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.193787 last_received_ts = 358.193604 last_seq = 14496 current_ts = 358.210449 current_received_ts = 358.210266 current_seq = 14497 count = 103 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.210449 last_received_ts = 358.210266 last_seq = 14497 current_ts = 358.227112 current_received_ts = 358.226959 current_seq = 14498 count = 104 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 358.227112 last_received_ts = 358.226959 last_seq = 14498 current_ts = 358.243774 current_received_ts = 358.243530 current_seq = 14499 count = 105 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.243774 last_received_ts = 358.243530 last_seq = 14499 current_ts = 358.260468 current_received_ts = 358.260101 current_seq = 14500 count = 106 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 358.260468 last_received_ts = 358.260101 last_seq = 14500 current_ts = 358.277130 current_received_ts = 358.276947 current_seq = 14501 count = 107 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 80us (kms_flip:2400) DEBUG: name = flip last_ts = 358.277130 last_received_ts = 358.276947 last_seq = 14501 current_ts = 358.293793 current_received_ts = 358.293610 current_seq = 14502 count = 108 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.293793 last_received_ts = 358.293610 last_seq = 14502 current_ts = 358.310455 current_received_ts = 358.310150 current_seq = 14503 count = 109 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.310455 last_received_ts = 358.310150 last_seq = 14503 current_ts = 358.327118 current_received_ts = 358.326996 current_seq = 14504 count = 110 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.327118 last_received_ts = 358.326996 last_seq = 14504 current_ts = 358.343781 current_received_ts = 358.343658 current_seq = 14505 count = 111 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 24us (kms_flip:2400) DEBUG: name = flip last_ts = 358.343781 last_received_ts = 358.343658 last_seq = 14505 current_ts = 358.360443 current_received_ts = 358.360352 current_seq = 14506 count = 112 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.360443 last_received_ts = 358.360352 last_seq = 14506 current_ts = 358.377106 current_received_ts = 358.376984 current_seq = 14507 count = 113 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 19us (kms_flip:2400) DEBUG: name = flip last_ts = 358.377106 last_received_ts = 358.376984 last_seq = 14507 current_ts = 358.393799 current_received_ts = 358.393616 current_seq = 14508 count = 114 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.393799 last_received_ts = 358.393616 last_seq = 14508 current_ts = 358.410461 current_received_ts = 358.410248 current_seq = 14509 count = 115 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.410461 last_received_ts = 358.410248 last_seq = 14509 current_ts = 358.427124 current_received_ts = 358.427094 current_seq = 14510 count = 116 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 358.427124 last_received_ts = 358.427094 last_seq = 14510 current_ts = 358.443787 current_received_ts = 358.443604 current_seq = 14511 count = 117 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.443787 last_received_ts = 358.443604 last_seq = 14511 current_ts = 358.460449 current_received_ts = 358.460236 current_seq = 14512 count = 118 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.460449 last_received_ts = 358.460236 last_seq = 14512 current_ts = 358.477112 current_received_ts = 358.476990 current_seq = 14513 count = 119 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 22us (kms_flip:2400) DEBUG: name = flip last_ts = 358.477112 last_received_ts = 358.476990 last_seq = 14513 current_ts = 358.493774 current_received_ts = 358.493591 current_seq = 14514 count = 120 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.493774 last_received_ts = 358.493591 last_seq = 14514 current_ts = 358.510468 current_received_ts = 358.510223 current_seq = 14515 count = 121 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 25us (kms_flip:2400) DEBUG: name = flip last_ts = 358.510468 last_received_ts = 358.510223 last_seq = 14515 current_ts = 358.527130 current_received_ts = 358.527069 current_seq = 14516 count = 122 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 23us (kms_flip:2400) DEBUG: name = flip last_ts = 358.527130 last_received_ts = 358.527069 last_seq = 14516 current_ts = 358.543793 current_received_ts = 358.543640 current_seq = 14517 count = 123 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.543793 last_received_ts = 358.543640 last_seq = 14517 current_ts = 358.560455 current_received_ts = 358.560272 current_seq = 14518 count = 124 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.560455 last_received_ts = 358.560272 last_seq = 14518 current_ts = 358.577118 current_received_ts = 358.576996 current_seq = 14519 count = 125 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 20us (kms_flip:2400) DEBUG: name = flip last_ts = 358.577118 last_received_ts = 358.576996 last_seq = 14519 current_ts = 358.593811 current_received_ts = 358.593628 current_seq = 14520 count = 126 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.593811 last_received_ts = 358.593628 last_seq = 14520 current_ts = 358.610443 current_received_ts = 358.610260 current_seq = 14521 count = 127 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.610443 last_received_ts = 358.610260 last_seq = 14521 current_ts = 358.627136 current_received_ts = 358.626984 current_seq = 14522 count = 128 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 21us (kms_flip:2400) DEBUG: name = flip last_ts = 358.627136 last_received_ts = 358.626984 last_seq = 14522 current_ts = 358.643799 current_received_ts = 358.643646 current_seq = 14523 count = 129 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.643799 last_received_ts = 358.643646 last_seq = 14523 current_ts = 358.660461 current_received_ts = 358.660217 current_seq = 14524 count = 130 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.660461 last_received_ts = 358.660217 last_seq = 14524 current_ts = 358.677124 current_received_ts = 358.677094 current_seq = 14525 count = 131 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 28us (kms_flip:2400) DEBUG: name = flip last_ts = 358.677124 last_received_ts = 358.677094 last_seq = 14525 current_ts = 358.693787 current_received_ts = 358.693634 current_seq = 14526 count = 132 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.693787 last_received_ts = 358.693634 last_seq = 14526 current_ts = 358.710449 current_received_ts = 358.710236 current_seq = 14527 count = 133 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.710449 last_received_ts = 358.710236 last_seq = 14527 current_ts = 358.727112 current_received_ts = 358.727081 current_seq = 14528 count = 134 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.727112 last_received_ts = 358.727081 last_seq = 14528 current_ts = 358.743805 current_received_ts = 358.743591 current_seq = 14529 count = 135 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.743805 last_received_ts = 358.743591 last_seq = 14529 current_ts = 358.760468 current_received_ts = 358.760254 current_seq = 14530 count = 136 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.760468 last_received_ts = 358.760254 last_seq = 14530 current_ts = 358.777130 current_received_ts = 358.776855 current_seq = 14531 count = 137 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.777130 last_received_ts = 358.776855 last_seq = 14531 current_ts = 358.793793 current_received_ts = 358.793610 current_seq = 14532 count = 138 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.793793 last_received_ts = 358.793610 last_seq = 14532 current_ts = 358.810455 current_received_ts = 358.810242 current_seq = 14533 count = 139 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.810455 last_received_ts = 358.810242 last_seq = 14533 current_ts = 358.827118 current_received_ts = 358.827057 current_seq = 14534 count = 140 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 21us (kms_flip:2400) DEBUG: name = flip last_ts = 358.827118 last_received_ts = 358.827057 last_seq = 14534 current_ts = 358.843811 current_received_ts = 358.843628 current_seq = 14535 count = 141 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.843811 last_received_ts = 358.843628 last_seq = 14535 current_ts = 358.860443 current_received_ts = 358.860260 current_seq = 14536 count = 142 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.860443 last_received_ts = 358.860260 last_seq = 14536 current_ts = 358.877136 current_received_ts = 358.876923 current_seq = 14537 count = 143 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 97us (kms_flip:2400) DEBUG: name = flip last_ts = 358.877136 last_received_ts = 358.876923 last_seq = 14537 current_ts = 358.893799 current_received_ts = 358.893585 current_seq = 14538 count = 144 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 26us (kms_flip:2400) DEBUG: name = flip last_ts = 358.893799 last_received_ts = 358.893585 last_seq = 14538 current_ts = 358.910461 current_received_ts = 358.910248 current_seq = 14539 count = 145 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.910461 last_received_ts = 358.910248 last_seq = 14539 current_ts = 358.927124 current_received_ts = 358.926971 current_seq = 14540 count = 146 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 27us (kms_flip:2400) DEBUG: name = flip last_ts = 358.927124 last_received_ts = 358.926971 last_seq = 14540 current_ts = 358.943787 current_received_ts = 358.943451 current_seq = 14541 count = 147 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 20us (kms_flip:2400) DEBUG: name = flip last_ts = 358.943787 last_received_ts = 358.943451 last_seq = 14541 current_ts = 358.960449 current_received_ts = 358.961060 current_seq = 14542 count = 148 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 14us (kms_flip:2400) DEBUG: name = flip last_ts = 358.960449 last_received_ts = 358.961060 last_seq = 14542 current_ts = 358.977112 current_received_ts = 358.977325 current_seq = 14543 count = 149 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 13us (kms_flip:2400) DEBUG: name = flip last_ts = 358.977112 last_received_ts = 358.977325 last_seq = 14543 current_ts = 358.993774 current_received_ts = 358.993256 current_seq = 14544 count = 150 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 14us (kms_flip:2400) DEBUG: name = flip last_ts = 358.993774 last_received_ts = 358.993256 last_seq = 14544 current_ts = 359.010437 current_received_ts = 359.011139 current_seq = 14545 count = 151 seq_step = 1 (kms_flip:2400) DEBUG: Vblank took 899us (kms_flip:2400) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:2400) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2400) igt_core-INFO: Stack trace: (kms_flip:2400) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2400) igt_core-INFO: #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() (kms_flip:2400) igt_core-INFO: #2 ../tests/kms_flip.c:1891 run_test() (kms_flip:2400) igt_core-INFO: #3 ../tests/kms_flip.c:2126 __igt_unique____real_main2047() (kms_flip:2400) igt_core-INFO: #4 ../tests/kms_flip.c:2047 main() (kms_flip:2400) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2400) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2400) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A1: FAIL (3.627s)
Dmesg	<6> [356.372115] [IGT] kms_flip: starting dynamic subtest B-HDMI-A1 <7> [356.373376] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:180] <7> [356.373739] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:182] <7> [356.430928] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A] <7> [356.431505] 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> [356.432631] 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> [356.433733] 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> [356.434782] 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> [356.435399] 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> [356.435782] 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> [356.436191] 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> [356.436572] 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> [356.436949] 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> [356.437367] 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> [356.437746] 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> [356.438123] 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> [356.438527] 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> [356.438906] 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> [356.439329] 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> [356.439707] 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> [356.440162] 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> [356.440745] 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> [356.441215] 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> [356.441594] 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> [356.441972] 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> [356.442460] 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> [356.442841] 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> [356.443245] 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> [356.443649] 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> [356.444027] 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> [356.444456] 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> [356.444858] 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> [356.445282] 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> [356.445662] 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> [356.446038] 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> [356.446482] 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> [356.446860] 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> [356.447317] 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> [356.447699] 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> [356.448079] 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> [356.448523] 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> [356.448908] 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> [356.449352] 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> [356.449731] 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> [356.450109] 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> [356.450536] 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> [356.450916] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in avi infoframe <7> [356.451333] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [356.451713] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [356.451718] i915 0000:00:02.0: colorspace: RGB <7> [356.451722] i915 0000:00:02.0: scan mode: Underscan <7> [356.451726] i915 0000:00:02.0: colorimetry: No Data <7> [356.451729] i915 0000:00:02.0: picture aspect: No Data <7> [356.451733] i915 0000:00:02.0: active aspect: Same as Picture <7> [356.451736] i915 0000:00:02.0: itc: No Data <7> [356.451740] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [356.451744] i915 0000:00:02.0: quantization range: Full <7> [356.451747] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [356.451750] i915 0000:00:02.0: video code: 0 <7> [356.451753] i915 0000:00:02.0: ycc quantization range: Full <7> [356.451757] i915 0000:00:02.0: hdmi content type: Graphics <7> [356.451760] i915 0000:00:02.0: pixel repeat: 0 <7> [356.451763] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [356.451767] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [356.452143] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in spd infoframe <7> [356.452559] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [356.452937] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [356.452942] i915 0000:00:02.0: vendor: Intel <7> [356.452945] i915 0000:00:02.0: product: Integrated gfx <7> [356.452948] i915 0000:00:02.0: source device information: PC General (0x9) <7> [356.452952] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [356.453365] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hdmi infoframe <7> [356.453834] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [356.454412] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [356.454417] i915 0000:00:02.0: empty frame <7> [356.454420] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [356.454876] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:78:pipe A] fastset requirement not met, forcing full modeset <7> [356.455382] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:78:pipe A] releasing PORT PLL B <7> [356.455830] 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> [356.456291] 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> [356.456753] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:78:pipe A] min cdclk: 192000 kHz -> 0 kHz <7> [356.457283] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [356.457665] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz <7> [356.458041] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4 <7> [356.458469] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:78:pipe A] enable: no [modeset] <7> [356.458851] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:36:plane 1A] fb: [NOFB], visible: no <7> [356.459274] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:45:plane 2A] fb: [NOFB], visible: no <7> [356.459653] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:plane 3A] fb: [NOFB], visible: no <7> [356.460060] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 4A] fb: [NOFB], visible: no <7> [356.460516] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:72:cursor A] fb: [NOFB], visible: no <7> [356.461046] 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> [356.483926] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [356.484601] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [356.501251] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time <7> [356.609657] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [356.610898] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x1, on? 1) for [CRTC:78:pipe A] <7> [356.613899] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL B <7> [356.614511] 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> [356.614948] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [356.615401] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [356.615783] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:166:HDMI-A-1] <7> [356.616729] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-b <7> [356.617161] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [356.617797] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:78:pipe A] <7> [356.618863] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [356.619292] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C] <7> [356.619641] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [356.619702] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:166:HDMI-A-1] <7> [356.619880] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 12 bpc for HDMI output (pipe bpp: 36) <7> [356.620391] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [356.620777] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:165:DDI B/PHY B] [CRTC:121:pipe B] <7> [356.623433] 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> [356.623930] 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> [356.624365] 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> [356.624746] 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> [356.625122] 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> [356.625570] 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> [356.625949] 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> [356.626553] 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> [356.627000] 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> [356.627537] 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> [356.627930] 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> [356.628335] 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> [356.628713] 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> [356.629108] 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> [356.629542] 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> [356.629943] 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> [356.630370] 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> [356.630750] 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> [356.631127] 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> [356.631536] 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> [356.631946] 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> [356.634621] 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> [356.635548] 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> [356.636002] 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> [356.636524] 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> [356.636908] 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> [356.637338] 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> [356.637717] 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> [356.638113] 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> [356.638584] 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> [356.638988] 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> [356.639454] 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> [356.639831] 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> [356.640228] 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> [356.640607] 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> [356.641015] 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> [356.643493] 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> [356.644101] 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> [356.644610] 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> [356.644993] 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> [356.645399] 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> [356.645781] 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> [356.646464] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in avi infoframe <7> [356.646953] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [356.647478] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [356.647863] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [356.647870] i915 0000:00:02.0: colorspace: RGB <7> [356.647874] i915 0000:00:02.0: scan mode: Underscan <7> [356.647878] i915 0000:00:02.0: colorimetry: No Data <7> [356.647881] i915 0000:00:02.0: picture aspect: No Data <7> [356.647885] i915 0000:00:02.0: active aspect: Same as Picture <7> [356.647888] i915 0000:00:02.0: itc: No Data <7> [356.647892] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [356.647896] i915 0000:00:02.0: quantization range: Full <7> [356.647899] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [356.647903] i915 0000:00:02.0: video code: 0 <7> [356.647906] i915 0000:00:02.0: ycc quantization range: Full <7> [356.647909] i915 0000:00:02.0: hdmi content type: Graphics <7> [356.647913] i915 0000:00:02.0: pixel repeat: 0 <7> [356.647916] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [356.647920] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in spd infoframe <7> [356.648324] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [356.648719] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [356.649094] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [356.649098] i915 0000:00:02.0: vendor: Intel <7> [356.649102] i915 0000:00:02.0: product: Integrated gfx <7> [356.649105] i915 0000:00:02.0: source device information: PC General (0x9) <7> [356.649109] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hdmi infoframe <7> [356.649581] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [356.649982] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [356.650419] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [356.650424] i915 0000:00:02.0: empty frame <7> [356.650429] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] fastset requirement not met, forcing full modeset <7> [356.650894] 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> [356.651363] 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> [356.651769] 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> [356.652145] 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> [356.654212] 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> [356.654719] 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> [356.655095] 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> [356.655515] 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> [356.655992] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:121:pipe B] min cdclk: 0 kHz -> 192000 kHz <7> [356.657893] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [356.658824] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz <7> [356.659323] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13 <7> [356.659710] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:121:pipe B] using pre-allocated PORT PLL B <7> [356.660095] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:121:pipe B] reserving PORT PLL B <7> [356.660641] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:121:pipe B] enable: yes [modeset] <7> [356.661027] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [356.661449] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 36, dithering: 0 <7> [356.661825] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [356.662238] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [356.662616] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [356.662992] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [356.663468] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [356.663871] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6 <7> [356.664294] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [356.664299] i915 0000:00:02.0: colorspace: RGB <7> [356.664304] i915 0000:00:02.0: scan mode: Underscan <7> [356.664307] i915 0000:00:02.0: colorimetry: No Data <7> [356.664311] i915 0000:00:02.0: picture aspect: No Data <7> [356.664314] i915 0000:00:02.0: active aspect: Same as Picture <7> [356.664317] i915 0000:00:02.0: itc: No Data <7> [356.664321] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [356.664324] i915 0000:00:02.0: quantization range: Full <7> [356.664327] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [356.664331] i915 0000:00:02.0: video code: 0 <7> [356.664334] i915 0000:00:02.0: ycc quantization range: Full <7> [356.664337] i915 0000:00:02.0: hdmi content type: Graphics <7> [356.664341] i915 0000:00:02.0: pixel repeat: 0 <7> [356.664344] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [356.664348] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [356.664353] i915 0000:00:02.0: vendor: Intel <7> [356.664356] i915 0000:00:02.0: product: Integrated gfx <7> [356.664359] i915 0000:00:02.0: source device information: PC General (0x9) <7> [356.664363] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [356.664367] i915 0000:00:02.0: empty frame <7> [356.664370] 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> [356.664748] 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> [356.665124] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [356.665531] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [356.665935] 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> [356.668269] 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> [356.668775] 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> [356.669155] 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> [356.669572] 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> [356.669954] 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> [356.670369] 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> [356.670747] 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> [356.671128] 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> [356.672741] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [356.673263] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [356.673641] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [356.674019] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [356.674832] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [356.675336] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [356.675721] 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> [356.676102] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [356.676647] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [356.677029] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [356.677446] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [356.677822] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [356.678274] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [356.678671] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [356.679051] 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> [356.679495] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [356.679873] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [356.680275] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:88:plane 2B] fb: [NOFB], visible: no <7> [356.680655] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:97:plane 3B] fb: [NOFB], visible: no <7> [356.681061] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:106:plane 4B] fb: [NOFB], visible: no <7> [356.683878] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:115:cursor B] fb: [NOFB], visible: no <7> [356.685163] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [356.686115] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-b <7> [356.686988] 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> [356.687481] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [356.687868] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [356.688457] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL B (active 0x2, on? 0) for [CRTC:121:pipe B] <7> [356.688847] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL B <7> [356.689553] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B <7> [356.690053] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [356.710370] 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> [356.723735] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10 <7> [356.727012] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000) <7> [356.727551] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <7> [356.728104] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:166:HDMI-A-1] <7> [356.728809] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:121:pipe B] <7> [356.737306] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL <7> [356.737327] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled <6> [360.000534] [IGT] kms_flip: finished subtest B-HDMI-A1, FAIL

Detail

Value

Duration

3.63 seconds

Hostname

shard-glk9

Igt-Version

IGT-Version: 2.4-g0a40de522 (x86_64) (Linux: 7.0.0-rc6-CI_DRM_18263-g35dad892ec87+ 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:925 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1891 run_test()
  #3 ../tests/kms_flip.c:2126 __igt_unique____real_main2047()
  #4 ../tests/kms_flip.c:2047 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A1: FAIL (3.627s)

Err

Starting dynamic subtest: B-HDMI-A1
(kms_flip:2400) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:2400) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2400) DEBUG: name = flip
last_ts = 356.977112
last_received_ts = 356.976929
last_seq = 14423
current_ts = 356.993805
current_received_ts = 356.993591
current_seq = 14424
count = 30
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 356.993805
last_received_ts = 356.993591
last_seq = 14424
current_ts = 357.010468
current_received_ts = 357.010315
current_seq = 14425
count = 31
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.010468
last_received_ts = 357.010315
last_seq = 14425
current_ts = 357.027130
current_received_ts = 357.026978
current_seq = 14426
count = 32
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 19us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.027130
last_received_ts = 357.026978
last_seq = 14426
current_ts = 357.043793
current_received_ts = 357.043640
current_seq = 14427
count = 33
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.043793
last_received_ts = 357.043640
last_seq = 14427
current_ts = 357.060455
current_received_ts = 357.060333
current_seq = 14428
count = 34
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.060455
last_received_ts = 357.060333
last_seq = 14428
current_ts = 357.077118
current_received_ts = 357.076996
current_seq = 14429
count = 35
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.077118
last_received_ts = 357.076996
last_seq = 14429
current_ts = 357.093781
current_received_ts = 357.093658
current_seq = 14430
count = 36
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.093781
last_received_ts = 357.093658
last_seq = 14430
current_ts = 357.110474
current_received_ts = 357.110321
current_seq = 14431
count = 37
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.110474
last_received_ts = 357.110321
last_seq = 14431
current_ts = 357.127136
current_received_ts = 357.126984
current_seq = 14432
count = 38
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.127136
last_received_ts = 357.126984
last_seq = 14432
current_ts = 357.143799
current_received_ts = 357.143585
current_seq = 14433
count = 39
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.143799
last_received_ts = 357.143585
last_seq = 14433
current_ts = 357.160461
current_received_ts = 357.160278
current_seq = 14434
count = 40
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.160461
last_received_ts = 357.160278
last_seq = 14434
current_ts = 357.177124
current_received_ts = 357.177094
current_seq = 14435
count = 41
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.177124
last_received_ts = 357.177094
last_seq = 14435
current_ts = 357.193787
current_received_ts = 357.193634
current_seq = 14436
count = 42
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.193787
last_received_ts = 357.193634
last_seq = 14436
current_ts = 357.210449
current_received_ts = 357.210327
current_seq = 14437
count = 43
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.210449
last_received_ts = 357.210327
last_seq = 14437
current_ts = 357.227112
current_received_ts = 357.227081
current_seq = 14438
count = 44
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 22us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.227112
last_received_ts = 357.227081
last_seq = 14438
current_ts = 357.243805
current_received_ts = 357.243652
current_seq = 14439
count = 45
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.243805
last_received_ts = 357.243652
last_seq = 14439
current_ts = 357.260437
current_received_ts = 357.260223
current_seq = 14440
count = 46
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.260437
last_received_ts = 357.260223
last_seq = 14440
current_ts = 357.277130
current_received_ts = 357.276947
current_seq = 14441
count = 47
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 100us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.277130
last_received_ts = 357.276947
last_seq = 14441
current_ts = 357.293793
current_received_ts = 357.293610
current_seq = 14442
count = 48
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.293793
last_received_ts = 357.293610
last_seq = 14442
current_ts = 357.310455
current_received_ts = 357.310333
current_seq = 14443
count = 49
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 24us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.310455
last_received_ts = 357.310333
last_seq = 14443
current_ts = 357.327118
current_received_ts = 357.326996
current_seq = 14444
count = 50
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.327118
last_received_ts = 357.326996
last_seq = 14444
current_ts = 357.343781
current_received_ts = 357.343658
current_seq = 14445
count = 51
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.343781
last_received_ts = 357.343658
last_seq = 14445
current_ts = 357.360443
current_received_ts = 357.360321
current_seq = 14446
count = 52
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 24us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.360443
last_received_ts = 357.360321
last_seq = 14446
current_ts = 357.377136
current_received_ts = 357.376984
current_seq = 14447
count = 53
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.377136
last_received_ts = 357.376984
last_seq = 14447
current_ts = 357.393799
current_received_ts = 357.393646
current_seq = 14448
count = 54
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.393799
last_received_ts = 357.393646
last_seq = 14448
current_ts = 357.410461
current_received_ts = 357.410339
current_seq = 14449
count = 55
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.410461
last_received_ts = 357.410339
last_seq = 14449
current_ts = 357.427124
current_received_ts = 357.426971
current_seq = 14450
count = 56
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 20us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.427124
last_received_ts = 357.426971
last_seq = 14450
current_ts = 357.443787
current_received_ts = 357.443634
current_seq = 14451
count = 57
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.443787
last_received_ts = 357.443634
last_seq = 14451
current_ts = 357.460449
current_received_ts = 357.460297
current_seq = 14452
count = 58
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.460449
last_received_ts = 357.460297
last_seq = 14452
current_ts = 357.477142
current_received_ts = 357.477203
current_seq = 14453
count = 59
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 24us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.477142
last_received_ts = 357.477203
last_seq = 14453
current_ts = 357.493805
current_received_ts = 357.493622
current_seq = 14454
count = 60
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.493805
last_received_ts = 357.493622
last_seq = 14454
current_ts = 357.510468
current_received_ts = 357.510254
current_seq = 14455
count = 61
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.510468
last_received_ts = 357.510254
last_seq = 14455
current_ts = 357.527130
current_received_ts = 357.526947
current_seq = 14456
count = 62
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.527130
last_received_ts = 357.526947
last_seq = 14456
current_ts = 357.543793
current_received_ts = 357.543640
current_seq = 14457
count = 63
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.543793
last_received_ts = 357.543640
last_seq = 14457
current_ts = 357.560455
current_received_ts = 357.560303
current_seq = 14458
count = 64
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.560455
last_received_ts = 357.560303
last_seq = 14458
current_ts = 357.577118
current_received_ts = 357.576965
current_seq = 14459
count = 65
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.577118
last_received_ts = 357.576965
last_seq = 14459
current_ts = 357.593781
current_received_ts = 357.593689
current_seq = 14460
count = 66
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.593781
last_received_ts = 357.593689
last_seq = 14460
current_ts = 357.610443
current_received_ts = 357.610352
current_seq = 14461
count = 67
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 24us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.610443
last_received_ts = 357.610352
last_seq = 14461
current_ts = 357.627136
current_received_ts = 357.627075
current_seq = 14462
count = 68
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.627136
last_received_ts = 357.627075
last_seq = 14462
current_ts = 357.643799
current_received_ts = 357.643646
current_seq = 14463
count = 69
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.643799
last_received_ts = 357.643646
last_seq = 14463
current_ts = 357.660461
current_received_ts = 357.660339
current_seq = 14464
count = 70
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.660461
last_received_ts = 357.660339
last_seq = 14464
current_ts = 357.677124
current_received_ts = 357.676971
current_seq = 14465
count = 71
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.677124
last_received_ts = 357.676971
last_seq = 14465
current_ts = 357.693787
current_received_ts = 357.693604
current_seq = 14466
count = 72
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.693787
last_received_ts = 357.693604
last_seq = 14466
current_ts = 357.710449
current_received_ts = 357.710327
current_seq = 14467
count = 73
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.710449
last_received_ts = 357.710327
last_seq = 14467
current_ts = 357.727112
current_received_ts = 357.726929
current_seq = 14468
count = 74
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 18us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.727112
last_received_ts = 357.726929
last_seq = 14468
current_ts = 357.743774
current_received_ts = 357.743591
current_seq = 14469
count = 75
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.743774
last_received_ts = 357.743591
last_seq = 14469
current_ts = 357.760468
current_received_ts = 357.760315
current_seq = 14470
count = 76
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.760468
last_received_ts = 357.760315
last_seq = 14470
current_ts = 357.777130
current_received_ts = 357.776947
current_seq = 14471
count = 77
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 78us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.777130
last_received_ts = 357.776947
last_seq = 14471
current_ts = 357.793793
current_received_ts = 357.793610
current_seq = 14472
count = 78
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.793793
last_received_ts = 357.793610
last_seq = 14472
current_ts = 357.810455
current_received_ts = 357.810303
current_seq = 14473
count = 79
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.810455
last_received_ts = 357.810303
last_seq = 14473
current_ts = 357.827118
current_received_ts = 357.826965
current_seq = 14474
count = 80
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 20us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.827118
last_received_ts = 357.826965
last_seq = 14474
current_ts = 357.843781
current_received_ts = 357.843658
current_seq = 14475
count = 81
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.843781
last_received_ts = 357.843658
last_seq = 14475
current_ts = 357.860443
current_received_ts = 357.860291
current_seq = 14476
count = 82
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.860443
last_received_ts = 357.860291
last_seq = 14476
current_ts = 357.877136
current_received_ts = 357.877228
current_seq = 14477
count = 83
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.877136
last_received_ts = 357.877228
last_seq = 14477
current_ts = 357.893799
current_received_ts = 357.893646
current_seq = 14478
count = 84
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.893799
last_received_ts = 357.893646
last_seq = 14478
current_ts = 357.910461
current_received_ts = 357.910309
current_seq = 14479
count = 85
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.910461
last_received_ts = 357.910309
last_seq = 14479
current_ts = 357.927124
current_received_ts = 357.926971
current_seq = 14480
count = 86
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.927124
last_received_ts = 357.926971
last_seq = 14480
current_ts = 357.943787
current_received_ts = 357.943665
current_seq = 14481
count = 87
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.943787
last_received_ts = 357.943665
last_seq = 14481
current_ts = 357.960449
current_received_ts = 357.960266
current_seq = 14482
count = 88
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.960449
last_received_ts = 357.960266
last_seq = 14482
current_ts = 357.977112
current_received_ts = 357.977081
current_seq = 14483
count = 89
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.977112
last_received_ts = 357.977081
last_seq = 14483
current_ts = 357.993774
current_received_ts = 357.993591
current_seq = 14484
count = 90
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 357.993774
last_received_ts = 357.993591
last_seq = 14484
current_ts = 358.010468
current_received_ts = 358.010254
current_seq = 14485
count = 91
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.010468
last_received_ts = 358.010254
last_seq = 14485
current_ts = 358.027130
current_received_ts = 358.027130
current_seq = 14486
count = 92
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.027130
last_received_ts = 358.027130
last_seq = 14486
current_ts = 358.043793
current_received_ts = 358.043610
current_seq = 14487
count = 93
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 28us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.043793
last_received_ts = 358.043610
last_seq = 14487
current_ts = 358.060455
current_received_ts = 358.060242
current_seq = 14488
count = 94
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.060455
last_received_ts = 358.060242
last_seq = 14488
current_ts = 358.077118
current_received_ts = 358.076996
current_seq = 14489
count = 95
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.077118
last_received_ts = 358.076996
last_seq = 14489
current_ts = 358.093781
current_received_ts = 358.093597
current_seq = 14490
count = 96
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.093781
last_received_ts = 358.093597
last_seq = 14490
current_ts = 358.110443
current_received_ts = 358.110321
current_seq = 14491
count = 97
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.110443
last_received_ts = 358.110321
last_seq = 14491
current_ts = 358.127136
current_received_ts = 358.127075
current_seq = 14492
count = 98
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.127136
last_received_ts = 358.127075
last_seq = 14492
current_ts = 358.143799
current_received_ts = 358.143585
current_seq = 14493
count = 99
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.143799
last_received_ts = 358.143585
last_seq = 14493
current_ts = 358.160461
current_received_ts = 358.160248
current_seq = 14494
count = 100
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.160461
last_received_ts = 358.160248
last_seq = 14494
current_ts = 358.177124
current_received_ts = 358.176941
current_seq = 14495
count = 101
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 78us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.177124
last_received_ts = 358.176941
last_seq = 14495
current_ts = 358.193787
current_received_ts = 358.193604
current_seq = 14496
count = 102
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.193787
last_received_ts = 358.193604
last_seq = 14496
current_ts = 358.210449
current_received_ts = 358.210266
current_seq = 14497
count = 103
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.210449
last_received_ts = 358.210266
last_seq = 14497
current_ts = 358.227112
current_received_ts = 358.226959
current_seq = 14498
count = 104
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.227112
last_received_ts = 358.226959
last_seq = 14498
current_ts = 358.243774
current_received_ts = 358.243530
current_seq = 14499
count = 105
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.243774
last_received_ts = 358.243530
last_seq = 14499
current_ts = 358.260468
current_received_ts = 358.260101
current_seq = 14500
count = 106
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.260468
last_received_ts = 358.260101
last_seq = 14500
current_ts = 358.277130
current_received_ts = 358.276947
current_seq = 14501
count = 107
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 80us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.277130
last_received_ts = 358.276947
last_seq = 14501
current_ts = 358.293793
current_received_ts = 358.293610
current_seq = 14502
count = 108
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.293793
last_received_ts = 358.293610
last_seq = 14502
current_ts = 358.310455
current_received_ts = 358.310150
current_seq = 14503
count = 109
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.310455
last_received_ts = 358.310150
last_seq = 14503
current_ts = 358.327118
current_received_ts = 358.326996
current_seq = 14504
count = 110
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.327118
last_received_ts = 358.326996
last_seq = 14504
current_ts = 358.343781
current_received_ts = 358.343658
current_seq = 14505
count = 111
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 24us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.343781
last_received_ts = 358.343658
last_seq = 14505
current_ts = 358.360443
current_received_ts = 358.360352
current_seq = 14506
count = 112
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.360443
last_received_ts = 358.360352
last_seq = 14506
current_ts = 358.377106
current_received_ts = 358.376984
current_seq = 14507
count = 113
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 19us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.377106
last_received_ts = 358.376984
last_seq = 14507
current_ts = 358.393799
current_received_ts = 358.393616
current_seq = 14508
count = 114
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.393799
last_received_ts = 358.393616
last_seq = 14508
current_ts = 358.410461
current_received_ts = 358.410248
current_seq = 14509
count = 115
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.410461
last_received_ts = 358.410248
last_seq = 14509
current_ts = 358.427124
current_received_ts = 358.427094
current_seq = 14510
count = 116
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.427124
last_received_ts = 358.427094
last_seq = 14510
current_ts = 358.443787
current_received_ts = 358.443604
current_seq = 14511
count = 117
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.443787
last_received_ts = 358.443604
last_seq = 14511
current_ts = 358.460449
current_received_ts = 358.460236
current_seq = 14512
count = 118
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.460449
last_received_ts = 358.460236
last_seq = 14512
current_ts = 358.477112
current_received_ts = 358.476990
current_seq = 14513
count = 119
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 22us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.477112
last_received_ts = 358.476990
last_seq = 14513
current_ts = 358.493774
current_received_ts = 358.493591
current_seq = 14514
count = 120
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.493774
last_received_ts = 358.493591
last_seq = 14514
current_ts = 358.510468
current_received_ts = 358.510223
current_seq = 14515
count = 121
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 25us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.510468
last_received_ts = 358.510223
last_seq = 14515
current_ts = 358.527130
current_received_ts = 358.527069
current_seq = 14516
count = 122
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 23us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.527130
last_received_ts = 358.527069
last_seq = 14516
current_ts = 358.543793
current_received_ts = 358.543640
current_seq = 14517
count = 123
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.543793
last_received_ts = 358.543640
last_seq = 14517
current_ts = 358.560455
current_received_ts = 358.560272
current_seq = 14518
count = 124
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.560455
last_received_ts = 358.560272
last_seq = 14518
current_ts = 358.577118
current_received_ts = 358.576996
current_seq = 14519
count = 125
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 20us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.577118
last_received_ts = 358.576996
last_seq = 14519
current_ts = 358.593811
current_received_ts = 358.593628
current_seq = 14520
count = 126
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.593811
last_received_ts = 358.593628
last_seq = 14520
current_ts = 358.610443
current_received_ts = 358.610260
current_seq = 14521
count = 127
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.610443
last_received_ts = 358.610260
last_seq = 14521
current_ts = 358.627136
current_received_ts = 358.626984
current_seq = 14522
count = 128
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 21us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.627136
last_received_ts = 358.626984
last_seq = 14522
current_ts = 358.643799
current_received_ts = 358.643646
current_seq = 14523
count = 129
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.643799
last_received_ts = 358.643646
last_seq = 14523
current_ts = 358.660461
current_received_ts = 358.660217
current_seq = 14524
count = 130
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.660461
last_received_ts = 358.660217
last_seq = 14524
current_ts = 358.677124
current_received_ts = 358.677094
current_seq = 14525
count = 131
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 28us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.677124
last_received_ts = 358.677094
last_seq = 14525
current_ts = 358.693787
current_received_ts = 358.693634
current_seq = 14526
count = 132
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.693787
last_received_ts = 358.693634
last_seq = 14526
current_ts = 358.710449
current_received_ts = 358.710236
current_seq = 14527
count = 133
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.710449
last_received_ts = 358.710236
last_seq = 14527
current_ts = 358.727112
current_received_ts = 358.727081
current_seq = 14528
count = 134
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.727112
last_received_ts = 358.727081
last_seq = 14528
current_ts = 358.743805
current_received_ts = 358.743591
current_seq = 14529
count = 135
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.743805
last_received_ts = 358.743591
last_seq = 14529
current_ts = 358.760468
current_received_ts = 358.760254
current_seq = 14530
count = 136
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.760468
last_received_ts = 358.760254
last_seq = 14530
current_ts = 358.777130
current_received_ts = 358.776855
current_seq = 14531
count = 137
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.777130
last_received_ts = 358.776855
last_seq = 14531
current_ts = 358.793793
current_received_ts = 358.793610
current_seq = 14532
count = 138
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.793793
last_received_ts = 358.793610
last_seq = 14532
current_ts = 358.810455
current_received_ts = 358.810242
current_seq = 14533
count = 139
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.810455
last_received_ts = 358.810242
last_seq = 14533
current_ts = 358.827118
current_received_ts = 358.827057
current_seq = 14534
count = 140
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 21us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.827118
last_received_ts = 358.827057
last_seq = 14534
current_ts = 358.843811
current_received_ts = 358.843628
current_seq = 14535
count = 141
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.843811
last_received_ts = 358.843628
last_seq = 14535
current_ts = 358.860443
current_received_ts = 358.860260
current_seq = 14536
count = 142
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.860443
last_received_ts = 358.860260
last_seq = 14536
current_ts = 358.877136
current_received_ts = 358.876923
current_seq = 14537
count = 143
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 97us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.877136
last_received_ts = 358.876923
last_seq = 14537
current_ts = 358.893799
current_received_ts = 358.893585
current_seq = 14538
count = 144
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 26us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.893799
last_received_ts = 358.893585
last_seq = 14538
current_ts = 358.910461
current_received_ts = 358.910248
current_seq = 14539
count = 145
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.910461
last_received_ts = 358.910248
last_seq = 14539
current_ts = 358.927124
current_received_ts = 358.926971
current_seq = 14540
count = 146
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 27us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.927124
last_received_ts = 358.926971
last_seq = 14540
current_ts = 358.943787
current_received_ts = 358.943451
current_seq = 14541
count = 147
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 20us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.943787
last_received_ts = 358.943451
last_seq = 14541
current_ts = 358.960449
current_received_ts = 358.961060
current_seq = 14542
count = 148
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 14us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.960449
last_received_ts = 358.961060
last_seq = 14542
current_ts = 358.977112
current_received_ts = 358.977325
current_seq = 14543
count = 149
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 13us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.977112
last_received_ts = 358.977325
last_seq = 14543
current_ts = 358.993774
current_received_ts = 358.993256
current_seq = 14544
count = 150
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 14us
(kms_flip:2400) DEBUG: name = flip
last_ts = 358.993774
last_received_ts = 358.993256
last_seq = 14544
current_ts = 359.010437
current_received_ts = 359.011139
current_seq = 14545
count = 151
seq_step = 1
(kms_flip:2400) DEBUG: Vblank took 899us
(kms_flip:2400) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:2400) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2400) igt_core-INFO: Stack trace:
(kms_flip:2400) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2400) igt_core-INFO:   #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0()
(kms_flip:2400) igt_core-INFO:   #2 ../tests/kms_flip.c:1891 run_test()
(kms_flip:2400) igt_core-INFO:   #3 ../tests/kms_flip.c:2126 __igt_unique____real_main2047()
(kms_flip:2400) igt_core-INFO:   #4 ../tests/kms_flip.c:2047 main()
(kms_flip:2400) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2400) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2400) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (3.627s)

Dmesg

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

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

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

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

<7> [356.431505] 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> [356.432631] 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> [356.433733] 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> [356.434782] 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> [356.435399] 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> [356.435782] 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> [356.436191] 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> [356.436572] 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> [356.436949] 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> [356.437367] 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> [356.437746] 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> [356.438123] 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> [356.438527] 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> [356.438906] 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> [356.439329] 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> [356.439707] 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> [356.440162] 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> [356.440745] 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> [356.441215] 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> [356.441594] 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> [356.441972] 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> [356.442460] 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> [356.442841] 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> [356.443245] 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> [356.443649] 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> [356.444027] 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> [356.444456] 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> [356.444858] 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> [356.445282] 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> [356.445662] 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> [356.446038] 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> [356.446482] 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> [356.446860] 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> [356.447317] 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> [356.447699] 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> [356.448079] 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> [356.448523] 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> [356.448908] 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> [356.449352] 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> [356.449731] 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> [356.450109] 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> [356.450536] 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> [356.450916] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in avi infoframe

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [356.455830] 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> [356.456291] 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> [356.456753] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:78:pipe A] min cdclk: 192000 kHz -> 0 kHz

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

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

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

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

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

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

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

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

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

<7> [356.461046] 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> [356.483926] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B

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

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

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

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

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

<7> [356.614511] 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> [356.614948] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B]

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

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

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

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

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

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

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

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

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

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

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

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

<7> [356.623433] 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> [356.623930] 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> [356.624365] 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> [356.624746] 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> [356.625122] 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> [356.625570] 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> [356.625949] 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> [356.626553] 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> [356.627000] 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> [356.627537] 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> [356.627930] 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> [356.628335] 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> [356.628713] 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> [356.629108] 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> [356.629542] 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> [356.629943] 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> [356.630370] 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> [356.630750] 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> [356.631127] 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> [356.631536] 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> [356.631946] 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> [356.634621] 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> [356.635548] 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> [356.636002] 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> [356.636524] 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> [356.636908] 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> [356.637338] 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> [356.637717] 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> [356.638113] 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> [356.638584] 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> [356.638988] 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> [356.639454] 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> [356.639831] 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> [356.640228] 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> [356.640607] 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> [356.641015] 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> [356.643493] 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> [356.644101] 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> [356.644610] 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> [356.644993] 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> [356.645399] 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> [356.645781] 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> [356.646464] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in avi infoframe

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [356.650894] 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> [356.651363] 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> [356.651769] 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> [356.652145] 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> [356.654212] 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> [356.654719] 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> [356.655095] 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> [356.655515] 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> [356.655992] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:121:pipe B] min cdclk: 0 kHz -> 192000 kHz

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [356.664370] 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> [356.664748] 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> [356.665124] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

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

<7> [356.665935] 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> [356.668269] 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> [356.668775] 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> [356.669155] 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> [356.669572] 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> [356.669954] 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> [356.670369] 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> [356.670747] 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> [356.671128] 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> [356.672741] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0

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

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

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

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

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

<7> [356.675721] 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> [356.676102] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

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

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

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

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

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

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

<7> [356.679051] 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> [356.679495] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0

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

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

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

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

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

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

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

<7> [356.686988] 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> [356.687481] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B]

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

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

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

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

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

<7> [356.710370] 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> [356.723735] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10

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

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

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

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

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

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

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

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