igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a1 on shard-tglu@IGT

Detail	Value
Duration	1.30 seconds
Hostname	shard-tglu-8
Igt-Version	IGT-Version: 2.3-g1072e4f2e (x86_64) (Linux: 6.19.0-rc1-CI_DRM_17698-g605176fe40c8+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A1 1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1889 run_test() #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045() #4 ../tests/kms_flip.c:2045 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-HDMI-A1: FAIL (1.298s)
Err	Starting dynamic subtest: B-HDMI-A1 (kms_flip:2113) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2113) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-HDMI-A1 failed. ** DEBUG (kms_flip:2113) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 (kms_flip:2113) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 (kms_flip:2113) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 90.222115 current_received_ts = 90.221687 current_seq = 465 count = 0 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 12us (kms_flip:2113) DEBUG: name = flip last_ts = 90.222115 last_received_ts = 90.221687 last_seq = 465 current_ts = 90.230453 current_received_ts = 90.230080 current_seq = 466 count = 1 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 11us (kms_flip:2113) DEBUG: name = flip last_ts = 90.230453 last_received_ts = 90.230080 last_seq = 466 current_ts = 90.238792 current_received_ts = 90.238380 current_seq = 467 count = 2 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 26us (kms_flip:2113) DEBUG: name = flip last_ts = 90.238792 last_received_ts = 90.238380 last_seq = 467 current_ts = 90.247124 current_received_ts = 90.246719 current_seq = 468 count = 3 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 22us (kms_flip:2113) DEBUG: name = flip last_ts = 90.247124 last_received_ts = 90.246719 last_seq = 468 current_ts = 90.255463 current_received_ts = 90.255173 current_seq = 469 count = 4 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 16us (kms_flip:2113) DEBUG: name = flip last_ts = 90.255463 last_received_ts = 90.255173 last_seq = 469 current_ts = 90.263794 current_received_ts = 90.263527 current_seq = 470 count = 5 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 29us (kms_flip:2113) DEBUG: name = flip last_ts = 90.263794 last_received_ts = 90.263527 last_seq = 470 current_ts = 90.272125 current_received_ts = 90.271881 current_seq = 471 count = 6 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 39us (kms_flip:2113) DEBUG: name = flip last_ts = 90.272125 last_received_ts = 90.271881 last_seq = 471 current_ts = 90.280457 current_received_ts = 90.280205 current_seq = 472 count = 7 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 90.280457 last_received_ts = 90.280205 last_seq = 472 current_ts = 90.288795 current_received_ts = 90.288460 current_seq = 473 count = 8 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 25us (kms_flip:2113) DEBUG: name = flip last_ts = 90.288795 last_received_ts = 90.288460 last_seq = 473 current_ts = 90.297134 current_received_ts = 90.296799 current_seq = 474 count = 9 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 26us (kms_flip:2113) DEBUG: name = flip last_ts = 90.297134 last_received_ts = 90.296799 last_seq = 474 current_ts = 90.305466 current_received_ts = 90.305161 current_seq = 475 count = 10 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 90.305466 last_received_ts = 90.305161 last_seq = 475 current_ts = 90.313805 current_received_ts = 90.313461 current_seq = 476 count = 11 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 90.313805 last_received_ts = 90.313461 last_seq = 476 current_ts = 90.322136 current_received_ts = 90.321892 current_seq = 477 count = 12 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 90.322136 last_received_ts = 90.321892 last_seq = 477 current_ts = 90.330475 current_received_ts = 90.330193 current_seq = 478 count = 13 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 34us (kms_flip:2113) DEBUG: name = flip last_ts = 90.330475 last_received_ts = 90.330193 last_seq = 478 current_ts = 90.338806 current_received_ts = 90.338470 current_seq = 479 count = 14 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.338806 last_received_ts = 90.338470 last_seq = 479 current_ts = 90.347137 current_received_ts = 90.346954 current_seq = 480 count = 15 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 54us (kms_flip:2113) DEBUG: name = flip last_ts = 90.347137 last_received_ts = 90.346954 last_seq = 480 current_ts = 90.355476 current_received_ts = 90.355240 current_seq = 481 count = 16 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 36us (kms_flip:2113) DEBUG: name = flip last_ts = 90.355476 last_received_ts = 90.355240 last_seq = 481 current_ts = 90.363808 current_received_ts = 90.363503 current_seq = 482 count = 17 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 29us (kms_flip:2113) DEBUG: name = flip last_ts = 90.363808 last_received_ts = 90.363503 last_seq = 482 current_ts = 90.372147 current_received_ts = 90.371811 current_seq = 483 count = 18 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 30us (kms_flip:2113) DEBUG: name = flip last_ts = 90.372147 last_received_ts = 90.371811 last_seq = 483 current_ts = 90.380478 current_received_ts = 90.380150 current_seq = 484 count = 19 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 30us (kms_flip:2113) DEBUG: name = flip last_ts = 90.380478 last_received_ts = 90.380150 last_seq = 484 current_ts = 90.388817 current_received_ts = 90.388588 current_seq = 485 count = 20 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 36us (kms_flip:2113) DEBUG: name = flip last_ts = 90.388817 last_received_ts = 90.388588 last_seq = 485 current_ts = 90.397148 current_received_ts = 90.396973 current_seq = 486 count = 21 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 63us (kms_flip:2113) DEBUG: name = flip last_ts = 90.397148 last_received_ts = 90.396973 last_seq = 486 current_ts = 90.405487 current_received_ts = 90.405251 current_seq = 487 count = 22 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 29us (kms_flip:2113) DEBUG: name = flip last_ts = 90.405487 last_received_ts = 90.405251 last_seq = 487 current_ts = 90.413818 current_received_ts = 90.413612 current_seq = 488 count = 23 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 34us (kms_flip:2113) DEBUG: name = flip last_ts = 90.413818 last_received_ts = 90.413612 last_seq = 488 current_ts = 90.422150 current_received_ts = 90.421936 current_seq = 489 count = 24 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 90.422150 last_received_ts = 90.421936 last_seq = 489 current_ts = 90.430489 current_received_ts = 90.430237 current_seq = 490 count = 25 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.430489 last_received_ts = 90.430237 last_seq = 490 current_ts = 90.438820 current_received_ts = 90.438522 current_seq = 491 count = 26 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 26us (kms_flip:2113) DEBUG: name = flip last_ts = 90.438820 last_received_ts = 90.438522 last_seq = 491 current_ts = 90.447159 current_received_ts = 90.446854 current_seq = 492 count = 27 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.447159 last_received_ts = 90.446854 last_seq = 492 current_ts = 90.455490 current_received_ts = 90.455162 current_seq = 493 count = 28 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 90.455490 last_received_ts = 90.455162 last_seq = 493 current_ts = 90.463829 current_received_ts = 90.463554 current_seq = 494 count = 29 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 23us (kms_flip:2113) DEBUG: name = flip last_ts = 90.463829 last_received_ts = 90.463554 last_seq = 494 current_ts = 90.472160 current_received_ts = 90.471863 current_seq = 495 count = 30 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 26us (kms_flip:2113) DEBUG: name = flip last_ts = 90.472160 last_received_ts = 90.471863 last_seq = 495 current_ts = 90.480492 current_received_ts = 90.480263 current_seq = 496 count = 31 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.480492 last_received_ts = 90.480263 last_seq = 496 current_ts = 90.488831 current_received_ts = 90.488533 current_seq = 497 count = 32 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.488831 last_received_ts = 90.488533 last_seq = 497 current_ts = 90.497162 current_received_ts = 90.496872 current_seq = 498 count = 33 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 90.497162 last_received_ts = 90.496872 last_seq = 498 current_ts = 90.505493 current_received_ts = 90.505280 current_seq = 499 count = 34 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.505493 last_received_ts = 90.505280 last_seq = 499 current_ts = 90.513832 current_received_ts = 90.513596 current_seq = 500 count = 35 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 34us (kms_flip:2113) DEBUG: name = flip last_ts = 90.513832 last_received_ts = 90.513596 last_seq = 500 current_ts = 90.522163 current_received_ts = 90.521988 current_seq = 501 count = 36 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 35us (kms_flip:2113) DEBUG: name = flip last_ts = 90.522163 last_received_ts = 90.521988 last_seq = 501 current_ts = 90.530502 current_received_ts = 90.530266 current_seq = 502 count = 37 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 36us (kms_flip:2113) DEBUG: name = flip last_ts = 90.530502 last_received_ts = 90.530266 last_seq = 502 current_ts = 90.538834 current_received_ts = 90.538551 current_seq = 503 count = 38 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 29us (kms_flip:2113) DEBUG: name = flip last_ts = 90.538834 last_received_ts = 90.538551 last_seq = 503 current_ts = 90.547173 current_received_ts = 90.547043 current_seq = 504 count = 39 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 34us (kms_flip:2113) DEBUG: name = flip last_ts = 90.547173 last_received_ts = 90.547043 last_seq = 504 current_ts = 90.555504 current_received_ts = 90.555222 current_seq = 505 count = 40 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.555504 last_received_ts = 90.555222 last_seq = 505 current_ts = 90.563835 current_received_ts = 90.563622 current_seq = 506 count = 41 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 26us (kms_flip:2113) DEBUG: name = flip last_ts = 90.563835 last_received_ts = 90.563622 last_seq = 506 current_ts = 90.572166 current_received_ts = 90.571907 current_seq = 507 count = 42 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 29us (kms_flip:2113) DEBUG: name = flip last_ts = 90.572166 last_received_ts = 90.571907 last_seq = 507 current_ts = 90.580513 current_received_ts = 90.580292 current_seq = 508 count = 43 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 38us (kms_flip:2113) DEBUG: name = flip last_ts = 90.580513 last_received_ts = 90.580292 last_seq = 508 current_ts = 90.588844 current_received_ts = 90.588638 current_seq = 509 count = 44 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 31us (kms_flip:2113) DEBUG: name = flip last_ts = 90.588844 last_received_ts = 90.588638 last_seq = 509 current_ts = 90.597176 current_received_ts = 90.596992 current_seq = 510 count = 45 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 35us (kms_flip:2113) DEBUG: name = flip last_ts = 90.597176 last_received_ts = 90.596992 last_seq = 510 current_ts = 90.605515 current_received_ts = 90.605270 current_seq = 511 count = 46 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 26us (kms_flip:2113) DEBUG: name = flip last_ts = 90.605515 last_received_ts = 90.605270 last_seq = 511 current_ts = 90.613846 current_received_ts = 90.613579 current_seq = 512 count = 47 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 37us (kms_flip:2113) DEBUG: name = flip last_ts = 90.613846 last_received_ts = 90.613579 last_seq = 512 current_ts = 90.622177 current_received_ts = 90.621880 current_seq = 513 count = 48 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 90.622177 last_received_ts = 90.621880 last_seq = 513 current_ts = 90.630516 current_received_ts = 90.630264 current_seq = 514 count = 49 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.630516 last_received_ts = 90.630264 last_seq = 514 current_ts = 90.638847 current_received_ts = 90.638596 current_seq = 515 count = 50 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 34us (kms_flip:2113) DEBUG: name = flip last_ts = 90.638847 last_received_ts = 90.638596 last_seq = 515 current_ts = 90.647186 current_received_ts = 90.647049 current_seq = 516 count = 51 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 36us (kms_flip:2113) DEBUG: name = flip last_ts = 90.647186 last_received_ts = 90.647049 last_seq = 516 current_ts = 90.655518 current_received_ts = 90.655235 current_seq = 517 count = 52 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 90.655518 last_received_ts = 90.655235 last_seq = 517 current_ts = 90.663849 current_received_ts = 90.663635 current_seq = 518 count = 53 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 32us (kms_flip:2113) DEBUG: name = flip last_ts = 90.663849 last_received_ts = 90.663635 last_seq = 518 current_ts = 90.672188 current_received_ts = 90.672035 current_seq = 519 count = 54 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 32us (kms_flip:2113) DEBUG: name = flip last_ts = 90.672188 last_received_ts = 90.672035 last_seq = 519 current_ts = 90.680527 current_received_ts = 90.680237 current_seq = 520 count = 55 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 90.680527 last_received_ts = 90.680237 last_seq = 520 current_ts = 90.688858 current_received_ts = 90.688606 current_seq = 521 count = 56 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 35us (kms_flip:2113) DEBUG: name = flip last_ts = 90.688858 last_received_ts = 90.688606 last_seq = 521 current_ts = 90.697189 current_received_ts = 90.696976 current_seq = 522 count = 57 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 43us (kms_flip:2113) DEBUG: name = flip last_ts = 90.697189 last_received_ts = 90.696976 last_seq = 522 current_ts = 90.705528 current_received_ts = 90.705307 current_seq = 523 count = 58 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 90.705528 last_received_ts = 90.705307 last_seq = 523 current_ts = 90.713860 current_received_ts = 90.713623 current_seq = 524 count = 59 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 31us (kms_flip:2113) DEBUG: name = flip last_ts = 90.713860 last_received_ts = 90.713623 last_seq = 524 current_ts = 90.722191 current_received_ts = 90.722054 current_seq = 525 count = 60 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 34us (kms_flip:2113) DEBUG: name = flip last_ts = 90.722191 last_received_ts = 90.722054 last_seq = 525 current_ts = 90.730530 current_received_ts = 90.730225 current_seq = 526 count = 61 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 90.730530 last_received_ts = 90.730225 last_seq = 526 current_ts = 90.738869 current_received_ts = 90.738609 current_seq = 527 count = 62 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 90.738869 last_received_ts = 90.738609 last_seq = 527 current_ts = 90.747200 current_received_ts = 90.747086 current_seq = 528 count = 63 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 90.747200 last_received_ts = 90.747086 last_seq = 528 current_ts = 90.755531 current_received_ts = 90.755341 current_seq = 529 count = 64 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 29us (kms_flip:2113) DEBUG: name = flip last_ts = 90.755531 last_received_ts = 90.755341 last_seq = 529 current_ts = 90.763863 current_received_ts = 90.763573 current_seq = 530 count = 65 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 90.763863 last_received_ts = 90.763573 last_seq = 530 current_ts = 90.772202 current_received_ts = 90.771996 current_seq = 531 count = 66 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 90.772202 last_received_ts = 90.771996 last_seq = 531 current_ts = 90.780540 current_received_ts = 90.780304 current_seq = 532 count = 67 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 36us (kms_flip:2113) DEBUG: name = flip last_ts = 90.780540 last_received_ts = 90.780304 last_seq = 532 current_ts = 90.788872 current_received_ts = 90.788620 current_seq = 533 count = 68 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 90.788872 last_received_ts = 90.788620 last_seq = 533 current_ts = 90.797203 current_received_ts = 90.797073 current_seq = 534 count = 69 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 29us (kms_flip:2113) DEBUG: name = flip last_ts = 90.797203 last_received_ts = 90.797073 last_seq = 534 current_ts = 90.805542 current_received_ts = 90.805313 current_seq = 535 count = 70 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 90.805542 last_received_ts = 90.805313 last_seq = 535 current_ts = 90.813873 current_received_ts = 90.813599 current_seq = 536 count = 71 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.813873 last_received_ts = 90.813599 last_seq = 536 current_ts = 90.822212 current_received_ts = 90.822067 current_seq = 537 count = 72 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 90.822212 last_received_ts = 90.822067 last_seq = 537 current_ts = 90.830544 current_received_ts = 90.830299 current_seq = 538 count = 73 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 35us (kms_flip:2113) DEBUG: name = flip last_ts = 90.830544 last_received_ts = 90.830299 last_seq = 538 current_ts = 90.838882 current_received_ts = 90.838669 current_seq = 539 count = 74 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 32us (kms_flip:2113) DEBUG: name = flip last_ts = 90.838882 last_received_ts = 90.838669 last_seq = 539 current_ts = 90.847221 current_received_ts = 90.847038 current_seq = 540 count = 75 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 34us (kms_flip:2113) DEBUG: name = flip last_ts = 90.847221 last_received_ts = 90.847038 last_seq = 540 current_ts = 90.855545 current_received_ts = 90.855339 current_seq = 541 count = 76 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 90.855545 last_received_ts = 90.855339 last_seq = 541 current_ts = 90.863884 current_received_ts = 90.863655 current_seq = 542 count = 77 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 25us (kms_flip:2113) DEBUG: name = flip last_ts = 90.863884 last_received_ts = 90.863655 last_seq = 542 current_ts = 90.872215 current_received_ts = 90.871941 current_seq = 543 count = 78 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.872215 last_received_ts = 90.871941 last_seq = 543 current_ts = 90.880554 current_received_ts = 90.880318 current_seq = 544 count = 79 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 31us (kms_flip:2113) DEBUG: name = flip last_ts = 90.880554 last_received_ts = 90.880318 last_seq = 544 current_ts = 90.888893 current_received_ts = 90.888641 current_seq = 545 count = 80 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 30us (kms_flip:2113) DEBUG: name = flip last_ts = 90.888893 last_received_ts = 90.888641 last_seq = 545 current_ts = 90.897224 current_received_ts = 90.896919 current_seq = 546 count = 81 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 26us (kms_flip:2113) DEBUG: name = flip last_ts = 90.897224 last_received_ts = 90.896919 last_seq = 546 current_ts = 90.905556 current_received_ts = 90.905289 current_seq = 547 count = 82 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 32us (kms_flip:2113) DEBUG: name = flip last_ts = 90.905556 last_received_ts = 90.905289 last_seq = 547 current_ts = 90.913895 current_received_ts = 90.913719 current_seq = 548 count = 83 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 32us (kms_flip:2113) DEBUG: name = flip last_ts = 90.913895 last_received_ts = 90.913719 last_seq = 548 current_ts = 90.922234 current_received_ts = 90.921928 current_seq = 549 count = 84 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 26us (kms_flip:2113) DEBUG: name = flip last_ts = 90.922234 last_received_ts = 90.921928 last_seq = 549 current_ts = 90.930557 current_received_ts = 90.930283 current_seq = 550 count = 85 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 26us (kms_flip:2113) DEBUG: name = flip last_ts = 90.930557 last_received_ts = 90.930283 last_seq = 550 current_ts = 90.938896 current_received_ts = 90.938660 current_seq = 551 count = 86 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 31us (kms_flip:2113) DEBUG: name = flip last_ts = 90.938896 last_received_ts = 90.938660 last_seq = 551 current_ts = 90.947235 current_received_ts = 90.947083 current_seq = 552 count = 87 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.947235 last_received_ts = 90.947083 last_seq = 552 current_ts = 90.955566 current_received_ts = 90.955261 current_seq = 553 count = 88 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 90.955566 last_received_ts = 90.955261 last_seq = 553 current_ts = 90.963898 current_received_ts = 90.963684 current_seq = 554 count = 89 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 90.963898 last_received_ts = 90.963684 last_seq = 554 current_ts = 90.972237 current_received_ts = 90.972115 current_seq = 555 count = 90 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 26us (kms_flip:2113) DEBUG: name = flip last_ts = 90.972237 last_received_ts = 90.972115 last_seq = 555 current_ts = 90.980568 current_received_ts = 90.980293 current_seq = 556 count = 91 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 29us (kms_flip:2113) DEBUG: name = flip last_ts = 90.980568 last_received_ts = 90.980293 last_seq = 556 current_ts = 90.988907 current_received_ts = 90.988670 current_seq = 557 count = 92 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 31us (kms_flip:2113) DEBUG: name = flip last_ts = 90.988907 last_received_ts = 90.988670 last_seq = 557 current_ts = 90.997238 current_received_ts = 90.997093 current_seq = 558 count = 93 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 32us (kms_flip:2113) DEBUG: name = flip last_ts = 90.997238 last_received_ts = 90.997093 last_seq = 558 current_ts = 91.005577 current_received_ts = 91.005325 current_seq = 559 count = 94 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 36us (kms_flip:2113) DEBUG: name = flip last_ts = 91.005577 last_received_ts = 91.005325 last_seq = 559 current_ts = 91.013908 current_received_ts = 91.013702 current_seq = 560 count = 95 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 29us (kms_flip:2113) DEBUG: name = flip last_ts = 91.013908 last_received_ts = 91.013702 last_seq = 560 current_ts = 91.022240 current_received_ts = 91.021965 current_seq = 561 count = 96 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 56us (kms_flip:2113) DEBUG: name = flip last_ts = 91.022240 last_received_ts = 91.021965 last_seq = 561 current_ts = 91.030579 current_received_ts = 91.030350 current_seq = 562 count = 97 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 35us (kms_flip:2113) DEBUG: name = flip last_ts = 91.030579 last_received_ts = 91.030350 last_seq = 562 current_ts = 91.038910 current_received_ts = 91.038689 current_seq = 563 count = 98 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 91.038910 last_received_ts = 91.038689 last_seq = 563 current_ts = 91.047241 current_received_ts = 91.046967 current_seq = 564 count = 99 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 49us (kms_flip:2113) DEBUG: name = flip last_ts = 91.047241 last_received_ts = 91.046967 last_seq = 564 current_ts = 91.055580 current_received_ts = 91.055275 current_seq = 565 count = 100 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 28us (kms_flip:2113) DEBUG: name = flip last_ts = 91.055580 last_received_ts = 91.055275 last_seq = 565 current_ts = 91.063911 current_received_ts = 91.063705 current_seq = 566 count = 101 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 34us (kms_flip:2113) DEBUG: name = flip last_ts = 91.063911 last_received_ts = 91.063705 last_seq = 566 current_ts = 91.072250 current_received_ts = 91.072136 current_seq = 567 count = 102 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 91.072250 last_received_ts = 91.072136 last_seq = 567 current_ts = 91.080582 current_received_ts = 91.080338 current_seq = 568 count = 103 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 30us (kms_flip:2113) DEBUG: name = flip last_ts = 91.080582 last_received_ts = 91.080338 last_seq = 568 current_ts = 91.088921 current_received_ts = 91.088699 current_seq = 569 count = 104 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 34us (kms_flip:2113) DEBUG: name = flip last_ts = 91.088921 last_received_ts = 91.088699 last_seq = 569 current_ts = 91.097252 current_received_ts = 91.097046 current_seq = 570 count = 105 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 37us (kms_flip:2113) DEBUG: name = flip last_ts = 91.097252 last_received_ts = 91.097046 last_seq = 570 current_ts = 91.105591 current_received_ts = 91.105301 current_seq = 571 count = 106 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 38us (kms_flip:2113) DEBUG: name = flip last_ts = 91.105591 last_received_ts = 91.105301 last_seq = 571 current_ts = 91.113922 current_received_ts = 91.113655 current_seq = 572 count = 107 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 31us (kms_flip:2113) DEBUG: name = flip last_ts = 91.113922 last_received_ts = 91.113655 last_seq = 572 current_ts = 91.122261 current_received_ts = 91.122108 current_seq = 573 count = 108 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 91.122261 last_received_ts = 91.122108 last_seq = 573 current_ts = 91.130592 current_received_ts = 91.130325 current_seq = 574 count = 109 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 29us (kms_flip:2113) DEBUG: name = flip last_ts = 91.130592 last_received_ts = 91.130325 last_seq = 574 current_ts = 91.138924 current_received_ts = 91.138664 current_seq = 575 count = 110 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 30us (kms_flip:2113) DEBUG: name = flip last_ts = 91.138924 last_received_ts = 91.138664 last_seq = 575 current_ts = 91.147263 current_received_ts = 91.147102 current_seq = 576 count = 111 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 32us (kms_flip:2113) DEBUG: name = flip last_ts = 91.147263 last_received_ts = 91.147102 last_seq = 576 current_ts = 91.155594 current_received_ts = 91.155304 current_seq = 577 count = 112 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 91.155594 last_received_ts = 91.155304 last_seq = 577 current_ts = 91.163933 current_received_ts = 91.163651 current_seq = 578 count = 113 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 26us (kms_flip:2113) DEBUG: name = flip last_ts = 91.163933 last_received_ts = 91.163651 last_seq = 578 current_ts = 91.172264 current_received_ts = 91.172089 current_seq = 579 count = 114 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 91.172264 last_received_ts = 91.172089 last_seq = 579 current_ts = 91.180603 current_received_ts = 91.180351 current_seq = 580 count = 115 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 91.180603 last_received_ts = 91.180351 last_seq = 580 current_ts = 91.188934 current_received_ts = 91.188713 current_seq = 581 count = 116 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 33us (kms_flip:2113) DEBUG: name = flip last_ts = 91.188934 last_received_ts = 91.188713 last_seq = 581 current_ts = 91.197266 current_received_ts = 91.196968 current_seq = 582 count = 117 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 43us (kms_flip:2113) DEBUG: name = flip last_ts = 91.197266 last_received_ts = 91.196968 last_seq = 582 current_ts = 91.205605 current_received_ts = 91.205292 current_seq = 583 count = 118 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 27us (kms_flip:2113) DEBUG: name = flip last_ts = 91.205605 last_received_ts = 91.205292 last_seq = 583 current_ts = 91.213936 current_received_ts = 91.213715 current_seq = 584 count = 119 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 32us (kms_flip:2113) DEBUG: name = flip last_ts = 91.213936 last_received_ts = 91.213715 last_seq = 584 current_ts = 91.222275 current_received_ts = 91.221962 current_seq = 585 count = 120 seq_step = 1 (kms_flip:2113) DEBUG: Vblank took 1082us (kms_flip:2113) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2113) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2113) igt_core-INFO: Stack trace: (kms_flip:2113) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2113) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:2113) igt_core-INFO: #2 ../tests/kms_flip.c:1889 run_test() (kms_flip:2113) igt_core-INFO: #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045() (kms_flip:2113) igt_core-INFO: #4 ../tests/kms_flip.c:2045 main() (kms_flip:2113) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2113) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2113) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A1: FAIL (1.298s)
Dmesg	<6> [90.082942] [IGT] kms_flip: starting dynamic subtest B-HDMI-A1 <7> [90.083794] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:635] <7> [90.084033] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:636] <7> [90.132407] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:169:pipe A] <7> [90.132588] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [90.132912] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [90.133288] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [90.133826] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [90.134391] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [90.134916] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [90.135489] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [90.135922] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2080, found 0) <7> [90.136269] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [90.136571] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2080, found 0) <7> [90.136990] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1968, found 0) <7> [90.137463] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2000, found 0) <7> [90.137890] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [90.138342] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [90.138634] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [90.138916] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [90.139231] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1144, found 0) <7> [90.139563] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1144, found 0) <7> [90.139894] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [90.140244] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2080, found 0) <7> [90.140526] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [90.140744] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2080, found 0) <7> [90.140962] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1968, found 0) <7> [90.141267] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2000, found 0) <7> [90.141595] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [90.141925] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [90.142202] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [90.142434] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [90.142603] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1144, found 0) <7> [90.142766] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1144, found 0) <7> [90.142931] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [90.143173] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [90.143418] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [90.143665] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [90.143907] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in has_infoframe (expected yes, found no) <7> [90.144135] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [90.144299] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 285500, found 0) <7> [90.144465] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 285500, found 0) <7> [90.144635] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in port_clock (expected 285500, found 0) <7> [90.144878] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [90.145135] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in avi infoframe <7> [90.145373] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [90.145601] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [90.145605] i915 0000:00:02.0: colorspace: RGB <7> [90.145608] i915 0000:00:02.0: scan mode: Underscan <7> [90.145610] i915 0000:00:02.0: colorimetry: No Data <7> [90.145613] i915 0000:00:02.0: picture aspect: No Data <7> [90.145615] i915 0000:00:02.0: active aspect: Same as Picture <7> [90.145618] i915 0000:00:02.0: itc: No Data <7> [90.145620] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [90.145623] i915 0000:00:02.0: quantization range: Full <7> [90.145625] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [90.145628] i915 0000:00:02.0: video code: 0 <7> [90.145631] i915 0000:00:02.0: ycc quantization range: Full <7> [90.145633] i915 0000:00:02.0: hdmi content type: Graphics <7> [90.145636] i915 0000:00:02.0: pixel repeat: 0 <7> [90.145639] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [90.145642] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [90.145827] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in spd infoframe <7> [90.145985] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [90.146165] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [90.146167] i915 0000:00:02.0: vendor: Intel <7> [90.146168] i915 0000:00:02.0: product: Integrated gfx <7> [90.146170] i915 0000:00:02.0: source device information: PC General (0x9) <7> [90.146172] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [90.146353] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:169:pipe A] fastset requirement not met in hdmi infoframe <7> [90.146590] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [90.146822] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [90.146825] i915 0000:00:02.0: empty frame <7> [90.146828] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [90.147072] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:169:pipe A] fastset requirement not met, forcing full modeset <7> [90.147311] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:169:pipe A] releasing DPLL 0 <7> [90.147587] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no <7> [90.147750] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:169:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [90.147936] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:163:cursor A] ddb (1993 - 2048) -> ( 0 - 0), size 55 -> 0 <7> [90.148140] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:169:pipe A] min cdclk: 192000 kHz -> 0 kHz <7> [90.148409] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [90.148648] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz <7> [90.148883] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [90.149131] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:169:pipe A] enable: no [modeset] <7> [90.149319] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:33:plane 1A] fb: [NOFB], visible: no <7> [90.149477] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 2A] fb: [NOFB], visible: no <7> [90.149633] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:93:plane 3A] fb: [NOFB], visible: no <7> [90.149794] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:123:plane 4A] fb: [NOFB], visible: no <7> [90.150028] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:133:plane 5A] fb: [NOFB], visible: no <7> [90.150297] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:143:plane 6A] fb: [NOFB], visible: no <7> [90.150533] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:153:plane 7A] fb: [NOFB], visible: no <7> [90.150760] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:163:cursor A] fb: [NOFB], visible: no <7> [90.150992] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:586:HDMI-A-1][ENCODER:585:DDI B/PHY B] Disable audio codec on [CRTC:169:pipe A] <7> [90.162962] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [90.165066] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:586:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10 <7> [90.165728] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [90.165876] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [90.166462] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [90.166690] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:586:HDMI-A-1] Failed to read TMDS config: -6 <7> [90.166715] i915 0000:00:02.0: [drm:intel_ddi_disable [i915]] [CONNECTOR:586:HDMI-A-1] Failed to reset sink scrambling/TMDS bit clock ratio <7> [90.166971] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [90.172078] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [90.172274] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:169:pipe A] <7> [90.172459] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0 <7> [90.172632] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 172800 kHz, VCO 345600 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [90.172913] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:585:DDI B/PHY B] <7> [90.173118] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:595:DDI TC1/PHY TC1] <7> [90.173355] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DP-MST A] <7> [90.173586] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:598:DP-MST B] <7> [90.173818] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST C] <7> [90.174043] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST D] <7> [90.174259] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:605:DDI TC2/PHY TC2] <7> [90.174415] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DP-MST A] <7> [90.174568] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:608:DP-MST B] <7> [90.174721] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST C] <7> [90.174880] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST D] <7> [90.175088] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:614:DDI TC3/PHY TC3] <7> [90.175321] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DP-MST A] <7> [90.175549] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:617:DP-MST B] <7> [90.175774] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST C] <7> [90.175995] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST D] <7> [90.176182] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:623:DDI TC4/PHY TC4] <7> [90.176340] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DP-MST A] <7> [90.176494] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:626:DP-MST B] <7> [90.176680] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST C] <7> [90.176908] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST D] <7> [90.177155] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:586:HDMI-A-1] <7> [90.177635] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [90.177852] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_3 <7> [90.178033] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [90.178261] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:169:pipe A] <7> [90.179184] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:307:pipe B] <7> [90.179365] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:445:pipe C] <7> [90.179498] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:583:pipe D] <7> [90.179635] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:307:pipe B] <7> [90.179665] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:586:HDMI-A-1] <7> [90.179729] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:586:HDMI-A-1] Limiting display bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36) <7> [90.179948] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [90.180222] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:307:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [90.180464] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:585:DDI B/PHY B] [CRTC:307:pipe B] <7> [90.180688] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [90.180905] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [90.181082] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [90.181243] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [90.181400] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [90.181608] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [90.181842] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [90.182085] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2080) <7> [90.182316] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [90.182515] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2080) <7> [90.182670] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1968) <7> [90.182826] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2000) <7> [90.182982] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [90.183203] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [90.183437] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [90.183670] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [90.183902] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1144) <7> [90.184141] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1144) <7> [90.184310] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [90.184466] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2080) <7> [90.184621] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [90.184776] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2080) <7> [90.184932] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1968) <7> [90.185118] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2000) <7> [90.185295] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [90.185451] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [90.185605] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [90.185760] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [90.185915] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1144) <7> [90.186080] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1144) <7> [90.186311] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [90.186544] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [90.186781] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [90.187014] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [90.187258] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in has_infoframe (expected no, found yes) <7> [90.187430] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [90.187589] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 285500) <7> [90.187746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 285500) <7> [90.187904] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in port_clock (expected 0, found 285500) <7> [90.188185] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [90.188345] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in avi infoframe <7> [90.188530] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [90.188751] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [90.188979] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [90.188982] i915 0000:00:02.0: colorspace: RGB <7> [90.188985] i915 0000:00:02.0: scan mode: Underscan <7> [90.188988] i915 0000:00:02.0: colorimetry: No Data <7> [90.188991] i915 0000:00:02.0: picture aspect: No Data <7> [90.188993] i915 0000:00:02.0: active aspect: Same as Picture <7> [90.188996] i915 0000:00:02.0: itc: No Data <7> [90.188999] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [90.189001] i915 0000:00:02.0: quantization range: Full <7> [90.189004] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [90.189007] i915 0000:00:02.0: video code: 0 <7> [90.189009] i915 0000:00:02.0: ycc quantization range: Full <7> [90.189012] i915 0000:00:02.0: hdmi content type: Graphics <7> [90.189015] i915 0000:00:02.0: pixel repeat: 0 <7> [90.189018] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [90.189021] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in spd infoframe <7> [90.189284] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [90.189511] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [90.189739] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [90.189743] i915 0000:00:02.0: vendor: Intel <7> [90.189746] i915 0000:00:02.0: product: Integrated gfx <7> [90.189748] i915 0000:00:02.0: source device information: PC General (0x9) <7> [90.189751] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:307:pipe B] fastset requirement not met in hdmi infoframe <7> [90.189985] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [90.190221] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [90.190435] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [90.190438] i915 0000:00:02.0: empty frame <7> [90.190442] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:307:pipe B] fastset requirement not met, forcing full modeset <7> [90.190728] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no <7> [90.190910] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:307:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2 <7> [90.191148] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:171:plane 1B] ddb ( 0 - 0) -> ( 0 - 1993), size 0 -> 1993 <7> [90.191303] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:301:cursor B] ddb ( 0 - 0) -> (1993 - 2048), size 0 -> 55 <7> [90.191470] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:171: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> [90.191643] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:171:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 8, 8, 8, 8, 11, 16, 16, 0, 0, 0 <7> [90.191798] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:171:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 129, 129, 129, 129, 177, 257, 257, 30, 0, 0 <7> [90.191950] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:171:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 143, 143, 143, 143, 196, 284, 284, 31, 0, 0 <7> [90.192174] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:307:pipe B] data rate 1142000 num active planes 1 <7> [90.192338] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 14993 required 1142 <7> [90.192503] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [90.192679] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:307:pipe B] min cdclk: 0 kHz -> 192000 kHz <7> [90.192880] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [90.193039] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [90.193300] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [90.193537] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:307:pipe B] allocated DPLL 0 <7> [90.193781] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:307:pipe B] reserving DPLL 0 <7> [90.194017] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:307:pipe B] enable: yes [modeset] <7> [90.194237] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [90.194408] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [90.194565] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [90.194721] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [90.194877] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [90.195071] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [90.195310] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [90.195548] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x0 <7> [90.195780] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [90.195784] i915 0000:00:02.0: colorspace: RGB <7> [90.195786] i915 0000:00:02.0: scan mode: Underscan <7> [90.195789] i915 0000:00:02.0: colorimetry: No Data <7> [90.195791] i915 0000:00:02.0: picture aspect: No Data <7> [90.195794] i915 0000:00:02.0: active aspect: Same as Picture <7> [90.195797] i915 0000:00:02.0: itc: No Data <7> [90.195799] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [90.195802] i915 0000:00:02.0: quantization range: Full <7> [90.195805] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [90.195807] i915 0000:00:02.0: video code: 0 <7> [90.195810] i915 0000:00:02.0: ycc quantization range: Full <7> [90.195812] i915 0000:00:02.0: hdmi content type: Graphics <7> [90.195815] i915 0000:00:02.0: pixel repeat: 0 <7> [90.195817] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [90.195821] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [90.195824] i915 0000:00:02.0: vendor: Intel <7> [90.195827] i915 0000:00:02.0: product: Integrated gfx <7> [90.195829] i915 0000:00:02.0: source device information: PC General (0x9) <7> [90.195832] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [90.195835] i915 0000:00:02.0: empty frame <7> [90.195837] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 0f 00 6d a2 00 7f 00 00 00 00 00 00 00 00 <7> [90.196086] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 0d 82 34 12 66 69 74 48 65 61 64 6c 65 73 73 47 <7> [90.196255] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 53 7f 7f 28 0f 7f 07 17 7f ff 3f 7f ff 47 7f ff <7> [90.196411] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 5f 7f 82 7f 7f 00 7f 7f 51 7f 7f 30 77 7f 03 00 <7> [90.196565] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [90.196718] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [90.196946] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1144, vmax: 1144, flipline: 1144, pipeline full: 61, guardband: 63 vsync start: 0, vsync end: 0 <7> [90.197199] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1081, vmax vblank: 1081, vmin vtotal: 1144, vmax vtotal: 1144 <7> [90.197430] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 <7> [90.197664] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 <7> [90.197891] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5 <7> [90.198084] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x40 0x5 <7> [90.198305] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5 <7> [90.198460] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 285500, pipe src: 1920x1080+0+0, pixel rate 285500, min cdclk 192000 <7> [90.198617] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [90.198847] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [90.199091] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [90.199327] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [90.199557] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1801be, cfgcr1: 0x488, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0 <7> [90.199728] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [90.199882] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [90.200036] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [90.200223] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.200451] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.200686] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.200916] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [90.201160] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [90.201365] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.201519] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.201672] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.201824] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [90.201984] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [90.202233] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:171:plane 1B] fb: [FB:635] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [90.202467] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [90.202697] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [90.202923] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:201:plane 2B] fb: [NOFB], visible: no <7> [90.203115] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:231:plane 3B] fb: [NOFB], visible: no <7> [90.203297] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:261:plane 4B] fb: [NOFB], visible: no <7> [90.203475] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:271:plane 5B] fb: [NOFB], visible: no <7> [90.203649] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:281:plane 6B] fb: [NOFB], visible: no <7> [90.203822] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:291:plane 7B] fb: [NOFB], visible: no <7> [90.203996] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:301:cursor B] fb: [NOFB], visible: no <7> [90.204829] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [90.205020] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_3 <7> [90.205265] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 192000 kHz, VCO 384000 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [90.205507] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:585:DDI B/PHY B] <7> [90.205668] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:595:DDI TC1/PHY TC1] <7> [90.205826] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DP-MST A] <7> [90.205982] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:598:DP-MST B] <7> [90.206162] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST C] <7> [90.206321] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST D] <7> [90.206479] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:605:DDI TC2/PHY TC2] <7> [90.206635] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DP-MST A] <7> [90.206791] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:608:DP-MST B] <7> [90.206946] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST C] <7> [90.207112] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST D] <7> [90.207264] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:614:DDI TC3/PHY TC3] <7> [90.207416] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DP-MST A] <7> [90.207570] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:617:DP-MST B] <7> [90.207722] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST C] <7> [90.207874] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST D] <7> [90.208024] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:623:DDI TC4/PHY TC4] <7> [90.208192] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DP-MST A] <7> [90.208342] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:626:DP-MST B] <7> [90.208495] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST C] <7> [90.208647] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST D] <7> [90.208918] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [90.209136] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:307:pipe B] <7> [90.209302] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0 <7> [90.209524] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B <7> [90.209760] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [90.210473] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:586:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10 <7> [90.211152] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [90.211321] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [90.211922] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [90.212091] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:586:HDMI-A-1] Failed to read TMDS config: -6 <7> [90.212112] i915 0000:00:02.0: [drm:intel_ddi_enable [i915]] [CONNECTOR:586:HDMI-A-1] Failed to configure sink scrambling/TMDS bit clock ratio <7> [90.218063] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x810 <7> [90.220746] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:586:HDMI-A-1][ENCODER:585:DDI B/PHY B] Enable audio codec on [CRTC:307:pipe B], 64 bytes ELD <7> [90.222631] azx_init_pci: snd_hda_intel 0000:00:1f.3: Clearing TCSEL <7> [90.222667] azx_init_pci: snd_hda_intel 0000:00:1f.3: SCH snoop: Enabled <7> [90.229068] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] HDMI audio pixel clock setting for 285500 not found, falling back to defaults <7> [90.229253] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000) <7> [90.229412] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <6> [90.229577] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 5 not expected <6> [90.229579] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 0 not expected <6> [90.229581] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 10 not expected <6> [90.229583] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 6 not expected <7> [90.229713] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:586:HDMI-A-1] <7> [90.229966] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:307:pipe B] <6> [91.381835] [IGT] kms_flip: finished subtest B-HDMI-A1, FAIL

