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

Detail	Value
Duration	4.96 seconds
Hostname	shard-tglu-4
Igt-Version	IGT-Version: 2.4-g0784a5f7a (x86_64) (Linux: 7.1.0-rc3-CI_DRM_18473-gb83102e9c063+ 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:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-HDMI-A1: FAIL (4.963s)
Err	Starting dynamic subtest: B-HDMI-A1 (kms_flip:2077) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2077) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-HDMI-A1 failed. ** DEBUG (kms_flip:2077) DEBUG: name = flip last_ts = 66.819572 last_received_ts = 66.819214 last_seq = 538 current_ts = 66.827904 current_received_ts = 66.827553 current_seq = 539 count = 433 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 66.827904 last_received_ts = 66.827553 last_seq = 539 current_ts = 66.836235 current_received_ts = 66.835869 current_seq = 540 count = 434 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 66.836235 last_received_ts = 66.835869 last_seq = 540 current_ts = 66.844566 current_received_ts = 66.844193 current_seq = 541 count = 435 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 13us (kms_flip:2077) DEBUG: name = flip last_ts = 66.844566 last_received_ts = 66.844193 last_seq = 541 current_ts = 66.852905 current_received_ts = 66.852554 current_seq = 542 count = 436 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 66.852905 last_received_ts = 66.852554 last_seq = 542 current_ts = 66.861244 current_received_ts = 66.860886 current_seq = 543 count = 437 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 66.861244 last_received_ts = 66.860886 last_seq = 543 current_ts = 66.869576 current_received_ts = 66.869225 current_seq = 544 count = 438 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 66.869576 last_received_ts = 66.869225 last_seq = 544 current_ts = 66.877914 current_received_ts = 66.877594 current_seq = 545 count = 439 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 66.877914 last_received_ts = 66.877594 last_seq = 545 current_ts = 66.886246 current_received_ts = 66.885902 current_seq = 546 count = 440 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 66.886246 last_received_ts = 66.885902 last_seq = 546 current_ts = 66.894577 current_received_ts = 66.894241 current_seq = 547 count = 441 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 66.894577 last_received_ts = 66.894241 last_seq = 547 current_ts = 66.902916 current_received_ts = 66.902580 current_seq = 548 count = 442 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 66.902916 last_received_ts = 66.902580 last_seq = 548 current_ts = 66.911247 current_received_ts = 66.910919 current_seq = 549 count = 443 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 66.911247 last_received_ts = 66.910919 last_seq = 549 current_ts = 66.919586 current_received_ts = 66.919243 current_seq = 550 count = 444 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 66.919586 last_received_ts = 66.919243 last_seq = 550 current_ts = 66.927917 current_received_ts = 66.927574 current_seq = 551 count = 445 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 66.927917 last_received_ts = 66.927574 last_seq = 551 current_ts = 66.936256 current_received_ts = 66.935898 current_seq = 552 count = 446 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 66.936256 last_received_ts = 66.935898 last_seq = 552 current_ts = 66.944588 current_received_ts = 66.944237 current_seq = 553 count = 447 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 66.944588 last_received_ts = 66.944237 last_seq = 553 current_ts = 66.952919 current_received_ts = 66.952560 current_seq = 554 count = 448 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 66.952919 last_received_ts = 66.952560 last_seq = 554 current_ts = 66.961258 current_received_ts = 66.960938 current_seq = 555 count = 449 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 66.961258 last_received_ts = 66.960938 last_seq = 555 current_ts = 66.969589 current_received_ts = 66.969246 current_seq = 556 count = 450 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 66.969589 last_received_ts = 66.969246 last_seq = 556 current_ts = 66.977928 current_received_ts = 66.977585 current_seq = 557 count = 451 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 66.977928 last_received_ts = 66.977585 last_seq = 557 current_ts = 66.986259 current_received_ts = 66.985916 current_seq = 558 count = 452 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 66.986259 last_received_ts = 66.985916 last_seq = 558 current_ts = 66.994598 current_received_ts = 66.994247 current_seq = 559 count = 453 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 66.994598 last_received_ts = 66.994247 last_seq = 559 current_ts = 67.002930 current_received_ts = 67.002602 current_seq = 560 count = 454 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.002930 last_received_ts = 67.002602 last_seq = 560 current_ts = 67.011269 current_received_ts = 67.010895 current_seq = 561 count = 455 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.011269 last_received_ts = 67.010895 last_seq = 561 current_ts = 67.019592 current_received_ts = 67.019257 current_seq = 562 count = 456 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.019592 last_received_ts = 67.019257 last_seq = 562 current_ts = 67.027931 current_received_ts = 67.027603 current_seq = 563 count = 457 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.027931 last_received_ts = 67.027603 last_seq = 563 current_ts = 67.036263 current_received_ts = 67.035904 current_seq = 564 count = 458 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.036263 last_received_ts = 67.035904 last_seq = 564 current_ts = 67.044601 current_received_ts = 67.044273 current_seq = 565 count = 459 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 13us (kms_flip:2077) DEBUG: name = flip last_ts = 67.044601 last_received_ts = 67.044273 last_seq = 565 current_ts = 67.052940 current_received_ts = 67.052597 current_seq = 566 count = 460 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 13us (kms_flip:2077) DEBUG: name = flip last_ts = 67.052940 last_received_ts = 67.052597 last_seq = 566 current_ts = 67.061272 current_received_ts = 67.060944 current_seq = 567 count = 461 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.061272 last_received_ts = 67.060944 last_seq = 567 current_ts = 67.069603 current_received_ts = 67.069275 current_seq = 568 count = 462 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.069603 last_received_ts = 67.069275 last_seq = 568 current_ts = 67.077942 current_received_ts = 67.077599 current_seq = 569 count = 463 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.077942 last_received_ts = 67.077599 last_seq = 569 current_ts = 67.086281 current_received_ts = 67.085953 current_seq = 570 count = 464 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 14us (kms_flip:2077) DEBUG: name = flip last_ts = 67.086281 last_received_ts = 67.085953 last_seq = 570 current_ts = 67.094612 current_received_ts = 67.094254 current_seq = 571 count = 465 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.094612 last_received_ts = 67.094254 last_seq = 571 current_ts = 67.102943 current_received_ts = 67.102615 current_seq = 572 count = 466 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.102943 last_received_ts = 67.102615 last_seq = 572 current_ts = 67.111282 current_received_ts = 67.110924 current_seq = 573 count = 467 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.111282 last_received_ts = 67.110924 last_seq = 573 current_ts = 67.119614 current_received_ts = 67.119293 current_seq = 574 count = 468 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.119614 last_received_ts = 67.119293 last_seq = 574 current_ts = 67.127945 current_received_ts = 67.127594 current_seq = 575 count = 469 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.127945 last_received_ts = 67.127594 last_seq = 575 current_ts = 67.136284 current_received_ts = 67.135925 current_seq = 576 count = 470 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.136284 last_received_ts = 67.135925 last_seq = 576 current_ts = 67.144615 current_received_ts = 67.144264 current_seq = 577 count = 471 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.144615 last_received_ts = 67.144264 last_seq = 577 current_ts = 67.152946 current_received_ts = 67.152580 current_seq = 578 count = 472 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.152946 last_received_ts = 67.152580 last_seq = 578 current_ts = 67.161285 current_received_ts = 67.160904 current_seq = 579 count = 473 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.161285 last_received_ts = 67.160904 last_seq = 579 current_ts = 67.169624 current_received_ts = 67.169250 current_seq = 580 count = 474 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 14us (kms_flip:2077) DEBUG: name = flip last_ts = 67.169624 last_received_ts = 67.169250 last_seq = 580 current_ts = 67.177956 current_received_ts = 67.177628 current_seq = 581 count = 475 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 13us (kms_flip:2077) DEBUG: name = flip last_ts = 67.177956 last_received_ts = 67.177628 last_seq = 581 current_ts = 67.186295 current_received_ts = 67.185944 current_seq = 582 count = 476 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 14us (kms_flip:2077) DEBUG: name = flip last_ts = 67.186295 last_received_ts = 67.185944 last_seq = 582 current_ts = 67.194626 current_received_ts = 67.194275 current_seq = 583 count = 477 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.194626 last_received_ts = 67.194275 last_seq = 583 current_ts = 67.202965 current_received_ts = 67.202606 current_seq = 584 count = 478 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.202965 last_received_ts = 67.202606 last_seq = 584 current_ts = 67.211288 current_received_ts = 67.210945 current_seq = 585 count = 479 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.211288 last_received_ts = 67.210945 last_seq = 585 current_ts = 67.219627 current_received_ts = 67.219261 current_seq = 586 count = 480 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.219627 last_received_ts = 67.219261 last_seq = 586 current_ts = 67.227959 current_received_ts = 67.227615 current_seq = 587 count = 481 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 14us (kms_flip:2077) DEBUG: name = flip last_ts = 67.227959 last_received_ts = 67.227615 last_seq = 587 current_ts = 67.236298 current_received_ts = 67.235970 current_seq = 588 count = 482 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.236298 last_received_ts = 67.235970 last_seq = 588 current_ts = 67.244629 current_received_ts = 67.244293 current_seq = 589 count = 483 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 13us (kms_flip:2077) DEBUG: name = flip last_ts = 67.244629 last_received_ts = 67.244293 last_seq = 589 current_ts = 67.252960 current_received_ts = 67.252617 current_seq = 590 count = 484 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.252960 last_received_ts = 67.252617 last_seq = 590 current_ts = 67.261307 current_received_ts = 67.260971 current_seq = 591 count = 485 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 24us (kms_flip:2077) DEBUG: name = flip last_ts = 67.261307 last_received_ts = 67.260971 last_seq = 591 current_ts = 67.269630 current_received_ts = 67.269302 current_seq = 592 count = 486 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 14us (kms_flip:2077) DEBUG: name = flip last_ts = 67.269630 last_received_ts = 67.269302 last_seq = 592 current_ts = 67.277969 current_received_ts = 67.277618 current_seq = 593 count = 487 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.277969 last_received_ts = 67.277618 last_seq = 593 current_ts = 67.286301 current_received_ts = 67.285980 current_seq = 594 count = 488 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 23us (kms_flip:2077) DEBUG: name = flip last_ts = 67.286301 last_received_ts = 67.285980 last_seq = 594 current_ts = 67.294640 current_received_ts = 67.294281 current_seq = 595 count = 489 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.294640 last_received_ts = 67.294281 last_seq = 595 current_ts = 67.302979 current_received_ts = 67.302605 current_seq = 596 count = 490 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 13us (kms_flip:2077) DEBUG: name = flip last_ts = 67.302979 last_received_ts = 67.302605 last_seq = 596 current_ts = 67.311310 current_received_ts = 67.310951 current_seq = 597 count = 491 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.311310 last_received_ts = 67.310951 last_seq = 597 current_ts = 67.319641 current_received_ts = 67.319290 current_seq = 598 count = 492 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.319641 last_received_ts = 67.319290 last_seq = 598 current_ts = 67.327972 current_received_ts = 67.327606 current_seq = 599 count = 493 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.327972 last_received_ts = 67.327606 last_seq = 599 current_ts = 67.336311 current_received_ts = 67.335960 current_seq = 600 count = 494 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.336311 last_received_ts = 67.335960 last_seq = 600 current_ts = 67.344643 current_received_ts = 67.344292 current_seq = 601 count = 495 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 14us (kms_flip:2077) DEBUG: name = flip last_ts = 67.344643 last_received_ts = 67.344292 last_seq = 601 current_ts = 67.352974 current_received_ts = 67.352623 current_seq = 602 count = 496 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.352974 last_received_ts = 67.352623 last_seq = 602 current_ts = 67.361313 current_received_ts = 67.361427 current_seq = 603 count = 497 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.361313 last_received_ts = 67.361427 last_seq = 603 current_ts = 67.369652 current_received_ts = 67.369316 current_seq = 604 count = 498 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.369652 last_received_ts = 67.369316 last_seq = 604 current_ts = 67.377983 current_received_ts = 67.377647 current_seq = 605 count = 499 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.377983 last_received_ts = 67.377647 last_seq = 605 current_ts = 67.386314 current_received_ts = 67.386009 current_seq = 606 count = 500 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.386314 last_received_ts = 67.386009 last_seq = 606 current_ts = 67.394653 current_received_ts = 67.394318 current_seq = 607 count = 501 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.394653 last_received_ts = 67.394318 last_seq = 607 current_ts = 67.402985 current_received_ts = 67.402657 current_seq = 608 count = 502 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.402985 last_received_ts = 67.402657 last_seq = 608 current_ts = 67.411324 current_received_ts = 67.411011 current_seq = 609 count = 503 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.411324 last_received_ts = 67.411011 last_seq = 609 current_ts = 67.419655 current_received_ts = 67.419304 current_seq = 610 count = 504 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 21us (kms_flip:2077) DEBUG: name = flip last_ts = 67.419655 last_received_ts = 67.419304 last_seq = 610 current_ts = 67.427994 current_received_ts = 67.427658 current_seq = 611 count = 505 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.427994 last_received_ts = 67.427658 last_seq = 611 current_ts = 67.436325 current_received_ts = 67.435928 current_seq = 612 count = 506 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.436325 last_received_ts = 67.435928 last_seq = 612 current_ts = 67.444664 current_received_ts = 67.444336 current_seq = 613 count = 507 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.444664 last_received_ts = 67.444336 last_seq = 613 current_ts = 67.452995 current_received_ts = 67.452660 current_seq = 614 count = 508 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.452995 last_received_ts = 67.452660 last_seq = 614 current_ts = 67.461334 current_received_ts = 67.461021 current_seq = 615 count = 509 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.461334 last_received_ts = 67.461021 last_seq = 615 current_ts = 67.469658 current_received_ts = 67.469345 current_seq = 616 count = 510 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.469658 last_received_ts = 67.469345 last_seq = 616 current_ts = 67.478004 current_received_ts = 67.477638 current_seq = 617 count = 511 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.478004 last_received_ts = 67.477638 last_seq = 617 current_ts = 67.486336 current_received_ts = 67.485977 current_seq = 618 count = 512 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 26us (kms_flip:2077) DEBUG: name = flip last_ts = 67.486336 last_received_ts = 67.485977 last_seq = 618 current_ts = 67.494667 current_received_ts = 67.494347 current_seq = 619 count = 513 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.494667 last_received_ts = 67.494347 last_seq = 619 current_ts = 67.502998 current_received_ts = 67.502663 current_seq = 620 count = 514 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.502998 last_received_ts = 67.502663 last_seq = 620 current_ts = 67.511337 current_received_ts = 67.511017 current_seq = 621 count = 515 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.511337 last_received_ts = 67.511017 last_seq = 621 current_ts = 67.519676 current_received_ts = 67.519341 current_seq = 622 count = 516 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.519676 last_received_ts = 67.519341 last_seq = 622 current_ts = 67.528008 current_received_ts = 67.527672 current_seq = 623 count = 517 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.528008 last_received_ts = 67.527672 last_seq = 623 current_ts = 67.536339 current_received_ts = 67.536034 current_seq = 624 count = 518 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.536339 last_received_ts = 67.536034 last_seq = 624 current_ts = 67.544678 current_received_ts = 67.544342 current_seq = 625 count = 519 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.544678 last_received_ts = 67.544342 last_seq = 625 current_ts = 67.553009 current_received_ts = 67.552673 current_seq = 626 count = 520 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.553009 last_received_ts = 67.552673 last_seq = 626 current_ts = 67.561348 current_received_ts = 67.561028 current_seq = 627 count = 521 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.561348 last_received_ts = 67.561028 last_seq = 627 current_ts = 67.569679 current_received_ts = 67.569321 current_seq = 628 count = 522 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.569679 last_received_ts = 67.569321 last_seq = 628 current_ts = 67.578018 current_received_ts = 67.577690 current_seq = 629 count = 523 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.578018 last_received_ts = 67.577690 last_seq = 629 current_ts = 67.586349 current_received_ts = 67.586021 current_seq = 630 count = 524 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.586349 last_received_ts = 67.586021 last_seq = 630 current_ts = 67.594681 current_received_ts = 67.594345 current_seq = 631 count = 525 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.594681 last_received_ts = 67.594345 last_seq = 631 current_ts = 67.603020 current_received_ts = 67.602654 current_seq = 632 count = 526 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 12us (kms_flip:2077) DEBUG: name = flip last_ts = 67.603020 last_received_ts = 67.602654 last_seq = 632 current_ts = 67.611359 current_received_ts = 67.611404 current_seq = 633 count = 527 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 13us (kms_flip:2077) DEBUG: name = flip last_ts = 67.611359 last_received_ts = 67.611404 last_seq = 633 current_ts = 67.619682 current_received_ts = 67.619331 current_seq = 634 count = 528 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.619682 last_received_ts = 67.619331 last_seq = 634 current_ts = 67.628021 current_received_ts = 67.627678 current_seq = 635 count = 529 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 13us (kms_flip:2077) DEBUG: name = flip last_ts = 67.628021 last_received_ts = 67.627678 last_seq = 635 current_ts = 67.636353 current_received_ts = 67.635979 current_seq = 636 count = 530 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 21us (kms_flip:2077) DEBUG: name = flip last_ts = 67.636353 last_received_ts = 67.635979 last_seq = 636 current_ts = 67.644691 current_received_ts = 67.644348 current_seq = 637 count = 531 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.644691 last_received_ts = 67.644348 last_seq = 637 current_ts = 67.653023 current_received_ts = 67.652718 current_seq = 638 count = 532 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.653023 last_received_ts = 67.652718 last_seq = 638 current_ts = 67.661362 current_received_ts = 67.661049 current_seq = 639 count = 533 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 18us (kms_flip:2077) DEBUG: name = flip last_ts = 67.661362 last_received_ts = 67.661049 last_seq = 639 current_ts = 67.669693 current_received_ts = 67.669289 current_seq = 640 count = 534 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.669693 last_received_ts = 67.669289 last_seq = 640 current_ts = 67.678024 current_received_ts = 67.677643 current_seq = 641 count = 535 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.678024 last_received_ts = 67.677643 last_seq = 641 current_ts = 67.686363 current_received_ts = 67.685974 current_seq = 642 count = 536 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 25us (kms_flip:2077) DEBUG: name = flip last_ts = 67.686363 last_received_ts = 67.685974 last_seq = 642 current_ts = 67.694702 current_received_ts = 67.694344 current_seq = 643 count = 537 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.694702 last_received_ts = 67.694344 last_seq = 643 current_ts = 67.703033 current_received_ts = 67.702675 current_seq = 644 count = 538 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.703033 last_received_ts = 67.702675 last_seq = 644 current_ts = 67.711365 current_received_ts = 67.711014 current_seq = 645 count = 539 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 15us (kms_flip:2077) DEBUG: name = flip last_ts = 67.711365 last_received_ts = 67.711014 last_seq = 645 current_ts = 67.719704 current_received_ts = 67.719337 current_seq = 646 count = 540 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 26us (kms_flip:2077) DEBUG: name = flip last_ts = 67.719704 last_received_ts = 67.719337 last_seq = 646 current_ts = 67.728043 current_received_ts = 67.727676 current_seq = 647 count = 541 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.728043 last_received_ts = 67.727676 last_seq = 647 current_ts = 67.736366 current_received_ts = 67.736015 current_seq = 648 count = 542 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.736366 last_received_ts = 67.736015 last_seq = 648 current_ts = 67.744705 current_received_ts = 67.744347 current_seq = 649 count = 543 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.744705 last_received_ts = 67.744347 last_seq = 649 current_ts = 67.753044 current_received_ts = 67.752678 current_seq = 650 count = 544 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 20us (kms_flip:2077) DEBUG: name = flip last_ts = 67.753044 last_received_ts = 67.752678 last_seq = 650 current_ts = 67.761375 current_received_ts = 67.761009 current_seq = 651 count = 545 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.761375 last_received_ts = 67.761009 last_seq = 651 current_ts = 67.769707 current_received_ts = 67.769348 current_seq = 652 count = 546 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.769707 last_received_ts = 67.769348 last_seq = 652 current_ts = 67.778038 current_received_ts = 67.777687 current_seq = 653 count = 547 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.778038 last_received_ts = 67.777687 last_seq = 653 current_ts = 67.786377 current_received_ts = 67.786034 current_seq = 654 count = 548 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 17us (kms_flip:2077) DEBUG: name = flip last_ts = 67.786377 last_received_ts = 67.786034 last_seq = 654 current_ts = 67.794716 current_received_ts = 67.794350 current_seq = 655 count = 549 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 14us (kms_flip:2077) DEBUG: name = flip last_ts = 67.794716 last_received_ts = 67.794350 last_seq = 655 current_ts = 67.803047 current_received_ts = 67.802658 current_seq = 656 count = 550 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 22us (kms_flip:2077) DEBUG: name = flip last_ts = 67.803047 last_received_ts = 67.802658 last_seq = 656 current_ts = 67.811378 current_received_ts = 67.810989 current_seq = 657 count = 551 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 16us (kms_flip:2077) DEBUG: name = flip last_ts = 67.811378 last_received_ts = 67.810989 last_seq = 657 current_ts = 67.819717 current_received_ts = 67.819344 current_seq = 658 count = 552 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 14us (kms_flip:2077) DEBUG: name = flip last_ts = 67.819717 last_received_ts = 67.819344 last_seq = 658 current_ts = 67.828049 current_received_ts = 67.827660 current_seq = 659 count = 553 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 22us (kms_flip:2077) DEBUG: name = flip last_ts = 67.828049 last_received_ts = 67.827660 last_seq = 659 current_ts = 67.836388 current_received_ts = 67.835991 current_seq = 660 count = 554 seq_step = 1 (kms_flip:2077) DEBUG: Vblank took 610us (kms_flip:2077) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2077) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2077) igt_core-INFO: Stack trace: (kms_flip:2077) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2077) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:2077) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:2077) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() (kms_flip:2077) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:2077) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2077) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2077) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A1: FAIL (4.963s)
Dmesg	<6> [63.082643] [IGT] kms_flip: starting dynamic subtest B-HDMI-A1 <7> [63.083396] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:634] <7> [63.083617] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:636] <7> [63.123185] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:171:pipe A] <7> [63.123400] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [63.123781] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [63.124182] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [63.124585] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [63.124940] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [63.125358] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [63.125738] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [63.126100] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2080, found 0) <7> [63.126451] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [63.126785] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2080, found 0) <7> [63.127168] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1968, found 0) <7> [63.127542] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2000, found 0) <7> [63.127894] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [63.128267] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [63.128583] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [63.128880] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [63.129217] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1144, found 0) <7> [63.129532] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1144, found 0) <7> [63.129829] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [63.130158] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2080, found 0) <7> [63.130474] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [63.130772] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2080, found 0) <7> [63.131067] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1968, found 0) <7> [63.131311] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2000, found 0) <7> [63.131540] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [63.131766] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [63.131993] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [63.132251] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [63.132498] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1144, found 0) <7> [63.132725] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1144, found 0) <7> [63.132953] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [63.133210] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [63.133454] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [63.133688] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [63.133916] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in has_infoframe (expected yes, found no) <7> [63.134171] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [63.134388] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 285500, found 0) <7> [63.134551] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 285500, found 0) <7> [63.134716] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in port_clock (expected 285500, found 0) <7> [63.134888] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [63.135065] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in avi infoframe <7> [63.135242] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [63.135408] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [63.135410] i915 0000:00:02.0: colorspace: RGB <7> [63.135412] i915 0000:00:02.0: scan mode: Underscan <7> [63.135413] i915 0000:00:02.0: colorimetry: No Data <7> [63.135415] i915 0000:00:02.0: picture aspect: No Data <7> [63.135416] i915 0000:00:02.0: active aspect: Same as Picture <7> [63.135418] i915 0000:00:02.0: itc: No Data <7> [63.135419] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [63.135421] i915 0000:00:02.0: quantization range: Full <7> [63.135422] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [63.135424] i915 0000:00:02.0: video code: 0 <7> [63.135426] i915 0000:00:02.0: ycc quantization range: Full <7> [63.135427] i915 0000:00:02.0: hdmi content type: Graphics <7> [63.135429] i915 0000:00:02.0: pixel repeat: 0 <7> [63.135430] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [63.135432] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [63.135595] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in spd infoframe <7> [63.135760] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [63.135922] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [63.135924] i915 0000:00:02.0: vendor: Intel <7> [63.135926] i915 0000:00:02.0: product: Integrated gfx <7> [63.135928] i915 0000:00:02.0: source device information: PC General (0x9) <7> [63.135929] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [63.136109] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hdmi infoframe <7> [63.136300] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [63.136464] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [63.136466] i915 0000:00:02.0: empty frame <7> [63.136467] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [63.136631] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:171:pipe A] fastset requirement not met, forcing full modeset <7> [63.136801] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:171:pipe A] releasing DPLL 0 <7> [63.137006] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no <7> [63.137188] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:171:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [63.137394] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:165:cursor A] ddb (1993 - 2048) -> ( 0 - 0), size 55 -> 0 <7> [63.137575] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:171:pipe A] min cdclk: 192000 kHz -> 0 kHz <7> [63.137764] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [63.137924] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz <7> [63.138103] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [63.138281] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:171:pipe A] enable: no [modeset] <7> [63.138445] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [63.138607] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [63.138767] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [63.138925] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [63.139098] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [63.139269] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:145:plane 6A] fb: [NOFB], visible: no <7> [63.139425] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:155:plane 7A] fb: [NOFB], visible: no <7> [63.139584] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:165:cursor A] fb: [NOFB], visible: no <7> [63.139816] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:588:HDMI-A-1][ENCODER:587:DDI B/PHY B] Disable audio codec on [CRTC:171:pipe A] <7> [63.156113] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [63.161037] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:588:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10 <7> [63.161594] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [63.161750] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [63.162301] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [63.162536] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:588:HDMI-A-1] Failed to read TMDS config: -6 <7> [63.162561] i915 0000:00:02.0: [drm:intel_ddi_disable [i915]] [CONNECTOR:588:HDMI-A-1] Failed to reset sink scrambling/TMDS bit clock ratio <7> [63.162813] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [63.164649] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [63.164853] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:171:pipe A] <7> [63.165078] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0 <7> [63.165280] 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> [63.165509] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI B/PHY B] <7> [63.165694] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DDI TC1/PHY TC1] <7> [63.165859] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST A] <7> [63.166034] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST B] <7> [63.166218] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST C] <7> [63.166381] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:602:DP-MST D] <7> [63.166544] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DDI TC2/PHY TC2] <7> [63.166707] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST A] <7> [63.166868] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST B] <7> [63.167036] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST C] <7> [63.167217] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST D] <7> [63.167375] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DDI TC3/PHY TC3] <7> [63.167535] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST A] <7> [63.167693] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST B] <7> [63.167852] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST C] <7> [63.168008] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:621:DP-MST D] <7> [63.168181] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DDI TC4/PHY TC4] <7> [63.168385] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST A] <7> [63.168554] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST B] <7> [63.168723] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST C] <7> [63.168893] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:630:DP-MST D] <7> [63.169099] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:588:HDMI-A-1] <7> [63.169480] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [63.169713] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_3 <7> [63.169909] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [63.170139] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:171:pipe A] <7> [63.170745] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe B] <7> [63.170912] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe C] <7> [63.171061] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:585:pipe D] <7> [63.171211] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe B] <7> [63.171245] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:588:HDMI-A-1] <7> [63.171345] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:588:HDMI-A-1] Limiting target display pipe bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36) <7> [63.171531] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [63.171694] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [63.171866] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:587:DDI B/PHY B] [CRTC:309:pipe B] <7> [63.172032] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [63.172219] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [63.172382] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [63.172544] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [63.172705] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [63.172867] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [63.173038] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [63.173228] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2080) <7> [63.173389] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [63.173548] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2080) <7> [63.173707] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1968) <7> [63.173866] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2000) <7> [63.174051] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [63.174237] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [63.174396] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [63.174554] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [63.174713] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1144) <7> [63.174871] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1144) <7> [63.175043] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [63.175227] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2080) <7> [63.175389] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [63.175549] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2080) <7> [63.175708] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1968) <7> [63.175868] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2000) <7> [63.176035] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [63.176223] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [63.176381] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [63.176540] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [63.176698] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1144) <7> [63.176855] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1144) <7> [63.177010] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [63.177207] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [63.177400] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [63.177614] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [63.177772] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in has_infoframe (expected no, found yes) <7> [63.177938] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [63.178127] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 285500) <7> [63.178314] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 285500) <7> [63.178509] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in port_clock (expected 0, found 285500) <7> [63.178665] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [63.178830] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in avi infoframe <7> [63.178995] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [63.179191] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [63.179361] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [63.179363] i915 0000:00:02.0: colorspace: RGB <7> [63.179365] i915 0000:00:02.0: scan mode: Underscan <7> [63.179366] i915 0000:00:02.0: colorimetry: No Data <7> [63.179368] i915 0000:00:02.0: picture aspect: No Data <7> [63.179369] i915 0000:00:02.0: active aspect: Same as Picture <7> [63.179370] i915 0000:00:02.0: itc: No Data <7> [63.179372] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [63.179373] i915 0000:00:02.0: quantization range: Full <7> [63.179374] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [63.179376] i915 0000:00:02.0: video code: 0 <7> [63.179377] i915 0000:00:02.0: ycc quantization range: Full <7> [63.179379] i915 0000:00:02.0: hdmi content type: Graphics <7> [63.179380] i915 0000:00:02.0: pixel repeat: 0 <7> [63.179382] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [63.179384] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in spd infoframe <7> [63.179547] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [63.179708] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [63.179867] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [63.179869] i915 0000:00:02.0: vendor: Intel <7> [63.179871] i915 0000:00:02.0: product: Integrated gfx <7> [63.179872] i915 0000:00:02.0: source device information: PC General (0x9) <7> [63.179874] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hdmi infoframe <7> [63.180037] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [63.180221] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [63.180397] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [63.180399] i915 0000:00:02.0: empty frame <7> [63.180401] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe B] fastset requirement not met, forcing full modeset <7> [63.180595] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no <7> [63.180754] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:309:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2 <7> [63.180950] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:173:plane 1B] ddb ( 0 - 0) -> ( 0 - 1993), size 0 -> 1993 <7> [63.181122] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:303:cursor B] ddb ( 0 - 0) -> (1993 - 2048), size 0 -> 55 <7> [63.181306] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173: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> [63.181466] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173: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> [63.181623] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173: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> [63.181780] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173: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> [63.181954] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:309:pipe B] data rate 1142000 num active planes 1 <7> [63.182238] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 14993 required 1142 <7> [63.182401] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [63.182582] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:309:pipe B] min cdclk: 0 kHz -> 192000 kHz <7> [63.182785] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [63.182945] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [63.183122] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [63.183309] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:309:pipe B] allocated DPLL 0 <7> [63.183474] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:309:pipe B] reserving DPLL 0 <7> [63.183640] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:309:pipe B] enable: yes [modeset] <7> [63.183802] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [63.183964] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [63.184138] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [63.184322] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [63.184484] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [63.184645] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [63.184804] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [63.184963] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x0 <7> [63.185135] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [63.185137] i915 0000:00:02.0: colorspace: RGB <7> [63.185138] i915 0000:00:02.0: scan mode: Underscan <7> [63.185140] i915 0000:00:02.0: colorimetry: No Data <7> [63.185141] i915 0000:00:02.0: picture aspect: No Data <7> [63.185143] i915 0000:00:02.0: active aspect: Same as Picture <7> [63.185144] i915 0000:00:02.0: itc: No Data <7> [63.185146] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [63.185147] i915 0000:00:02.0: quantization range: Full <7> [63.185149] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [63.185150] i915 0000:00:02.0: video code: 0 <7> [63.185152] i915 0000:00:02.0: ycc quantization range: Full <7> [63.185153] i915 0000:00:02.0: hdmi content type: Graphics <7> [63.185155] i915 0000:00:02.0: pixel repeat: 0 <7> [63.185156] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [63.185158] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [63.185160] i915 0000:00:02.0: vendor: Intel <7> [63.185161] i915 0000:00:02.0: product: Integrated gfx <7> [63.185162] i915 0000:00:02.0: source device information: PC General (0x9) <7> [63.185164] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [63.185166] i915 0000:00:02.0: empty frame <7> [63.185167] 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> [63.185364] 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> [63.185522] 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> [63.185680] 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> [63.185837] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [63.185994] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [63.186175] 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> [63.186355] 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> [63.186512] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [63.186672] 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> [63.186827] 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> [63.186984] 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> [63.187173] 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> [63.187351] 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> [63.187510] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 285500, pixel rate 285500, min cdclk 192000, min voltage level 0 <7> [63.187666] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [63.187821] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [63.187978] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [63.188148] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [63.188335] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [63.188491] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [63.188646] 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> [63.188804] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x40000000 gamma_enable: 0 csc_enable: 0 <7> [63.188961] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 256 entries <7> [63.189130] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [63.189316] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [63.189471] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [63.189627] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [63.189783] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [63.189939] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [63.190116] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [63.190295] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [63.190451] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [63.190610] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [63.190766] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:173:plane 1B] fb: [FB:634] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [63.190926] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [63.191100] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [63.191281] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:203:plane 2B] fb: [NOFB], visible: no <7> [63.191439] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:233:plane 3B] fb: [NOFB], visible: no <7> [63.191596] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:263:plane 4B] fb: [NOFB], visible: no <7> [63.191751] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:273:plane 5B] fb: [NOFB], visible: no <7> [63.191907] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:283:plane 6B] fb: [NOFB], visible: no <7> [63.192074] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:293:plane 7B] fb: [NOFB], visible: no <7> [63.192256] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:303:cursor B] fb: [NOFB], visible: no <7> [63.193071] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [63.193266] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_3 <7> [63.193478] 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> [63.193741] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI B/PHY B] <7> [63.193954] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DDI TC1/PHY TC1] <7> [63.194131] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST A] <7> [63.194302] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST B] <7> [63.194474] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST C] <7> [63.194663] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:602:DP-MST D] <7> [63.194845] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DDI TC2/PHY TC2] <7> [63.195009] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST A] <7> [63.195191] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST B] <7> [63.195364] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST C] <7> [63.195574] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST D] <7> [63.195736] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DDI TC3/PHY TC3] <7> [63.195903] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST A] <7> [63.196088] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST B] <7> [63.196247] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST C] <7> [63.196436] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:621:DP-MST D] <7> [63.196611] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DDI TC4/PHY TC4] <7> [63.196778] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST A] <7> [63.196936] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST B] <7> [63.197120] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST C] <7> [63.197310] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:630:DP-MST D] <7> [63.197604] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [63.197812] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:309:pipe B] <7> [63.198008] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0 <7> [63.198262] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B <7> [63.198545] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [63.199297] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:588:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10 <7> [63.199878] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [63.200038] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x810 <7> [63.200076] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [63.200443] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [63.200613] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:588:HDMI-A-1] Failed to read TMDS config: -6 <7> [63.200630] i915 0000:00:02.0: [drm:intel_ddi_enable [i915]] [CONNECTOR:588:HDMI-A-1] Failed to configure sink scrambling/TMDS bit clock ratio <7> [63.204644] azx_init_pci: snd_hda_intel 0000:00:1f.3: Clearing TCSEL <7> [63.204676] azx_init_pci: snd_hda_intel 0000:00:1f.3: SCH snoop: Enabled <7> [63.217643] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:588:HDMI-A-1][ENCODER:587:DDI B/PHY B] Enable audio codec on [CRTC:309:pipe B], 64 bytes ELD <7> [63.226037] 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> [63.226230] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000) <7> [63.226377] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <6> [63.226528] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 5 not expected <6> [63.226531] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 0 not expected <6> [63.226532] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 10 not expected <6> [63.226533] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 6 not expected <7> [63.226669] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:588:HDMI-A-1] <7> [63.226904] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:309:pipe B] <7> [63.285494] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x810 <7> [63.290062] azx_init_pci: snd_hda_intel 0000:00:1f.3: Clearing TCSEL <7> [63.290094] azx_init_pci: snd_hda_intel 0000:00:1f.3: SCH snoop: Enabled <6> [68.046267] [IGT] kms_flip: finished subtest B-HDMI-A1, FAIL