Detail

Value

Duration

1.30 seconds

Hostname

shard-tglu-8

Igt-Version

IGT-Version: 2.3-g1072e4f2e (x86_64) (Linux: 6.19.0-rc1-CI_DRM_17698-g605176fe40c8+ x86_64)

Out

Starting dynamic subtest: B-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1889 run_test()
  #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045()
  #4 ../tests/kms_flip.c:2045 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A1: FAIL (1.298s)

Err

Starting dynamic subtest: B-HDMI-A1
(kms_flip:2113) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2113) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2113) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2113) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2113) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 90.222115
current_received_ts = 90.221687
current_seq = 465
count = 0
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 12us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.222115
last_received_ts = 90.221687
last_seq = 465
current_ts = 90.230453
current_received_ts = 90.230080
current_seq = 466
count = 1
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 11us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.230453
last_received_ts = 90.230080
last_seq = 466
current_ts = 90.238792
current_received_ts = 90.238380
current_seq = 467
count = 2
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 26us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.238792
last_received_ts = 90.238380
last_seq = 467
current_ts = 90.247124
current_received_ts = 90.246719
current_seq = 468
count = 3
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 22us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.247124
last_received_ts = 90.246719
last_seq = 468
current_ts = 90.255463
current_received_ts = 90.255173
current_seq = 469
count = 4
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 16us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.255463
last_received_ts = 90.255173
last_seq = 469
current_ts = 90.263794
current_received_ts = 90.263527
current_seq = 470
count = 5
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 29us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.263794
last_received_ts = 90.263527
last_seq = 470
current_ts = 90.272125
current_received_ts = 90.271881
current_seq = 471
count = 6
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 39us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.272125
last_received_ts = 90.271881
last_seq = 471
current_ts = 90.280457
current_received_ts = 90.280205
current_seq = 472
count = 7
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.280457
last_received_ts = 90.280205
last_seq = 472
current_ts = 90.288795
current_received_ts = 90.288460
current_seq = 473
count = 8
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 25us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.288795
last_received_ts = 90.288460
last_seq = 473
current_ts = 90.297134
current_received_ts = 90.296799
current_seq = 474
count = 9
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 26us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.297134
last_received_ts = 90.296799
last_seq = 474
current_ts = 90.305466
current_received_ts = 90.305161
current_seq = 475
count = 10
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.305466
last_received_ts = 90.305161
last_seq = 475
current_ts = 90.313805
current_received_ts = 90.313461
current_seq = 476
count = 11
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.313805
last_received_ts = 90.313461
last_seq = 476
current_ts = 90.322136
current_received_ts = 90.321892
current_seq = 477
count = 12
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.322136
last_received_ts = 90.321892
last_seq = 477
current_ts = 90.330475
current_received_ts = 90.330193
current_seq = 478
count = 13
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 34us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.330475
last_received_ts = 90.330193
last_seq = 478
current_ts = 90.338806
current_received_ts = 90.338470
current_seq = 479
count = 14
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.338806
last_received_ts = 90.338470
last_seq = 479
current_ts = 90.347137
current_received_ts = 90.346954
current_seq = 480
count = 15
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 54us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.347137
last_received_ts = 90.346954
last_seq = 480
current_ts = 90.355476
current_received_ts = 90.355240
current_seq = 481
count = 16
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 36us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.355476
last_received_ts = 90.355240
last_seq = 481
current_ts = 90.363808
current_received_ts = 90.363503
current_seq = 482
count = 17
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 29us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.363808
last_received_ts = 90.363503
last_seq = 482
current_ts = 90.372147
current_received_ts = 90.371811
current_seq = 483
count = 18
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 30us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.372147
last_received_ts = 90.371811
last_seq = 483
current_ts = 90.380478
current_received_ts = 90.380150
current_seq = 484
count = 19
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 30us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.380478
last_received_ts = 90.380150
last_seq = 484
current_ts = 90.388817
current_received_ts = 90.388588
current_seq = 485
count = 20
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 36us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.388817
last_received_ts = 90.388588
last_seq = 485
current_ts = 90.397148
current_received_ts = 90.396973
current_seq = 486
count = 21
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 63us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.397148
last_received_ts = 90.396973
last_seq = 486
current_ts = 90.405487
current_received_ts = 90.405251
current_seq = 487
count = 22
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 29us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.405487
last_received_ts = 90.405251
last_seq = 487
current_ts = 90.413818
current_received_ts = 90.413612
current_seq = 488
count = 23
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 34us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.413818
last_received_ts = 90.413612
last_seq = 488
current_ts = 90.422150
current_received_ts = 90.421936
current_seq = 489
count = 24
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.422150
last_received_ts = 90.421936
last_seq = 489
current_ts = 90.430489
current_received_ts = 90.430237
current_seq = 490
count = 25
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.430489
last_received_ts = 90.430237
last_seq = 490
current_ts = 90.438820
current_received_ts = 90.438522
current_seq = 491
count = 26
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 26us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.438820
last_received_ts = 90.438522
last_seq = 491
current_ts = 90.447159
current_received_ts = 90.446854
current_seq = 492
count = 27
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.447159
last_received_ts = 90.446854
last_seq = 492
current_ts = 90.455490
current_received_ts = 90.455162
current_seq = 493
count = 28
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.455490
last_received_ts = 90.455162
last_seq = 493
current_ts = 90.463829
current_received_ts = 90.463554
current_seq = 494
count = 29
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 23us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.463829
last_received_ts = 90.463554
last_seq = 494
current_ts = 90.472160
current_received_ts = 90.471863
current_seq = 495
count = 30
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 26us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.472160
last_received_ts = 90.471863
last_seq = 495
current_ts = 90.480492
current_received_ts = 90.480263
current_seq = 496
count = 31
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.480492
last_received_ts = 90.480263
last_seq = 496
current_ts = 90.488831
current_received_ts = 90.488533
current_seq = 497
count = 32
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.488831
last_received_ts = 90.488533
last_seq = 497
current_ts = 90.497162
current_received_ts = 90.496872
current_seq = 498
count = 33
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.497162
last_received_ts = 90.496872
last_seq = 498
current_ts = 90.505493
current_received_ts = 90.505280
current_seq = 499
count = 34
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.505493
last_received_ts = 90.505280
last_seq = 499
current_ts = 90.513832
current_received_ts = 90.513596
current_seq = 500
count = 35
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 34us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.513832
last_received_ts = 90.513596
last_seq = 500
current_ts = 90.522163
current_received_ts = 90.521988
current_seq = 501
count = 36
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 35us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.522163
last_received_ts = 90.521988
last_seq = 501
current_ts = 90.530502
current_received_ts = 90.530266
current_seq = 502
count = 37
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 36us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.530502
last_received_ts = 90.530266
last_seq = 502
current_ts = 90.538834
current_received_ts = 90.538551
current_seq = 503
count = 38
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 29us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.538834
last_received_ts = 90.538551
last_seq = 503
current_ts = 90.547173
current_received_ts = 90.547043
current_seq = 504
count = 39
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 34us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.547173
last_received_ts = 90.547043
last_seq = 504
current_ts = 90.555504
current_received_ts = 90.555222
current_seq = 505
count = 40
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.555504
last_received_ts = 90.555222
last_seq = 505
current_ts = 90.563835
current_received_ts = 90.563622
current_seq = 506
count = 41
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 26us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.563835
last_received_ts = 90.563622
last_seq = 506
current_ts = 90.572166
current_received_ts = 90.571907
current_seq = 507
count = 42
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 29us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.572166
last_received_ts = 90.571907
last_seq = 507
current_ts = 90.580513
current_received_ts = 90.580292
current_seq = 508
count = 43
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 38us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.580513
last_received_ts = 90.580292
last_seq = 508
current_ts = 90.588844
current_received_ts = 90.588638
current_seq = 509
count = 44
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 31us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.588844
last_received_ts = 90.588638
last_seq = 509
current_ts = 90.597176
current_received_ts = 90.596992
current_seq = 510
count = 45
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 35us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.597176
last_received_ts = 90.596992
last_seq = 510
current_ts = 90.605515
current_received_ts = 90.605270
current_seq = 511
count = 46
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 26us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.605515
last_received_ts = 90.605270
last_seq = 511
current_ts = 90.613846
current_received_ts = 90.613579
current_seq = 512
count = 47
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 37us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.613846
last_received_ts = 90.613579
last_seq = 512
current_ts = 90.622177
current_received_ts = 90.621880
current_seq = 513
count = 48
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.622177
last_received_ts = 90.621880
last_seq = 513
current_ts = 90.630516
current_received_ts = 90.630264
current_seq = 514
count = 49
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.630516
last_received_ts = 90.630264
last_seq = 514
current_ts = 90.638847
current_received_ts = 90.638596
current_seq = 515
count = 50
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 34us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.638847
last_received_ts = 90.638596
last_seq = 515
current_ts = 90.647186
current_received_ts = 90.647049
current_seq = 516
count = 51
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 36us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.647186
last_received_ts = 90.647049
last_seq = 516
current_ts = 90.655518
current_received_ts = 90.655235
current_seq = 517
count = 52
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.655518
last_received_ts = 90.655235
last_seq = 517
current_ts = 90.663849
current_received_ts = 90.663635
current_seq = 518
count = 53
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 32us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.663849
last_received_ts = 90.663635
last_seq = 518
current_ts = 90.672188
current_received_ts = 90.672035
current_seq = 519
count = 54
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 32us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.672188
last_received_ts = 90.672035
last_seq = 519
current_ts = 90.680527
current_received_ts = 90.680237
current_seq = 520
count = 55
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.680527
last_received_ts = 90.680237
last_seq = 520
current_ts = 90.688858
current_received_ts = 90.688606
current_seq = 521
count = 56
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 35us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.688858
last_received_ts = 90.688606
last_seq = 521
current_ts = 90.697189
current_received_ts = 90.696976
current_seq = 522
count = 57
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 43us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.697189
last_received_ts = 90.696976
last_seq = 522
current_ts = 90.705528
current_received_ts = 90.705307
current_seq = 523
count = 58
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.705528
last_received_ts = 90.705307
last_seq = 523
current_ts = 90.713860
current_received_ts = 90.713623
current_seq = 524
count = 59
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 31us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.713860
last_received_ts = 90.713623
last_seq = 524
current_ts = 90.722191
current_received_ts = 90.722054
current_seq = 525
count = 60
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 34us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.722191
last_received_ts = 90.722054
last_seq = 525
current_ts = 90.730530
current_received_ts = 90.730225
current_seq = 526
count = 61
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.730530
last_received_ts = 90.730225
last_seq = 526
current_ts = 90.738869
current_received_ts = 90.738609
current_seq = 527
count = 62
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.738869
last_received_ts = 90.738609
last_seq = 527
current_ts = 90.747200
current_received_ts = 90.747086
current_seq = 528
count = 63
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.747200
last_received_ts = 90.747086
last_seq = 528
current_ts = 90.755531
current_received_ts = 90.755341
current_seq = 529
count = 64
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 29us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.755531
last_received_ts = 90.755341
last_seq = 529
current_ts = 90.763863
current_received_ts = 90.763573
current_seq = 530
count = 65
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.763863
last_received_ts = 90.763573
last_seq = 530
current_ts = 90.772202
current_received_ts = 90.771996
current_seq = 531
count = 66
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.772202
last_received_ts = 90.771996
last_seq = 531
current_ts = 90.780540
current_received_ts = 90.780304
current_seq = 532
count = 67
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 36us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.780540
last_received_ts = 90.780304
last_seq = 532
current_ts = 90.788872
current_received_ts = 90.788620
current_seq = 533
count = 68
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.788872
last_received_ts = 90.788620
last_seq = 533
current_ts = 90.797203
current_received_ts = 90.797073
current_seq = 534
count = 69
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 29us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.797203
last_received_ts = 90.797073
last_seq = 534
current_ts = 90.805542
current_received_ts = 90.805313
current_seq = 535
count = 70
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.805542
last_received_ts = 90.805313
last_seq = 535
current_ts = 90.813873
current_received_ts = 90.813599
current_seq = 536
count = 71
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.813873
last_received_ts = 90.813599
last_seq = 536
current_ts = 90.822212
current_received_ts = 90.822067
current_seq = 537
count = 72
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.822212
last_received_ts = 90.822067
last_seq = 537
current_ts = 90.830544
current_received_ts = 90.830299
current_seq = 538
count = 73
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 35us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.830544
last_received_ts = 90.830299
last_seq = 538
current_ts = 90.838882
current_received_ts = 90.838669
current_seq = 539
count = 74
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 32us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.838882
last_received_ts = 90.838669
last_seq = 539
current_ts = 90.847221
current_received_ts = 90.847038
current_seq = 540
count = 75
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 34us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.847221
last_received_ts = 90.847038
last_seq = 540
current_ts = 90.855545
current_received_ts = 90.855339
current_seq = 541
count = 76
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.855545
last_received_ts = 90.855339
last_seq = 541
current_ts = 90.863884
current_received_ts = 90.863655
current_seq = 542
count = 77
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 25us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.863884
last_received_ts = 90.863655
last_seq = 542
current_ts = 90.872215
current_received_ts = 90.871941
current_seq = 543
count = 78
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.872215
last_received_ts = 90.871941
last_seq = 543
current_ts = 90.880554
current_received_ts = 90.880318
current_seq = 544
count = 79
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 31us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.880554
last_received_ts = 90.880318
last_seq = 544
current_ts = 90.888893
current_received_ts = 90.888641
current_seq = 545
count = 80
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 30us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.888893
last_received_ts = 90.888641
last_seq = 545
current_ts = 90.897224
current_received_ts = 90.896919
current_seq = 546
count = 81
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 26us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.897224
last_received_ts = 90.896919
last_seq = 546
current_ts = 90.905556
current_received_ts = 90.905289
current_seq = 547
count = 82
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 32us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.905556
last_received_ts = 90.905289
last_seq = 547
current_ts = 90.913895
current_received_ts = 90.913719
current_seq = 548
count = 83
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 32us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.913895
last_received_ts = 90.913719
last_seq = 548
current_ts = 90.922234
current_received_ts = 90.921928
current_seq = 549
count = 84
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 26us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.922234
last_received_ts = 90.921928
last_seq = 549
current_ts = 90.930557
current_received_ts = 90.930283
current_seq = 550
count = 85
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 26us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.930557
last_received_ts = 90.930283
last_seq = 550
current_ts = 90.938896
current_received_ts = 90.938660
current_seq = 551
count = 86
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 31us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.938896
last_received_ts = 90.938660
last_seq = 551
current_ts = 90.947235
current_received_ts = 90.947083
current_seq = 552
count = 87
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.947235
last_received_ts = 90.947083
last_seq = 552
current_ts = 90.955566
current_received_ts = 90.955261
current_seq = 553
count = 88
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.955566
last_received_ts = 90.955261
last_seq = 553
current_ts = 90.963898
current_received_ts = 90.963684
current_seq = 554
count = 89
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.963898
last_received_ts = 90.963684
last_seq = 554
current_ts = 90.972237
current_received_ts = 90.972115
current_seq = 555
count = 90
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 26us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.972237
last_received_ts = 90.972115
last_seq = 555
current_ts = 90.980568
current_received_ts = 90.980293
current_seq = 556
count = 91
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 29us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.980568
last_received_ts = 90.980293
last_seq = 556
current_ts = 90.988907
current_received_ts = 90.988670
current_seq = 557
count = 92
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 31us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.988907
last_received_ts = 90.988670
last_seq = 557
current_ts = 90.997238
current_received_ts = 90.997093
current_seq = 558
count = 93
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 32us
(kms_flip:2113) DEBUG: name = flip
last_ts = 90.997238
last_received_ts = 90.997093
last_seq = 558
current_ts = 91.005577
current_received_ts = 91.005325
current_seq = 559
count = 94
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 36us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.005577
last_received_ts = 91.005325
last_seq = 559
current_ts = 91.013908
current_received_ts = 91.013702
current_seq = 560
count = 95
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 29us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.013908
last_received_ts = 91.013702
last_seq = 560
current_ts = 91.022240
current_received_ts = 91.021965
current_seq = 561
count = 96
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 56us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.022240
last_received_ts = 91.021965
last_seq = 561
current_ts = 91.030579
current_received_ts = 91.030350
current_seq = 562
count = 97
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 35us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.030579
last_received_ts = 91.030350
last_seq = 562
current_ts = 91.038910
current_received_ts = 91.038689
current_seq = 563
count = 98
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.038910
last_received_ts = 91.038689
last_seq = 563
current_ts = 91.047241
current_received_ts = 91.046967
current_seq = 564
count = 99
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 49us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.047241
last_received_ts = 91.046967
last_seq = 564
current_ts = 91.055580
current_received_ts = 91.055275
current_seq = 565
count = 100
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 28us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.055580
last_received_ts = 91.055275
last_seq = 565
current_ts = 91.063911
current_received_ts = 91.063705
current_seq = 566
count = 101
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 34us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.063911
last_received_ts = 91.063705
last_seq = 566
current_ts = 91.072250
current_received_ts = 91.072136
current_seq = 567
count = 102
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.072250
last_received_ts = 91.072136
last_seq = 567
current_ts = 91.080582
current_received_ts = 91.080338
current_seq = 568
count = 103
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 30us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.080582
last_received_ts = 91.080338
last_seq = 568
current_ts = 91.088921
current_received_ts = 91.088699
current_seq = 569
count = 104
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 34us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.088921
last_received_ts = 91.088699
last_seq = 569
current_ts = 91.097252
current_received_ts = 91.097046
current_seq = 570
count = 105
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 37us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.097252
last_received_ts = 91.097046
last_seq = 570
current_ts = 91.105591
current_received_ts = 91.105301
current_seq = 571
count = 106
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 38us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.105591
last_received_ts = 91.105301
last_seq = 571
current_ts = 91.113922
current_received_ts = 91.113655
current_seq = 572
count = 107
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 31us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.113922
last_received_ts = 91.113655
last_seq = 572
current_ts = 91.122261
current_received_ts = 91.122108
current_seq = 573
count = 108
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.122261
last_received_ts = 91.122108
last_seq = 573
current_ts = 91.130592
current_received_ts = 91.130325
current_seq = 574
count = 109
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 29us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.130592
last_received_ts = 91.130325
last_seq = 574
current_ts = 91.138924
current_received_ts = 91.138664
current_seq = 575
count = 110
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 30us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.138924
last_received_ts = 91.138664
last_seq = 575
current_ts = 91.147263
current_received_ts = 91.147102
current_seq = 576
count = 111
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 32us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.147263
last_received_ts = 91.147102
last_seq = 576
current_ts = 91.155594
current_received_ts = 91.155304
current_seq = 577
count = 112
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.155594
last_received_ts = 91.155304
last_seq = 577
current_ts = 91.163933
current_received_ts = 91.163651
current_seq = 578
count = 113
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 26us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.163933
last_received_ts = 91.163651
last_seq = 578
current_ts = 91.172264
current_received_ts = 91.172089
current_seq = 579
count = 114
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.172264
last_received_ts = 91.172089
last_seq = 579
current_ts = 91.180603
current_received_ts = 91.180351
current_seq = 580
count = 115
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.180603
last_received_ts = 91.180351
last_seq = 580
current_ts = 91.188934
current_received_ts = 91.188713
current_seq = 581
count = 116
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 33us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.188934
last_received_ts = 91.188713
last_seq = 581
current_ts = 91.197266
current_received_ts = 91.196968
current_seq = 582
count = 117
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 43us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.197266
last_received_ts = 91.196968
last_seq = 582
current_ts = 91.205605
current_received_ts = 91.205292
current_seq = 583
count = 118
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 27us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.205605
last_received_ts = 91.205292
last_seq = 583
current_ts = 91.213936
current_received_ts = 91.213715
current_seq = 584
count = 119
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 32us
(kms_flip:2113) DEBUG: name = flip
last_ts = 91.213936
last_received_ts = 91.213715
last_seq = 584
current_ts = 91.222275
current_received_ts = 91.221962
current_seq = 585
count = 120
seq_step = 1
(kms_flip:2113) DEBUG: Vblank took 1082us
(kms_flip:2113) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2113) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2113) igt_core-INFO: Stack trace:
(kms_flip:2113) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2113) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:2113) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:2113) igt_core-INFO:   #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045()
(kms_flip:2113) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:2113) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2113) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2113) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (1.298s)

Dmesg

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

<7> [90.083794] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:635]

<7> [90.084033] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:636]

<7> [90.132407] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:169:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [90.147311] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:169:pipe A] releasing DPLL 0

<7> [90.147587] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no

<7> [90.147750] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:169:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0

<7> [90.147936] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:163:cursor A] ddb (1993 - 2048) -> ( 0 - 0), size 55 -> 0

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

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

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

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

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

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

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

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

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

<7> [90.150028] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:133:plane 5A] fb: [NOFB], visible: no

<7> [90.150297] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:143:plane 6A] fb: [NOFB], visible: no

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

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

<7> [90.150992] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:586:HDMI-A-1][ENCODER:585:DDI B/PHY B] Disable audio codec on [CRTC:169:pipe A]

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

<7> [90.165066] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:586:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10

<7> [90.165728] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1)

<7> [90.165876] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry

<7> [90.166462] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1)

<7> [90.166690] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:586:HDMI-A-1] Failed to read TMDS config: -6

<7> [90.166715] i915 0000:00:02.0: [drm:intel_ddi_disable [i915]] [CONNECTOR:586:HDMI-A-1] Failed to reset sink scrambling/TMDS bit clock ratio

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

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

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

<7> [90.172459] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0

<7> [90.172632] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 172800 kHz, VCO 345600 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

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