Detail

Value

Duration

4.96 seconds

Hostname

shard-tglu-4

Igt-Version

IGT-Version: 2.4-g0784a5f7a (x86_64) (Linux: 7.1.0-rc3-CI_DRM_18473-gb83102e9c063+ 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:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A1: FAIL (4.963s)

Err

Starting dynamic subtest: B-HDMI-A1
(kms_flip:2077) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2077) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.819572
last_received_ts = 66.819214
last_seq = 538
current_ts = 66.827904
current_received_ts = 66.827553
current_seq = 539
count = 433
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.827904
last_received_ts = 66.827553
last_seq = 539
current_ts = 66.836235
current_received_ts = 66.835869
current_seq = 540
count = 434
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.836235
last_received_ts = 66.835869
last_seq = 540
current_ts = 66.844566
current_received_ts = 66.844193
current_seq = 541
count = 435
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 13us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.844566
last_received_ts = 66.844193
last_seq = 541
current_ts = 66.852905
current_received_ts = 66.852554
current_seq = 542
count = 436
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.852905
last_received_ts = 66.852554
last_seq = 542
current_ts = 66.861244
current_received_ts = 66.860886
current_seq = 543
count = 437
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.861244
last_received_ts = 66.860886
last_seq = 543
current_ts = 66.869576
current_received_ts = 66.869225
current_seq = 544
count = 438
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.869576
last_received_ts = 66.869225
last_seq = 544
current_ts = 66.877914
current_received_ts = 66.877594
current_seq = 545
count = 439
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.877914
last_received_ts = 66.877594
last_seq = 545
current_ts = 66.886246
current_received_ts = 66.885902
current_seq = 546
count = 440
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.886246
last_received_ts = 66.885902
last_seq = 546
current_ts = 66.894577
current_received_ts = 66.894241
current_seq = 547
count = 441
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.894577
last_received_ts = 66.894241
last_seq = 547
current_ts = 66.902916
current_received_ts = 66.902580
current_seq = 548
count = 442
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.902916
last_received_ts = 66.902580
last_seq = 548
current_ts = 66.911247
current_received_ts = 66.910919
current_seq = 549
count = 443
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.911247
last_received_ts = 66.910919
last_seq = 549
current_ts = 66.919586
current_received_ts = 66.919243
current_seq = 550
count = 444
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.919586
last_received_ts = 66.919243
last_seq = 550
current_ts = 66.927917
current_received_ts = 66.927574
current_seq = 551
count = 445
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.927917
last_received_ts = 66.927574
last_seq = 551
current_ts = 66.936256
current_received_ts = 66.935898
current_seq = 552
count = 446
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.936256
last_received_ts = 66.935898
last_seq = 552
current_ts = 66.944588
current_received_ts = 66.944237
current_seq = 553
count = 447
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.944588
last_received_ts = 66.944237
last_seq = 553
current_ts = 66.952919
current_received_ts = 66.952560
current_seq = 554
count = 448
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.952919
last_received_ts = 66.952560
last_seq = 554
current_ts = 66.961258
current_received_ts = 66.960938
current_seq = 555
count = 449
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.961258
last_received_ts = 66.960938
last_seq = 555
current_ts = 66.969589
current_received_ts = 66.969246
current_seq = 556
count = 450
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.969589
last_received_ts = 66.969246
last_seq = 556
current_ts = 66.977928
current_received_ts = 66.977585
current_seq = 557
count = 451
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.977928
last_received_ts = 66.977585
last_seq = 557
current_ts = 66.986259
current_received_ts = 66.985916
current_seq = 558
count = 452
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.986259
last_received_ts = 66.985916
last_seq = 558
current_ts = 66.994598
current_received_ts = 66.994247
current_seq = 559
count = 453
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 66.994598
last_received_ts = 66.994247
last_seq = 559
current_ts = 67.002930
current_received_ts = 67.002602
current_seq = 560
count = 454
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.002930
last_received_ts = 67.002602
last_seq = 560
current_ts = 67.011269
current_received_ts = 67.010895
current_seq = 561
count = 455
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.011269
last_received_ts = 67.010895
last_seq = 561
current_ts = 67.019592
current_received_ts = 67.019257
current_seq = 562
count = 456
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.019592
last_received_ts = 67.019257
last_seq = 562
current_ts = 67.027931
current_received_ts = 67.027603
current_seq = 563
count = 457
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.027931
last_received_ts = 67.027603
last_seq = 563
current_ts = 67.036263
current_received_ts = 67.035904
current_seq = 564
count = 458
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.036263
last_received_ts = 67.035904
last_seq = 564
current_ts = 67.044601
current_received_ts = 67.044273
current_seq = 565
count = 459
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 13us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.044601
last_received_ts = 67.044273
last_seq = 565
current_ts = 67.052940
current_received_ts = 67.052597
current_seq = 566
count = 460
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 13us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.052940
last_received_ts = 67.052597
last_seq = 566
current_ts = 67.061272
current_received_ts = 67.060944
current_seq = 567
count = 461
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.061272
last_received_ts = 67.060944
last_seq = 567
current_ts = 67.069603
current_received_ts = 67.069275
current_seq = 568
count = 462
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.069603
last_received_ts = 67.069275
last_seq = 568
current_ts = 67.077942
current_received_ts = 67.077599
current_seq = 569
count = 463
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.077942
last_received_ts = 67.077599
last_seq = 569
current_ts = 67.086281
current_received_ts = 67.085953
current_seq = 570
count = 464
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 14us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.086281
last_received_ts = 67.085953
last_seq = 570
current_ts = 67.094612
current_received_ts = 67.094254
current_seq = 571
count = 465
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.094612
last_received_ts = 67.094254
last_seq = 571
current_ts = 67.102943
current_received_ts = 67.102615
current_seq = 572
count = 466
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.102943
last_received_ts = 67.102615
last_seq = 572
current_ts = 67.111282
current_received_ts = 67.110924
current_seq = 573
count = 467
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.111282
last_received_ts = 67.110924
last_seq = 573
current_ts = 67.119614
current_received_ts = 67.119293
current_seq = 574
count = 468
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.119614
last_received_ts = 67.119293
last_seq = 574
current_ts = 67.127945
current_received_ts = 67.127594
current_seq = 575
count = 469
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.127945
last_received_ts = 67.127594
last_seq = 575
current_ts = 67.136284
current_received_ts = 67.135925
current_seq = 576
count = 470
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.136284
last_received_ts = 67.135925
last_seq = 576
current_ts = 67.144615
current_received_ts = 67.144264
current_seq = 577
count = 471
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.144615
last_received_ts = 67.144264
last_seq = 577
current_ts = 67.152946
current_received_ts = 67.152580
current_seq = 578
count = 472
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.152946
last_received_ts = 67.152580
last_seq = 578
current_ts = 67.161285
current_received_ts = 67.160904
current_seq = 579
count = 473
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.161285
last_received_ts = 67.160904
last_seq = 579
current_ts = 67.169624
current_received_ts = 67.169250
current_seq = 580
count = 474
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 14us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.169624
last_received_ts = 67.169250
last_seq = 580
current_ts = 67.177956
current_received_ts = 67.177628
current_seq = 581
count = 475
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 13us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.177956
last_received_ts = 67.177628
last_seq = 581
current_ts = 67.186295
current_received_ts = 67.185944
current_seq = 582
count = 476
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 14us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.186295
last_received_ts = 67.185944
last_seq = 582
current_ts = 67.194626
current_received_ts = 67.194275
current_seq = 583
count = 477
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.194626
last_received_ts = 67.194275
last_seq = 583
current_ts = 67.202965
current_received_ts = 67.202606
current_seq = 584
count = 478
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.202965
last_received_ts = 67.202606
last_seq = 584
current_ts = 67.211288
current_received_ts = 67.210945
current_seq = 585
count = 479
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.211288
last_received_ts = 67.210945
last_seq = 585
current_ts = 67.219627
current_received_ts = 67.219261
current_seq = 586
count = 480
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.219627
last_received_ts = 67.219261
last_seq = 586
current_ts = 67.227959
current_received_ts = 67.227615
current_seq = 587
count = 481
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 14us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.227959
last_received_ts = 67.227615
last_seq = 587
current_ts = 67.236298
current_received_ts = 67.235970
current_seq = 588
count = 482
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.236298
last_received_ts = 67.235970
last_seq = 588
current_ts = 67.244629
current_received_ts = 67.244293
current_seq = 589
count = 483
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 13us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.244629
last_received_ts = 67.244293
last_seq = 589
current_ts = 67.252960
current_received_ts = 67.252617
current_seq = 590
count = 484
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.252960
last_received_ts = 67.252617
last_seq = 590
current_ts = 67.261307
current_received_ts = 67.260971
current_seq = 591
count = 485
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 24us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.261307
last_received_ts = 67.260971
last_seq = 591
current_ts = 67.269630
current_received_ts = 67.269302
current_seq = 592
count = 486
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 14us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.269630
last_received_ts = 67.269302
last_seq = 592
current_ts = 67.277969
current_received_ts = 67.277618
current_seq = 593
count = 487
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.277969
last_received_ts = 67.277618
last_seq = 593
current_ts = 67.286301
current_received_ts = 67.285980
current_seq = 594
count = 488
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 23us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.286301
last_received_ts = 67.285980
last_seq = 594
current_ts = 67.294640
current_received_ts = 67.294281
current_seq = 595
count = 489
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.294640
last_received_ts = 67.294281
last_seq = 595
current_ts = 67.302979
current_received_ts = 67.302605
current_seq = 596
count = 490
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 13us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.302979
last_received_ts = 67.302605
last_seq = 596
current_ts = 67.311310
current_received_ts = 67.310951
current_seq = 597
count = 491
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.311310
last_received_ts = 67.310951
last_seq = 597
current_ts = 67.319641
current_received_ts = 67.319290
current_seq = 598
count = 492
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.319641
last_received_ts = 67.319290
last_seq = 598
current_ts = 67.327972
current_received_ts = 67.327606
current_seq = 599
count = 493
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.327972
last_received_ts = 67.327606
last_seq = 599
current_ts = 67.336311
current_received_ts = 67.335960
current_seq = 600
count = 494
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.336311
last_received_ts = 67.335960
last_seq = 600
current_ts = 67.344643
current_received_ts = 67.344292
current_seq = 601
count = 495
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 14us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.344643
last_received_ts = 67.344292
last_seq = 601
current_ts = 67.352974
current_received_ts = 67.352623
current_seq = 602
count = 496
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.352974
last_received_ts = 67.352623
last_seq = 602
current_ts = 67.361313
current_received_ts = 67.361427
current_seq = 603
count = 497
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.361313
last_received_ts = 67.361427
last_seq = 603
current_ts = 67.369652
current_received_ts = 67.369316
current_seq = 604
count = 498
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.369652
last_received_ts = 67.369316
last_seq = 604
current_ts = 67.377983
current_received_ts = 67.377647
current_seq = 605
count = 499
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.377983
last_received_ts = 67.377647
last_seq = 605
current_ts = 67.386314
current_received_ts = 67.386009
current_seq = 606
count = 500
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.386314
last_received_ts = 67.386009
last_seq = 606
current_ts = 67.394653
current_received_ts = 67.394318
current_seq = 607
count = 501
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.394653
last_received_ts = 67.394318
last_seq = 607
current_ts = 67.402985
current_received_ts = 67.402657
current_seq = 608
count = 502
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.402985
last_received_ts = 67.402657
last_seq = 608
current_ts = 67.411324
current_received_ts = 67.411011
current_seq = 609
count = 503
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.411324
last_received_ts = 67.411011
last_seq = 609
current_ts = 67.419655
current_received_ts = 67.419304
current_seq = 610
count = 504
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 21us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.419655
last_received_ts = 67.419304
last_seq = 610
current_ts = 67.427994
current_received_ts = 67.427658
current_seq = 611
count = 505
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.427994
last_received_ts = 67.427658
last_seq = 611
current_ts = 67.436325
current_received_ts = 67.435928
current_seq = 612
count = 506
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.436325
last_received_ts = 67.435928
last_seq = 612
current_ts = 67.444664
current_received_ts = 67.444336
current_seq = 613
count = 507
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.444664
last_received_ts = 67.444336
last_seq = 613
current_ts = 67.452995
current_received_ts = 67.452660
current_seq = 614
count = 508
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.452995
last_received_ts = 67.452660
last_seq = 614
current_ts = 67.461334
current_received_ts = 67.461021
current_seq = 615
count = 509
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.461334
last_received_ts = 67.461021
last_seq = 615
current_ts = 67.469658
current_received_ts = 67.469345
current_seq = 616
count = 510
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.469658
last_received_ts = 67.469345
last_seq = 616
current_ts = 67.478004
current_received_ts = 67.477638
current_seq = 617
count = 511
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.478004
last_received_ts = 67.477638
last_seq = 617
current_ts = 67.486336
current_received_ts = 67.485977
current_seq = 618
count = 512
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 26us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.486336
last_received_ts = 67.485977
last_seq = 618
current_ts = 67.494667
current_received_ts = 67.494347
current_seq = 619
count = 513
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.494667
last_received_ts = 67.494347
last_seq = 619
current_ts = 67.502998
current_received_ts = 67.502663
current_seq = 620
count = 514
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.502998
last_received_ts = 67.502663
last_seq = 620
current_ts = 67.511337
current_received_ts = 67.511017
current_seq = 621
count = 515
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.511337
last_received_ts = 67.511017
last_seq = 621
current_ts = 67.519676
current_received_ts = 67.519341
current_seq = 622
count = 516
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.519676
last_received_ts = 67.519341
last_seq = 622
current_ts = 67.528008
current_received_ts = 67.527672
current_seq = 623
count = 517
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.528008
last_received_ts = 67.527672
last_seq = 623
current_ts = 67.536339
current_received_ts = 67.536034
current_seq = 624
count = 518
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.536339
last_received_ts = 67.536034
last_seq = 624
current_ts = 67.544678
current_received_ts = 67.544342
current_seq = 625
count = 519
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.544678
last_received_ts = 67.544342
last_seq = 625
current_ts = 67.553009
current_received_ts = 67.552673
current_seq = 626
count = 520
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.553009
last_received_ts = 67.552673
last_seq = 626
current_ts = 67.561348
current_received_ts = 67.561028
current_seq = 627
count = 521
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.561348
last_received_ts = 67.561028
last_seq = 627
current_ts = 67.569679
current_received_ts = 67.569321
current_seq = 628
count = 522
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.569679
last_received_ts = 67.569321
last_seq = 628
current_ts = 67.578018
current_received_ts = 67.577690
current_seq = 629
count = 523
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.578018
last_received_ts = 67.577690
last_seq = 629
current_ts = 67.586349
current_received_ts = 67.586021
current_seq = 630
count = 524
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.586349
last_received_ts = 67.586021
last_seq = 630
current_ts = 67.594681
current_received_ts = 67.594345
current_seq = 631
count = 525
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.594681
last_received_ts = 67.594345
last_seq = 631
current_ts = 67.603020
current_received_ts = 67.602654
current_seq = 632
count = 526
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 12us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.603020
last_received_ts = 67.602654
last_seq = 632
current_ts = 67.611359
current_received_ts = 67.611404
current_seq = 633
count = 527
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 13us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.611359
last_received_ts = 67.611404
last_seq = 633
current_ts = 67.619682
current_received_ts = 67.619331
current_seq = 634
count = 528
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.619682
last_received_ts = 67.619331
last_seq = 634
current_ts = 67.628021
current_received_ts = 67.627678
current_seq = 635
count = 529
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 13us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.628021
last_received_ts = 67.627678
last_seq = 635
current_ts = 67.636353
current_received_ts = 67.635979
current_seq = 636
count = 530
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 21us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.636353
last_received_ts = 67.635979
last_seq = 636
current_ts = 67.644691
current_received_ts = 67.644348
current_seq = 637
count = 531
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.644691
last_received_ts = 67.644348
last_seq = 637
current_ts = 67.653023
current_received_ts = 67.652718
current_seq = 638
count = 532
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.653023
last_received_ts = 67.652718
last_seq = 638
current_ts = 67.661362
current_received_ts = 67.661049
current_seq = 639
count = 533
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 18us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.661362
last_received_ts = 67.661049
last_seq = 639
current_ts = 67.669693
current_received_ts = 67.669289
current_seq = 640
count = 534
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.669693
last_received_ts = 67.669289
last_seq = 640
current_ts = 67.678024
current_received_ts = 67.677643
current_seq = 641
count = 535
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.678024
last_received_ts = 67.677643
last_seq = 641
current_ts = 67.686363
current_received_ts = 67.685974
current_seq = 642
count = 536
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 25us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.686363
last_received_ts = 67.685974
last_seq = 642
current_ts = 67.694702
current_received_ts = 67.694344
current_seq = 643
count = 537
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.694702
last_received_ts = 67.694344
last_seq = 643
current_ts = 67.703033
current_received_ts = 67.702675
current_seq = 644
count = 538
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.703033
last_received_ts = 67.702675
last_seq = 644
current_ts = 67.711365
current_received_ts = 67.711014
current_seq = 645
count = 539
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 15us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.711365
last_received_ts = 67.711014
last_seq = 645
current_ts = 67.719704
current_received_ts = 67.719337
current_seq = 646
count = 540
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 26us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.719704
last_received_ts = 67.719337
last_seq = 646
current_ts = 67.728043
current_received_ts = 67.727676
current_seq = 647
count = 541
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.728043
last_received_ts = 67.727676
last_seq = 647
current_ts = 67.736366
current_received_ts = 67.736015
current_seq = 648
count = 542
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.736366
last_received_ts = 67.736015
last_seq = 648
current_ts = 67.744705
current_received_ts = 67.744347
current_seq = 649
count = 543
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.744705
last_received_ts = 67.744347
last_seq = 649
current_ts = 67.753044
current_received_ts = 67.752678
current_seq = 650
count = 544
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 20us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.753044
last_received_ts = 67.752678
last_seq = 650
current_ts = 67.761375
current_received_ts = 67.761009
current_seq = 651
count = 545
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.761375
last_received_ts = 67.761009
last_seq = 651
current_ts = 67.769707
current_received_ts = 67.769348
current_seq = 652
count = 546
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.769707
last_received_ts = 67.769348
last_seq = 652
current_ts = 67.778038
current_received_ts = 67.777687
current_seq = 653
count = 547
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.778038
last_received_ts = 67.777687
last_seq = 653
current_ts = 67.786377
current_received_ts = 67.786034
current_seq = 654
count = 548
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 17us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.786377
last_received_ts = 67.786034
last_seq = 654
current_ts = 67.794716
current_received_ts = 67.794350
current_seq = 655
count = 549
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 14us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.794716
last_received_ts = 67.794350
last_seq = 655
current_ts = 67.803047
current_received_ts = 67.802658
current_seq = 656
count = 550
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 22us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.803047
last_received_ts = 67.802658
last_seq = 656
current_ts = 67.811378
current_received_ts = 67.810989
current_seq = 657
count = 551
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 16us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.811378
last_received_ts = 67.810989
last_seq = 657
current_ts = 67.819717
current_received_ts = 67.819344
current_seq = 658
count = 552
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 14us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.819717
last_received_ts = 67.819344
last_seq = 658
current_ts = 67.828049
current_received_ts = 67.827660
current_seq = 659
count = 553
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 22us
(kms_flip:2077) DEBUG: name = flip
last_ts = 67.828049
last_received_ts = 67.827660
last_seq = 659
current_ts = 67.836388
current_received_ts = 67.835991
current_seq = 660
count = 554
seq_step = 1
(kms_flip:2077) DEBUG: Vblank took 610us
(kms_flip:2077) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2077) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2077) igt_core-INFO: Stack trace:
(kms_flip:2077) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2077) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:2077) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:2077) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
(kms_flip:2077) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:2077) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2077) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2077) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (4.963s)