<7> [90.173118] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:595:DDI TC1/PHY TC1]

<7> [90.173355] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DP-MST A]

<7> [90.173586] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:598:DP-MST B]

<7> [90.173818] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST C]

<7> [90.174043] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST D]

<7> [90.174259] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:605:DDI TC2/PHY TC2]

<7> [90.174415] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DP-MST A]

<7> [90.174568] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:608:DP-MST B]

<7> [90.174721] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST C]

<7> [90.174880] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST D]

<7> [90.175088] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:614:DDI TC3/PHY TC3]

<7> [90.175321] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DP-MST A]

<7> [90.175549] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:617:DP-MST B]

<7> [90.175774] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST C]

<7> [90.175995] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST D]

<7> [90.176182] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:623:DDI TC4/PHY TC4]

<7> [90.176340] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DP-MST A]

<7> [90.176494] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:626:DP-MST B]

<7> [90.176680] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST C]

<7> [90.176908] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST D]

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

<7> [90.177635] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1

<7> [90.177852] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_3

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

<7> [90.178261] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:169:pipe A]

<7> [90.179184] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:307:pipe B]

<7> [90.179365] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:445:pipe C]

<7> [90.179498] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:583:pipe D]

<7> [90.179635] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:307:pipe B]

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

<7> [90.179729] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:586:HDMI-A-1] Limiting display bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36)

<7> [90.179948] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 8 bpc for HDMI output (pipe bpp: 24)

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

<7> [90.180464] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:585:DDI B/PHY B] [CRTC:307:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [90.190728] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no

<7> [90.190910] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:307:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2

<7> [90.191148] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:171:plane 1B] ddb ( 0 - 0) -> ( 0 - 1993), size 0 -> 1993

<7> [90.191303] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:301:cursor B] ddb ( 0 - 0) -> (1993 - 2048), size 0 -> 55

<7> [90.191470] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:171: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> [90.191643] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:171:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 8, 8, 8, 8, 11, 16, 16, 0, 0, 0

<7> [90.191798] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:171:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 129, 129, 129, 129, 177, 257, 257, 30, 0, 0

<7> [90.191950] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:171:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 143, 143, 143, 143, 196, 284, 284, 31, 0, 0

<7> [90.192174] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:307:pipe B] data rate 1142000 num active planes 1

<7> [90.192338] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 14993 required 1142

<7> [90.192503] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1

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

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

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

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

<7> [90.193537] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:307:pipe B] allocated DPLL 0

<7> [90.193781] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:307:pipe B] reserving DPLL 0

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

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

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

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

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

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

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

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