Dmesg

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

<7> [63.083396] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:634]

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

<7> [63.123185] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:171:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [63.139816] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:588:HDMI-A-1][ENCODER:587:DDI B/PHY B] Disable audio codec on [CRTC:171:pipe A]

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

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

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

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

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

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

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

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

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

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

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

<7> [63.165280] 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> [63.165509] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI B/PHY B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [63.170139] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:171:pipe A]

<7> [63.170745] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe B]

<7> [63.170912] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe C]

<7> [63.171061] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:585:pipe D]

<7> [63.171211] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe B]

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

<7> [63.171345] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:588:HDMI-A-1] Limiting target display pipe bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36)

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

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

<7> [63.171866] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:587:DDI B/PHY B] [CRTC:309:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [63.180950] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:173:plane 1B] ddb ( 0 - 0) -> ( 0 - 1993), size 0 -> 1993

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

<7> [63.181306] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173: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> [63.181466] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173: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> [63.181623] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173: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> [63.181780] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173: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> [63.181954] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:309:pipe B] data rate 1142000 num active planes 1

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [63.185167] 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> [63.185364] 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> [63.185522] 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> [63.185680] 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> [63.185837] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

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

<7> [63.186175] 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> [63.186355] 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> [63.186512] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

<7> [63.186672] 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> [63.186827] 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> [63.186984] 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> [63.187173] 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> [63.187351] 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> [63.187510] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 285500, pixel rate 285500, min cdclk 192000, min voltage level 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [63.193478] 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> [63.193741] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI B/PHY B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [63.226037] 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> [63.226230] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000)

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

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

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

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

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

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

<7> [63.226904] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:309:pipe B]

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

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

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

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

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