<7> [90.195548] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [90.195837] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 0f 00 6d a2 00 7f 00 00 00 00 00 00 00 00

<7> [90.196086] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 0d 82 34 12 66 69 74 48 65 61 64 6c 65 73 73 47

<7> [90.196255] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 53 7f 7f 28 0f 7f 07 17 7f ff 3f 7f ff 47 7f ff

<7> [90.196411] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 5f 7f 82 7f 7f 00 7f 7f 51 7f 7f 30 77 7f 03 00

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

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

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

<7> [90.197199] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1081, vmax vblank: 1081, vmin vtotal: 1144, vmax vtotal: 1144

<7> [90.197430] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5

<7> [90.197664] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5

<7> [90.197891] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5

<7> [90.198084] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x40 0x5

<7> [90.198305] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5

<7> [90.198460] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 285500, pipe src: 1920x1080+0+0, pixel rate 285500, min cdclk 192000

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

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

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

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

<7> [90.199557] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1801be, cfgcr1: 0x488, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [90.203475] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:271:plane 5B] fb: [NOFB], visible: no

<7> [90.203649] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:281:plane 6B] fb: [NOFB], visible: no

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

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

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

<7> [90.205020] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_3

<7> [90.205265] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 192000 kHz, VCO 384000 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

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

<7> [90.205668] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:595:DDI TC1/PHY TC1]

<7> [90.205826] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DP-MST A]

<7> [90.205982] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:598:DP-MST B]

<7> [90.206162] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST C]

<7> [90.206321] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST D]

<7> [90.206479] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:605:DDI TC2/PHY TC2]

<7> [90.206635] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DP-MST A]

<7> [90.206791] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:608:DP-MST B]

<7> [90.206946] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST C]

<7> [90.207112] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST D]

<7> [90.207264] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:614:DDI TC3/PHY TC3]

<7> [90.207416] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DP-MST A]

<7> [90.207570] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:617:DP-MST B]

<7> [90.207722] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST C]

<7> [90.207874] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST D]

<7> [90.208024] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:623:DDI TC4/PHY TC4]

<7> [90.208192] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DP-MST A]

<7> [90.208342] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:626:DP-MST B]

<7> [90.208495] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST C]

<7> [90.208647] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST D]

<7> [90.208918] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3

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

<7> [90.209302] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0

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

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

<7> [90.210473] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:586:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10

<7> [90.211152] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1)

<7> [90.211321] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry

<7> [90.211922] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1)

<7> [90.212091] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:586:HDMI-A-1] Failed to read TMDS config: -6

<7> [90.212112] i915 0000:00:02.0: [drm:intel_ddi_enable [i915]] [CONNECTOR:586:HDMI-A-1] Failed to configure sink scrambling/TMDS bit clock ratio

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

<7> [90.220746] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:586:HDMI-A-1][ENCODER:585:DDI B/PHY B] Enable audio codec on [CRTC:307:pipe B], 64 bytes ELD

<7> [90.222631] azx_init_pci: snd_hda_intel 0000:00:1f.3: Clearing TCSEL

<7> [90.222667] azx_init_pci: snd_hda_intel 0000:00:1f.3: SCH snoop: Enabled

<7> [90.229068] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] HDMI audio pixel clock setting for 285500 not found, falling back to defaults

<7> [90.229253] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000)

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

<6> [90.229577] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 5 not expected

<6> [90.229579] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 0 not expected

<6> [90.229581] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 10 not expected

<6> [90.229583] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 6 not expected

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

<7> [90.229966] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:307:pipe B]

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

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