igt@kms_flip@flip-vs-expired-vblank-interruptible@c-hdmi-a1 on shard-tglu@Patchwork

Detail	Value
Duration	5.91 seconds
Hostname	shard-tglu-6
Igt-Version	IGT-Version: 2.4-g4568b2c14 (x86_64) (Linux: 7.1.0-rc1-Patchwork_165420v2-gaea2c496abcf+ x86_64)
Out	Starting dynamic subtest: C-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:2220 __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 C-HDMI-A1: FAIL (5.914s)
Err	Starting dynamic subtest: C-HDMI-A1 (kms_flip:2174) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2174) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2174) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest C-HDMI-A1 failed. ** DEBUG (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.712875 last_received_ts = 190.712540 last_seq = 566 current_ts = 190.721207 current_received_ts = 190.720856 current_seq = 567 count = 562 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 25us (kms_flip:2174) DEBUG: name = flip last_ts = 190.721207 last_received_ts = 190.720856 last_seq = 567 current_ts = 190.729538 current_received_ts = 190.729248 current_seq = 568 count = 563 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.729538 last_received_ts = 190.729248 last_seq = 568 current_ts = 190.737885 current_received_ts = 190.737518 current_seq = 569 count = 564 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.737885 last_received_ts = 190.737518 last_seq = 569 current_ts = 190.746216 current_received_ts = 190.745850 current_seq = 570 count = 565 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 32us (kms_flip:2174) DEBUG: name = flip last_ts = 190.746216 last_received_ts = 190.745850 last_seq = 570 current_ts = 190.754547 current_received_ts = 190.754181 current_seq = 571 count = 566 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.754547 last_received_ts = 190.754181 last_seq = 571 current_ts = 190.762878 current_received_ts = 190.762543 current_seq = 572 count = 567 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 29us (kms_flip:2174) DEBUG: name = flip last_ts = 190.762878 last_received_ts = 190.762543 last_seq = 572 current_ts = 190.771210 current_received_ts = 190.770920 current_seq = 573 count = 568 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.771210 last_received_ts = 190.770920 last_seq = 573 current_ts = 190.779556 current_received_ts = 190.779205 current_seq = 574 count = 569 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.779556 last_received_ts = 190.779205 last_seq = 574 current_ts = 190.787888 current_received_ts = 190.787567 current_seq = 575 count = 570 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 34us (kms_flip:2174) DEBUG: name = flip last_ts = 190.787888 last_received_ts = 190.787567 last_seq = 575 current_ts = 190.796219 current_received_ts = 190.795898 current_seq = 576 count = 571 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 29us (kms_flip:2174) DEBUG: name = flip last_ts = 190.796219 last_received_ts = 190.795898 last_seq = 576 current_ts = 190.804550 current_received_ts = 190.804214 current_seq = 577 count = 572 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 190.804550 last_received_ts = 190.804214 last_seq = 577 current_ts = 190.812881 current_received_ts = 190.812531 current_seq = 578 count = 573 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.812881 last_received_ts = 190.812531 last_seq = 578 current_ts = 190.821213 current_received_ts = 190.820892 current_seq = 579 count = 574 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 190.821213 last_received_ts = 190.820892 last_seq = 579 current_ts = 190.829559 current_received_ts = 190.829239 current_seq = 580 count = 575 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 22us (kms_flip:2174) DEBUG: name = flip last_ts = 190.829559 last_received_ts = 190.829239 last_seq = 580 current_ts = 190.837891 current_received_ts = 190.837509 current_seq = 581 count = 576 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 33us (kms_flip:2174) DEBUG: name = flip last_ts = 190.837891 last_received_ts = 190.837509 last_seq = 581 current_ts = 190.846222 current_received_ts = 190.845901 current_seq = 582 count = 577 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 34us (kms_flip:2174) DEBUG: name = flip last_ts = 190.846222 last_received_ts = 190.845901 last_seq = 582 current_ts = 190.854553 current_received_ts = 190.854233 current_seq = 583 count = 578 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.854553 last_received_ts = 190.854233 last_seq = 583 current_ts = 190.862885 current_received_ts = 190.862625 current_seq = 584 count = 579 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 46us (kms_flip:2174) DEBUG: name = flip last_ts = 190.862885 last_received_ts = 190.862625 last_seq = 584 current_ts = 190.871231 current_received_ts = 190.870850 current_seq = 585 count = 580 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.871231 last_received_ts = 190.870850 last_seq = 585 current_ts = 190.879562 current_received_ts = 190.879227 current_seq = 586 count = 581 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.879562 last_received_ts = 190.879227 last_seq = 586 current_ts = 190.887894 current_received_ts = 190.887512 current_seq = 587 count = 582 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.887894 last_received_ts = 190.887512 last_seq = 587 current_ts = 190.896225 current_received_ts = 190.895874 current_seq = 588 count = 583 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 190.896225 last_received_ts = 190.895874 last_seq = 588 current_ts = 190.904572 current_received_ts = 190.904236 current_seq = 589 count = 584 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 25us (kms_flip:2174) DEBUG: name = flip last_ts = 190.904572 last_received_ts = 190.904236 last_seq = 589 current_ts = 190.912903 current_received_ts = 190.912552 current_seq = 590 count = 585 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 26us (kms_flip:2174) DEBUG: name = flip last_ts = 190.912903 last_received_ts = 190.912552 last_seq = 590 current_ts = 190.921234 current_received_ts = 190.920929 current_seq = 591 count = 586 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 34us (kms_flip:2174) DEBUG: name = flip last_ts = 190.921234 last_received_ts = 190.920929 last_seq = 591 current_ts = 190.929565 current_received_ts = 190.929230 current_seq = 592 count = 587 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 27us (kms_flip:2174) DEBUG: name = flip last_ts = 190.929565 last_received_ts = 190.929230 last_seq = 592 current_ts = 190.937912 current_received_ts = 190.937546 current_seq = 593 count = 588 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 34us (kms_flip:2174) DEBUG: name = flip last_ts = 190.937912 last_received_ts = 190.937546 last_seq = 593 current_ts = 190.946243 current_received_ts = 190.945892 current_seq = 594 count = 589 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 26us (kms_flip:2174) DEBUG: name = flip last_ts = 190.946243 last_received_ts = 190.945892 last_seq = 594 current_ts = 190.954575 current_received_ts = 190.954224 current_seq = 595 count = 590 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 190.954575 last_received_ts = 190.954224 last_seq = 595 current_ts = 190.962906 current_received_ts = 190.962570 current_seq = 596 count = 591 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 22us (kms_flip:2174) DEBUG: name = flip last_ts = 190.962906 last_received_ts = 190.962570 last_seq = 596 current_ts = 190.971237 current_received_ts = 190.970963 current_seq = 597 count = 592 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 54us (kms_flip:2174) DEBUG: name = flip last_ts = 190.971237 last_received_ts = 190.970963 last_seq = 597 current_ts = 190.979584 current_received_ts = 190.979263 current_seq = 598 count = 593 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 22us (kms_flip:2174) DEBUG: name = flip last_ts = 190.979584 last_received_ts = 190.979263 last_seq = 598 current_ts = 190.987915 current_received_ts = 190.987640 current_seq = 599 count = 594 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 25us (kms_flip:2174) DEBUG: name = flip last_ts = 190.987915 last_received_ts = 190.987640 last_seq = 599 current_ts = 190.996246 current_received_ts = 190.995911 current_seq = 600 count = 595 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 190.996246 last_received_ts = 190.995911 last_seq = 600 current_ts = 191.004578 current_received_ts = 191.004288 current_seq = 601 count = 596 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 35us (kms_flip:2174) DEBUG: name = flip last_ts = 191.004578 last_received_ts = 191.004288 last_seq = 601 current_ts = 191.012924 current_received_ts = 191.012589 current_seq = 602 count = 597 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.012924 last_received_ts = 191.012589 last_seq = 602 current_ts = 191.021255 current_received_ts = 191.020859 current_seq = 603 count = 598 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 26us (kms_flip:2174) DEBUG: name = flip last_ts = 191.021255 last_received_ts = 191.020859 last_seq = 603 current_ts = 191.029587 current_received_ts = 191.029297 current_seq = 604 count = 599 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 191.029587 last_received_ts = 191.029297 last_seq = 604 current_ts = 191.037918 current_received_ts = 191.037567 current_seq = 605 count = 600 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 29us (kms_flip:2174) DEBUG: name = flip last_ts = 191.037918 last_received_ts = 191.037567 last_seq = 605 current_ts = 191.046265 current_received_ts = 191.045944 current_seq = 606 count = 601 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 47us (kms_flip:2174) DEBUG: name = flip last_ts = 191.046265 last_received_ts = 191.045944 last_seq = 606 current_ts = 191.054596 current_received_ts = 191.054230 current_seq = 607 count = 602 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 22us (kms_flip:2174) DEBUG: name = flip last_ts = 191.054596 last_received_ts = 191.054230 last_seq = 607 current_ts = 191.062927 current_received_ts = 191.062607 current_seq = 608 count = 603 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 34us (kms_flip:2174) DEBUG: name = flip last_ts = 191.062927 last_received_ts = 191.062607 last_seq = 608 current_ts = 191.071259 current_received_ts = 191.070938 current_seq = 609 count = 604 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 51us (kms_flip:2174) DEBUG: name = flip last_ts = 191.071259 last_received_ts = 191.070938 last_seq = 609 current_ts = 191.079590 current_received_ts = 191.079254 current_seq = 610 count = 605 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 35us (kms_flip:2174) DEBUG: name = flip last_ts = 191.079590 last_received_ts = 191.079254 last_seq = 610 current_ts = 191.087921 current_received_ts = 191.087631 current_seq = 611 count = 606 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 35us (kms_flip:2174) DEBUG: name = flip last_ts = 191.087921 last_received_ts = 191.087631 last_seq = 611 current_ts = 191.096268 current_received_ts = 191.095917 current_seq = 612 count = 607 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 35us (kms_flip:2174) DEBUG: name = flip last_ts = 191.096268 last_received_ts = 191.095917 last_seq = 612 current_ts = 191.104599 current_received_ts = 191.104309 current_seq = 613 count = 608 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.104599 last_received_ts = 191.104309 last_seq = 613 current_ts = 191.112930 current_received_ts = 191.112579 current_seq = 614 count = 609 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.112930 last_received_ts = 191.112579 last_seq = 614 current_ts = 191.121262 current_received_ts = 191.120911 current_seq = 615 count = 610 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.121262 last_received_ts = 191.120911 last_seq = 615 current_ts = 191.129608 current_received_ts = 191.129211 current_seq = 616 count = 611 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 22us (kms_flip:2174) DEBUG: name = flip last_ts = 191.129608 last_received_ts = 191.129211 last_seq = 616 current_ts = 191.137939 current_received_ts = 191.137604 current_seq = 617 count = 612 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.137939 last_received_ts = 191.137604 last_seq = 617 current_ts = 191.146271 current_received_ts = 191.145889 current_seq = 618 count = 613 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 42us (kms_flip:2174) DEBUG: name = flip last_ts = 191.146271 last_received_ts = 191.145889 last_seq = 618 current_ts = 191.154602 current_received_ts = 191.154251 current_seq = 619 count = 614 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 25us (kms_flip:2174) DEBUG: name = flip last_ts = 191.154602 last_received_ts = 191.154251 last_seq = 619 current_ts = 191.162949 current_received_ts = 191.162598 current_seq = 620 count = 615 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 22us (kms_flip:2174) DEBUG: name = flip last_ts = 191.162949 last_received_ts = 191.162598 last_seq = 620 current_ts = 191.171280 current_received_ts = 191.170914 current_seq = 621 count = 616 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 22us (kms_flip:2174) DEBUG: name = flip last_ts = 191.171280 last_received_ts = 191.170914 last_seq = 621 current_ts = 191.179611 current_received_ts = 191.179306 current_seq = 622 count = 617 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.179611 last_received_ts = 191.179306 last_seq = 622 current_ts = 191.187943 current_received_ts = 191.187592 current_seq = 623 count = 618 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.187943 last_received_ts = 191.187592 last_seq = 623 current_ts = 191.196274 current_received_ts = 191.195938 current_seq = 624 count = 619 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 26us (kms_flip:2174) DEBUG: name = flip last_ts = 191.196274 last_received_ts = 191.195938 last_seq = 624 current_ts = 191.204605 current_received_ts = 191.204269 current_seq = 625 count = 620 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.204605 last_received_ts = 191.204269 last_seq = 625 current_ts = 191.212952 current_received_ts = 191.212570 current_seq = 626 count = 621 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 29us (kms_flip:2174) DEBUG: name = flip last_ts = 191.212952 last_received_ts = 191.212570 last_seq = 626 current_ts = 191.221283 current_received_ts = 191.220993 current_seq = 627 count = 622 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.221283 last_received_ts = 191.220993 last_seq = 627 current_ts = 191.229614 current_received_ts = 191.229263 current_seq = 628 count = 623 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 191.229614 last_received_ts = 191.229263 last_seq = 628 current_ts = 191.237961 current_received_ts = 191.237610 current_seq = 629 count = 624 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 29us (kms_flip:2174) DEBUG: name = flip last_ts = 191.237961 last_received_ts = 191.237610 last_seq = 629 current_ts = 191.246292 current_received_ts = 191.245941 current_seq = 630 count = 625 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.246292 last_received_ts = 191.245941 last_seq = 630 current_ts = 191.254623 current_received_ts = 191.254318 current_seq = 631 count = 626 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 191.254623 last_received_ts = 191.254318 last_seq = 631 current_ts = 191.262955 current_received_ts = 191.262589 current_seq = 632 count = 627 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.262955 last_received_ts = 191.262589 last_seq = 632 current_ts = 191.271286 current_received_ts = 191.270950 current_seq = 633 count = 628 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.271286 last_received_ts = 191.270950 last_seq = 633 current_ts = 191.279633 current_received_ts = 191.279282 current_seq = 634 count = 629 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.279633 last_received_ts = 191.279282 last_seq = 634 current_ts = 191.287964 current_received_ts = 191.287567 current_seq = 635 count = 630 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.287964 last_received_ts = 191.287567 last_seq = 635 current_ts = 191.296295 current_received_ts = 191.295959 current_seq = 636 count = 631 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.296295 last_received_ts = 191.295959 last_seq = 636 current_ts = 191.304626 current_received_ts = 191.304291 current_seq = 637 count = 632 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.304626 last_received_ts = 191.304291 last_seq = 637 current_ts = 191.312958 current_received_ts = 191.312637 current_seq = 638 count = 633 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.312958 last_received_ts = 191.312637 last_seq = 638 current_ts = 191.321304 current_received_ts = 191.320953 current_seq = 639 count = 634 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.321304 last_received_ts = 191.320953 last_seq = 639 current_ts = 191.329636 current_received_ts = 191.329330 current_seq = 640 count = 635 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.329636 last_received_ts = 191.329330 last_seq = 640 current_ts = 191.337967 current_received_ts = 191.337616 current_seq = 641 count = 636 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 191.337967 last_received_ts = 191.337616 last_seq = 641 current_ts = 191.346298 current_received_ts = 191.345947 current_seq = 642 count = 637 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 191.346298 last_received_ts = 191.345947 last_seq = 642 current_ts = 191.354630 current_received_ts = 191.354355 current_seq = 643 count = 638 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.354630 last_received_ts = 191.354355 last_seq = 643 current_ts = 191.362976 current_received_ts = 191.362625 current_seq = 644 count = 639 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.362976 last_received_ts = 191.362625 last_seq = 644 current_ts = 191.371307 current_received_ts = 191.371017 current_seq = 645 count = 640 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.371307 last_received_ts = 191.371017 last_seq = 645 current_ts = 191.379639 current_received_ts = 191.379272 current_seq = 646 count = 641 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 28us (kms_flip:2174) DEBUG: name = flip last_ts = 191.379639 last_received_ts = 191.379272 last_seq = 646 current_ts = 191.387985 current_received_ts = 191.387680 current_seq = 647 count = 642 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.387985 last_received_ts = 191.387680 last_seq = 647 current_ts = 191.396317 current_received_ts = 191.395966 current_seq = 648 count = 643 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 40us (kms_flip:2174) DEBUG: name = flip last_ts = 191.396317 last_received_ts = 191.395966 last_seq = 648 current_ts = 191.404648 current_received_ts = 191.404297 current_seq = 649 count = 644 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.404648 last_received_ts = 191.404297 last_seq = 649 current_ts = 191.412979 current_received_ts = 191.412643 current_seq = 650 count = 645 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.412979 last_received_ts = 191.412643 last_seq = 650 current_ts = 191.421310 current_received_ts = 191.420975 current_seq = 651 count = 646 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 45us (kms_flip:2174) DEBUG: name = flip last_ts = 191.421310 last_received_ts = 191.420975 last_seq = 651 current_ts = 191.429657 current_received_ts = 191.429291 current_seq = 652 count = 647 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.429657 last_received_ts = 191.429291 last_seq = 652 current_ts = 191.437988 current_received_ts = 191.437637 current_seq = 653 count = 648 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 30us (kms_flip:2174) DEBUG: name = flip last_ts = 191.437988 last_received_ts = 191.437637 last_seq = 653 current_ts = 191.446320 current_received_ts = 191.445984 current_seq = 654 count = 649 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 47us (kms_flip:2174) DEBUG: name = flip last_ts = 191.446320 last_received_ts = 191.445984 last_seq = 654 current_ts = 191.454651 current_received_ts = 191.454361 current_seq = 655 count = 650 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 22us (kms_flip:2174) DEBUG: name = flip last_ts = 191.454651 last_received_ts = 191.454361 last_seq = 655 current_ts = 191.462982 current_received_ts = 191.462601 current_seq = 656 count = 651 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.462982 last_received_ts = 191.462601 last_seq = 656 current_ts = 191.471329 current_received_ts = 191.470963 current_seq = 657 count = 652 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 41us (kms_flip:2174) DEBUG: name = flip last_ts = 191.471329 last_received_ts = 191.470963 last_seq = 657 current_ts = 191.479660 current_received_ts = 191.479340 current_seq = 658 count = 653 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.479660 last_received_ts = 191.479340 last_seq = 658 current_ts = 191.487991 current_received_ts = 191.487625 current_seq = 659 count = 654 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.487991 last_received_ts = 191.487625 last_seq = 659 current_ts = 191.496323 current_received_ts = 191.495972 current_seq = 660 count = 655 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 29us (kms_flip:2174) DEBUG: name = flip last_ts = 191.496323 last_received_ts = 191.495972 last_seq = 660 current_ts = 191.504669 current_received_ts = 191.504333 current_seq = 661 count = 656 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.504669 last_received_ts = 191.504333 last_seq = 661 current_ts = 191.513000 current_received_ts = 191.512665 current_seq = 662 count = 657 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 33us (kms_flip:2174) DEBUG: name = flip last_ts = 191.513000 last_received_ts = 191.512665 last_seq = 662 current_ts = 191.521332 current_received_ts = 191.521057 current_seq = 663 count = 658 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.521332 last_received_ts = 191.521057 last_seq = 663 current_ts = 191.529663 current_received_ts = 191.529297 current_seq = 664 count = 659 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.529663 last_received_ts = 191.529297 last_seq = 664 current_ts = 191.537994 current_received_ts = 191.537704 current_seq = 665 count = 660 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 191.537994 last_received_ts = 191.537704 last_seq = 665 current_ts = 191.546341 current_received_ts = 191.545975 current_seq = 666 count = 661 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 50us (kms_flip:2174) DEBUG: name = flip last_ts = 191.546341 last_received_ts = 191.545975 last_seq = 666 current_ts = 191.554672 current_received_ts = 191.554306 current_seq = 667 count = 662 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 191.554672 last_received_ts = 191.554306 last_seq = 667 current_ts = 191.563004 current_received_ts = 191.562653 current_seq = 668 count = 663 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 191.563004 last_received_ts = 191.562653 last_seq = 668 current_ts = 191.571335 current_received_ts = 191.570984 current_seq = 669 count = 664 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 43us (kms_flip:2174) DEBUG: name = flip last_ts = 191.571335 last_received_ts = 191.570984 last_seq = 669 current_ts = 191.579681 current_received_ts = 191.579376 current_seq = 670 count = 665 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.579681 last_received_ts = 191.579376 last_seq = 670 current_ts = 191.588013 current_received_ts = 191.587662 current_seq = 671 count = 666 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 26us (kms_flip:2174) DEBUG: name = flip last_ts = 191.588013 last_received_ts = 191.587662 last_seq = 671 current_ts = 191.596344 current_received_ts = 191.596024 current_seq = 672 count = 667 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.596344 last_received_ts = 191.596024 last_seq = 672 current_ts = 191.604675 current_received_ts = 191.604340 current_seq = 673 count = 668 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.604675 last_received_ts = 191.604340 last_seq = 673 current_ts = 191.613007 current_received_ts = 191.612732 current_seq = 674 count = 669 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.613007 last_received_ts = 191.612732 last_seq = 674 current_ts = 191.621353 current_received_ts = 191.621017 current_seq = 675 count = 670 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 27us (kms_flip:2174) DEBUG: name = flip last_ts = 191.621353 last_received_ts = 191.621017 last_seq = 675 current_ts = 191.629669 current_received_ts = 191.629379 current_seq = 676 count = 671 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.629669 last_received_ts = 191.629379 last_seq = 676 current_ts = 191.638016 current_received_ts = 191.637665 current_seq = 677 count = 672 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 29us (kms_flip:2174) DEBUG: name = flip last_ts = 191.638016 last_received_ts = 191.637665 last_seq = 677 current_ts = 191.646347 current_received_ts = 191.645996 current_seq = 678 count = 673 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 191.646347 last_received_ts = 191.645996 last_seq = 678 current_ts = 191.654678 current_received_ts = 191.654327 current_seq = 679 count = 674 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.654678 last_received_ts = 191.654327 last_seq = 679 current_ts = 191.663010 current_received_ts = 191.662659 current_seq = 680 count = 675 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 25us (kms_flip:2174) DEBUG: name = flip last_ts = 191.663010 last_received_ts = 191.662659 last_seq = 680 current_ts = 191.671356 current_received_ts = 191.671066 current_seq = 681 count = 676 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.671356 last_received_ts = 191.671066 last_seq = 681 current_ts = 191.679688 current_received_ts = 191.679291 current_seq = 682 count = 677 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.679688 last_received_ts = 191.679291 last_seq = 682 current_ts = 191.688019 current_received_ts = 191.687683 current_seq = 683 count = 678 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 34us (kms_flip:2174) DEBUG: name = flip last_ts = 191.688019 last_received_ts = 191.687683 last_seq = 683 current_ts = 191.696365 current_received_ts = 191.695999 current_seq = 684 count = 679 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 24us (kms_flip:2174) DEBUG: name = flip last_ts = 191.696365 last_received_ts = 191.695999 last_seq = 684 current_ts = 191.704697 current_received_ts = 191.704361 current_seq = 685 count = 680 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 29us (kms_flip:2174) DEBUG: name = flip last_ts = 191.704697 last_received_ts = 191.704361 last_seq = 685 current_ts = 191.713028 current_received_ts = 191.712662 current_seq = 686 count = 681 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 23us (kms_flip:2174) DEBUG: name = flip last_ts = 191.713028 last_received_ts = 191.712662 last_seq = 686 current_ts = 191.721359 current_received_ts = 191.720978 current_seq = 687 count = 682 seq_step = 1 (kms_flip:2174) DEBUG: Vblank took 528us (kms_flip:2174) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2174) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2174) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:2174) igt_core-INFO: Stack trace: (kms_flip:2174) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2174) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:2174) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:2174) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() (kms_flip:2174) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:2174) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2174) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2174) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest C-HDMI-A1: FAIL (5.914s)
Dmesg	<6> [186.235691] [IGT] kms_flip: starting dynamic subtest C-HDMI-A1 <7> [186.236777] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:637] <7> [186.237111] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:638] <7> [186.261782] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:171:pipe A] <7> [186.262042] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe B] <7> [186.262141] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [186.262343] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [186.262509] 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> [186.262672] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in lane_count (expected 4, found 0) <7> [186.262837] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [186.263022] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [186.263216] 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 1920, found 0) <7> [186.263378] 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 2080, found 0) <7> [186.263537] 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 1920, found 0) <7> [186.263697] 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 2080, found 0) <7> [186.263861] 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 1968, found 0) <7> [186.264042] 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 2000, found 0) <7> [186.264221] 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 1080, found 0) <7> [186.264386] 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 1080, found 0) <7> [186.264549] 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 1083, found 0) <7> [186.264709] 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 1088, found 0) <7> [186.264888] 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 1144, found 0) <7> [186.265066] 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 1144, found 0) <7> [186.265226] 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 1920, found 0) <7> [186.265385] 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 2080, found 0) <7> [186.265544] 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 1920, found 0) <7> [186.265702] 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 2080, found 0) <7> [186.265860] 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 1968, found 0) <7> [186.266045] 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 2000, found 0) <7> [186.266230] 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 1080, found 0) <7> [186.266387] 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 1080, found 0) <7> [186.266545] 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 1083, found 0) <7> [186.266702] 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 1088, found 0) <7> [186.266860] 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 1144, found 0) <7> [186.267039] 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 1144, found 0) <7> [186.267219] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [186.267376] 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 1, found 0) <7> [186.267535] 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 4, found 0) <7> [186.267691] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [186.267849] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in has_infoframe (expected yes, found no) <7> [186.268027] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [186.268211] 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 285500, found 0) <7> [186.268370] 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 285500, found 0) <7> [186.268528] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in port_clock (expected 285500, found 0) <7> [186.268684] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [186.268843] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in avi infoframe <7> [186.269019] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [186.269202] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [186.269204] i915 0000:00:02.0: colorspace: RGB <7> [186.269206] i915 0000:00:02.0: scan mode: Underscan <7> [186.269207] i915 0000:00:02.0: colorimetry: No Data <7> [186.269209] i915 0000:00:02.0: picture aspect: No Data <7> [186.269210] i915 0000:00:02.0: active aspect: Same as Picture <7> [186.269212] i915 0000:00:02.0: itc: No Data <7> [186.269213] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [186.269214] i915 0000:00:02.0: quantization range: Full <7> [186.269216] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [186.269217] i915 0000:00:02.0: video code: 0 <7> [186.269219] i915 0000:00:02.0: ycc quantization range: Full <7> [186.269220] i915 0000:00:02.0: hdmi content type: Graphics <7> [186.269221] i915 0000:00:02.0: pixel repeat: 0 <7> [186.269223] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [186.269224] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [186.269401] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in spd infoframe <7> [186.269558] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [186.269715] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [186.269717] i915 0000:00:02.0: vendor: Intel <7> [186.269718] i915 0000:00:02.0: product: Integrated gfx <7> [186.269720] i915 0000:00:02.0: source device information: PC General (0x9) <7> [186.269721] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [186.269887] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hdmi infoframe <7> [186.270064] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [186.270222] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [186.270224] i915 0000:00:02.0: empty frame <7> [186.270225] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [186.270383] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe B] fastset requirement not met, forcing full modeset <7> [186.270543] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:309:pipe B] releasing DPLL 0 <7> [186.270733] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no <7> [186.270902] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:309:pipe B] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x2 -> 0x0 <7> [186.271125] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:303:cursor B] ddb (1993 - 2048) -> ( 0 - 0), size 55 -> 0 <7> [186.271304] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:309:pipe B] min cdclk: 192000 kHz -> 0 kHz <7> [186.271496] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [186.271659] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz <7> [186.271819] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [186.271998] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:309:pipe B] enable: no [modeset] <7> [186.272185] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:173:plane 1B] fb: [NOFB], visible: no <7> [186.272347] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:203:plane 2B] fb: [NOFB], visible: no <7> [186.272508] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:233:plane 3B] fb: [NOFB], visible: no <7> [186.272668] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:263:plane 4B] fb: [NOFB], visible: no <7> [186.272828] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:273:plane 5B] fb: [NOFB], visible: no <7> [186.273005] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:283:plane 6B] fb: [NOFB], visible: no <7> [186.273185] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:293:plane 7B] fb: [NOFB], visible: no <7> [186.273344] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:303:cursor B] fb: [NOFB], visible: no <7> [186.273583] 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:309:pipe B] <7> [186.283854] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [186.285887] 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> [186.286525] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [186.286680] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [186.287288] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [186.287447] 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> [186.287464] 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> [186.287643] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B <7> [186.292909] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [186.293115] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x2, on? 1) for [CRTC:309:pipe B] <7> [186.293308] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0 <7> [186.293485] 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> [186.293742] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI B/PHY B] <7> [186.293941] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DDI TC1/PHY TC1] <7> [186.294135] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST A] <7> [186.294296] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST B] <7> [186.294457] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST C] <7> [186.294617] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:602:DP-MST D] <7> [186.294778] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DDI TC2/PHY TC2] <7> [186.294953] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST A] <7> [186.295137] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST B] <7> [186.295298] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST C] <7> [186.295458] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST D] <7> [186.295615] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DDI TC3/PHY TC3] <7> [186.295774] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST A] <7> [186.295952] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST B] <7> [186.296127] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST C] <7> [186.296283] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:621:DP-MST D] <7> [186.296438] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DDI TC4/PHY TC4] <7> [186.296594] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST A] <7> [186.296751] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST B] <7> [186.296922] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST C] <7> [186.297134] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:630:DP-MST D] <7> [186.297349] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:588:HDMI-A-1] <7> [186.297840] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [186.298175] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_3 <7> [186.298432] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [186.298698] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:309:pipe B] <7> [186.299404] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe C] <7> [186.299678] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:585:pipe D] <7> [186.299938] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe C] <7> [186.299989] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:588:HDMI-A-1] <7> [186.300099] 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> [186.300360] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [186.300590] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:447:pipe C] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [186.300831] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:587:DDI B/PHY B] [CRTC:447:pipe C] <7> [186.301091] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [186.301340] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [186.301581] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [186.301810] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [186.302056] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [186.302283] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [186.302508] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [186.302742] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2080) <7> [186.302986] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [186.303206] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2080) <7> [186.303437] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1968) <7> [186.303661] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2000) <7> [186.303896] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [186.304127] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [186.304361] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [186.304585] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [186.304803] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1144) <7> [186.305048] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1144) <7> [186.305268] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [186.305498] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2080) <7> [186.305727] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [186.306091] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2080) <7> [186.306332] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1968) <7> [186.306564] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2000) <7> [186.306791] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [186.307038] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [186.307271] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [186.307493] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [186.307718] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1144) <7> [186.307950] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1144) <7> [186.308178] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [186.308410] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [186.308648] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [186.308891] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [186.309126] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in has_infoframe (expected no, found yes) <7> [186.309365] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in dpll_hw_state <7> [186.309596] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [186.309822] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: cfgcr0: 0x0, cfgcr1: 0x0, 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> [186.310069] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [186.310304] i915 0000:00:02.0: [drm:intel_pipe_config_compare [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> [186.310529] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [186.310752] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 285500) <7> [186.310978] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 285500) <7> [186.311172] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in port_clock (expected 0, found 285500) <7> [186.311369] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [186.311576] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in avi infoframe <7> [186.311812] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [186.312053] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [186.312277] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [186.312280] i915 0000:00:02.0: colorspace: RGB <7> [186.312283] i915 0000:00:02.0: scan mode: Underscan <7> [186.312286] i915 0000:00:02.0: colorimetry: No Data <7> [186.312289] i915 0000:00:02.0: picture aspect: No Data <7> [186.312291] i915 0000:00:02.0: active aspect: Same as Picture <7> [186.312293] i915 0000:00:02.0: itc: No Data <7> [186.312295] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [186.312297] i915 0000:00:02.0: quantization range: Full <7> [186.312299] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [186.312301] i915 0000:00:02.0: video code: 0 <7> [186.312304] i915 0000:00:02.0: ycc quantization range: Full <7> [186.312306] i915 0000:00:02.0: hdmi content type: Graphics <7> [186.312309] i915 0000:00:02.0: pixel repeat: 0 <7> [186.312312] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [186.312315] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in spd infoframe <7> [186.312546] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [186.312775] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [186.313018] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [186.313022] i915 0000:00:02.0: vendor: Intel <7> [186.313024] i915 0000:00:02.0: product: Integrated gfx <7> [186.313027] i915 0000:00:02.0: source device information: PC General (0x9) <7> [186.313030] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hdmi infoframe <7> [186.313256] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [186.313480] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [186.313705] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [186.313708] i915 0000:00:02.0: empty frame <7> [186.313712] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:447:pipe C] fastset requirement not met, forcing full modeset <7> [186.314004] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no <7> [186.314238] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:447:pipe C] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4 <7> [186.314534] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:311:plane 1C] ddb ( 0 - 0) -> ( 0 - 1993), size 0 -> 1993 <7> [186.314745] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:441:cursor C] ddb ( 0 - 0) -> (1993 - 2048), size 0 -> 55 <7> [186.314980] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,*twm, swm, stwm <7> [186.315193] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 8, 8, 8, 8, 11, 16, 16, 0, 0, 0 <7> [186.315420] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 129, 129, 129, 129, 177, 257, 257, 30, 0, 0 <7> [186.315629] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] 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> [186.315917] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:447:pipe C] data rate 1142000 num active planes 1 <7> [186.316148] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 14993 required 1142 <7> [186.316374] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [186.316636] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:447:pipe C] min cdclk: 0 kHz -> 192000 kHz <7> [186.316945] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [186.317170] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [186.317405] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [186.317648] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:447:pipe C] allocated DPLL 0 <7> [186.317896] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:447:pipe C] reserving DPLL 0 <7> [186.317927] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off <7> [186.318130] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:447:pipe C] enable: yes [modeset] <7> [186.318272] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6 <7> [186.318359] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [186.318446] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02 <7> [186.318596] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: C, pipe bpp: 24, dithering: 0 <7> [186.318837] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [186.319092] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [186.319318] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [186.319550] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [186.319636] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on <7> [186.319776] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [186.320025] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x0 <7> [186.320261] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [186.320264] i915 0000:00:02.0: colorspace: RGB <7> [186.320267] i915 0000:00:02.0: scan mode: Underscan <7> [186.320270] i915 0000:00:02.0: colorimetry: No Data <7> [186.320273] i915 0000:00:02.0: picture aspect: No Data <7> [186.320276] i915 0000:00:02.0: active aspect: Same as Picture <7> [186.320279] i915 0000:00:02.0: itc: No Data <7> [186.320282] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [186.320284] i915 0000:00:02.0: quantization range: Full <7> [186.320287] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [186.320290] i915 0000:00:02.0: video code: 0 <7> [186.320293] i915 0000:00:02.0: ycc quantization range: Full <7> [186.320295] i915 0000:00:02.0: hdmi content type: Graphics <7> [186.320298] i915 0000:00:02.0: pixel repeat: 0 <7> [186.320301] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [186.320304] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [186.320307] i915 0000:00:02.0: vendor: Intel <7> [186.320310] i915 0000:00:02.0: product: Integrated gfx <7> [186.320313] i915 0000:00:02.0: source device information: PC General (0x9) <7> [186.320316] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [186.320319] i915 0000:00:02.0: empty frame <7> [186.320322] 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> [186.320554] 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> [186.320773] 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> [186.321012] 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> [186.321242] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [186.321472] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [186.321705] 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> [186.321951] 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> [186.322176] 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> [186.322398] 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> [186.322631] 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> [186.322859] 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> [186.323110] 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> [186.323347] 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> [186.323583] 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> [186.323802] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [186.324042] 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> [186.324265] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [186.324496] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [186.324723] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [186.324962] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [186.325186] 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> [186.325418] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [186.325649] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [186.325892] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [186.326124] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [186.326353] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [186.326579] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [186.326755] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [186.326931] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [186.327117] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [186.327278] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [186.327438] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [186.327597] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [186.327757] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:311:plane 1C] fb: [FB:637] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [186.327933] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [186.328118] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [186.328279] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:341:plane 2C] fb: [NOFB], visible: no <7> [186.328438] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:371:plane 3C] fb: [NOFB], visible: no <7> [186.328596] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:401:plane 4C] fb: [NOFB], visible: no <7> [186.328755] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:411:plane 5C] fb: [NOFB], visible: no <7> [186.328932] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:421:plane 6C] fb: [NOFB], visible: no <7> [186.329110] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:431:plane 7C] fb: [NOFB], visible: no <7> [186.329270] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:441:cursor C] fb: [NOFB], visible: no <7> [186.330021] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on <7> [186.330263] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off <7> [186.330996] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00 <7> [186.332188] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [186.332364] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_3 <7> [186.332545] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_4 <7> [186.332743] 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> [186.333024] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI B/PHY B] <7> [186.333192] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DDI TC1/PHY TC1] <7> [186.333354] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST A] <7> [186.333515] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST B] <7> [186.333675] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST C] <7> [186.333834] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:602:DP-MST D] <7> [186.334011] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DDI TC2/PHY TC2] <7> [186.334190] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST A] <7> [186.334348] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST B] <7> [186.334508] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST C] <7> [186.334667] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST D] <7> [186.334828] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DDI TC3/PHY TC3] <7> [186.335010] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST A] <7> [186.335190] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST B] <7> [186.335348] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST C] <7> [186.335506] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:621:DP-MST D] <7> [186.335664] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DDI TC4/PHY TC4] <7> [186.335822] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST A] <7> [186.336044] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST B] <7> [186.336261] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST C] <7> [186.336419] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:630:DP-MST D] <7> [186.336703] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [186.336918] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x4, on? 0) for [CRTC:447:pipe C] <7> [186.337104] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0 <7> [186.337338] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B <7> [186.337582] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe C <7> [186.338302] 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> [186.338974] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [186.339136] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [186.339757] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [186.339921] 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> [186.339938] 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> [186.343390] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x810 <7> [186.347912] azx_init_pci: snd_hda_intel 0000:00:1f.3: Clearing TCSEL <7> [186.347955] azx_init_pci: snd_hda_intel 0000:00:1f.3: SCH snoop: Enabled <7> [186.348584] 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:447:pipe C], 64 bytes ELD <7> [186.356950] 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> [186.357147] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000) <7> [186.357309] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <6> [186.357475] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 5 not expected <6> [186.357477] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 0 not expected <6> [186.357479] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 10 not expected <6> [186.357480] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 6 not expected <7> [186.357620] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:588:HDMI-A-1] <7> [186.357885] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:447:pipe C] <6> [192.152191] [IGT] kms_flip: finished subtest C-HDMI-A1, FAIL

Detail

Value

Duration

5.91 seconds

Hostname

shard-tglu-6

Igt-Version

IGT-Version: 2.4-g4568b2c14 (x86_64) (Linux: 7.1.0-rc1-Patchwork_165420v2-gaea2c496abcf+ x86_64)

Out

Starting dynamic subtest: C-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:2220 __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 C-HDMI-A1: FAIL (5.914s)

Err

Starting dynamic subtest: C-HDMI-A1
(kms_flip:2174) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2174) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2174) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.712875
last_received_ts = 190.712540
last_seq = 566
current_ts = 190.721207
current_received_ts = 190.720856
current_seq = 567
count = 562
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 25us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.721207
last_received_ts = 190.720856
last_seq = 567
current_ts = 190.729538
current_received_ts = 190.729248
current_seq = 568
count = 563
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.729538
last_received_ts = 190.729248
last_seq = 568
current_ts = 190.737885
current_received_ts = 190.737518
current_seq = 569
count = 564
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.737885
last_received_ts = 190.737518
last_seq = 569
current_ts = 190.746216
current_received_ts = 190.745850
current_seq = 570
count = 565
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 32us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.746216
last_received_ts = 190.745850
last_seq = 570
current_ts = 190.754547
current_received_ts = 190.754181
current_seq = 571
count = 566
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.754547
last_received_ts = 190.754181
last_seq = 571
current_ts = 190.762878
current_received_ts = 190.762543
current_seq = 572
count = 567
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 29us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.762878
last_received_ts = 190.762543
last_seq = 572
current_ts = 190.771210
current_received_ts = 190.770920
current_seq = 573
count = 568
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.771210
last_received_ts = 190.770920
last_seq = 573
current_ts = 190.779556
current_received_ts = 190.779205
current_seq = 574
count = 569
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.779556
last_received_ts = 190.779205
last_seq = 574
current_ts = 190.787888
current_received_ts = 190.787567
current_seq = 575
count = 570
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 34us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.787888
last_received_ts = 190.787567
last_seq = 575
current_ts = 190.796219
current_received_ts = 190.795898
current_seq = 576
count = 571
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 29us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.796219
last_received_ts = 190.795898
last_seq = 576
current_ts = 190.804550
current_received_ts = 190.804214
current_seq = 577
count = 572
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.804550
last_received_ts = 190.804214
last_seq = 577
current_ts = 190.812881
current_received_ts = 190.812531
current_seq = 578
count = 573
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.812881
last_received_ts = 190.812531
last_seq = 578
current_ts = 190.821213
current_received_ts = 190.820892
current_seq = 579
count = 574
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.821213
last_received_ts = 190.820892
last_seq = 579
current_ts = 190.829559
current_received_ts = 190.829239
current_seq = 580
count = 575
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 22us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.829559
last_received_ts = 190.829239
last_seq = 580
current_ts = 190.837891
current_received_ts = 190.837509
current_seq = 581
count = 576
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 33us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.837891
last_received_ts = 190.837509
last_seq = 581
current_ts = 190.846222
current_received_ts = 190.845901
current_seq = 582
count = 577
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 34us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.846222
last_received_ts = 190.845901
last_seq = 582
current_ts = 190.854553
current_received_ts = 190.854233
current_seq = 583
count = 578
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.854553
last_received_ts = 190.854233
last_seq = 583
current_ts = 190.862885
current_received_ts = 190.862625
current_seq = 584
count = 579
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 46us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.862885
last_received_ts = 190.862625
last_seq = 584
current_ts = 190.871231
current_received_ts = 190.870850
current_seq = 585
count = 580
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.871231
last_received_ts = 190.870850
last_seq = 585
current_ts = 190.879562
current_received_ts = 190.879227
current_seq = 586
count = 581
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.879562
last_received_ts = 190.879227
last_seq = 586
current_ts = 190.887894
current_received_ts = 190.887512
current_seq = 587
count = 582
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.887894
last_received_ts = 190.887512
last_seq = 587
current_ts = 190.896225
current_received_ts = 190.895874
current_seq = 588
count = 583
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.896225
last_received_ts = 190.895874
last_seq = 588
current_ts = 190.904572
current_received_ts = 190.904236
current_seq = 589
count = 584
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 25us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.904572
last_received_ts = 190.904236
last_seq = 589
current_ts = 190.912903
current_received_ts = 190.912552
current_seq = 590
count = 585
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 26us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.912903
last_received_ts = 190.912552
last_seq = 590
current_ts = 190.921234
current_received_ts = 190.920929
current_seq = 591
count = 586
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 34us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.921234
last_received_ts = 190.920929
last_seq = 591
current_ts = 190.929565
current_received_ts = 190.929230
current_seq = 592
count = 587
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 27us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.929565
last_received_ts = 190.929230
last_seq = 592
current_ts = 190.937912
current_received_ts = 190.937546
current_seq = 593
count = 588
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 34us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.937912
last_received_ts = 190.937546
last_seq = 593
current_ts = 190.946243
current_received_ts = 190.945892
current_seq = 594
count = 589
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 26us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.946243
last_received_ts = 190.945892
last_seq = 594
current_ts = 190.954575
current_received_ts = 190.954224
current_seq = 595
count = 590
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.954575
last_received_ts = 190.954224
last_seq = 595
current_ts = 190.962906
current_received_ts = 190.962570
current_seq = 596
count = 591
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 22us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.962906
last_received_ts = 190.962570
last_seq = 596
current_ts = 190.971237
current_received_ts = 190.970963
current_seq = 597
count = 592
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 54us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.971237
last_received_ts = 190.970963
last_seq = 597
current_ts = 190.979584
current_received_ts = 190.979263
current_seq = 598
count = 593
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 22us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.979584
last_received_ts = 190.979263
last_seq = 598
current_ts = 190.987915
current_received_ts = 190.987640
current_seq = 599
count = 594
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 25us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.987915
last_received_ts = 190.987640
last_seq = 599
current_ts = 190.996246
current_received_ts = 190.995911
current_seq = 600
count = 595
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 190.996246
last_received_ts = 190.995911
last_seq = 600
current_ts = 191.004578
current_received_ts = 191.004288
current_seq = 601
count = 596
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 35us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.004578
last_received_ts = 191.004288
last_seq = 601
current_ts = 191.012924
current_received_ts = 191.012589
current_seq = 602
count = 597
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.012924
last_received_ts = 191.012589
last_seq = 602
current_ts = 191.021255
current_received_ts = 191.020859
current_seq = 603
count = 598
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 26us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.021255
last_received_ts = 191.020859
last_seq = 603
current_ts = 191.029587
current_received_ts = 191.029297
current_seq = 604
count = 599
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.029587
last_received_ts = 191.029297
last_seq = 604
current_ts = 191.037918
current_received_ts = 191.037567
current_seq = 605
count = 600
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 29us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.037918
last_received_ts = 191.037567
last_seq = 605
current_ts = 191.046265
current_received_ts = 191.045944
current_seq = 606
count = 601
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 47us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.046265
last_received_ts = 191.045944
last_seq = 606
current_ts = 191.054596
current_received_ts = 191.054230
current_seq = 607
count = 602
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 22us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.054596
last_received_ts = 191.054230
last_seq = 607
current_ts = 191.062927
current_received_ts = 191.062607
current_seq = 608
count = 603
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 34us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.062927
last_received_ts = 191.062607
last_seq = 608
current_ts = 191.071259
current_received_ts = 191.070938
current_seq = 609
count = 604
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 51us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.071259
last_received_ts = 191.070938
last_seq = 609
current_ts = 191.079590
current_received_ts = 191.079254
current_seq = 610
count = 605
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 35us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.079590
last_received_ts = 191.079254
last_seq = 610
current_ts = 191.087921
current_received_ts = 191.087631
current_seq = 611
count = 606
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 35us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.087921
last_received_ts = 191.087631
last_seq = 611
current_ts = 191.096268
current_received_ts = 191.095917
current_seq = 612
count = 607
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 35us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.096268
last_received_ts = 191.095917
last_seq = 612
current_ts = 191.104599
current_received_ts = 191.104309
current_seq = 613
count = 608
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.104599
last_received_ts = 191.104309
last_seq = 613
current_ts = 191.112930
current_received_ts = 191.112579
current_seq = 614
count = 609
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.112930
last_received_ts = 191.112579
last_seq = 614
current_ts = 191.121262
current_received_ts = 191.120911
current_seq = 615
count = 610
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.121262
last_received_ts = 191.120911
last_seq = 615
current_ts = 191.129608
current_received_ts = 191.129211
current_seq = 616
count = 611
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 22us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.129608
last_received_ts = 191.129211
last_seq = 616
current_ts = 191.137939
current_received_ts = 191.137604
current_seq = 617
count = 612
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.137939
last_received_ts = 191.137604
last_seq = 617
current_ts = 191.146271
current_received_ts = 191.145889
current_seq = 618
count = 613
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 42us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.146271
last_received_ts = 191.145889
last_seq = 618
current_ts = 191.154602
current_received_ts = 191.154251
current_seq = 619
count = 614
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 25us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.154602
last_received_ts = 191.154251
last_seq = 619
current_ts = 191.162949
current_received_ts = 191.162598
current_seq = 620
count = 615
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 22us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.162949
last_received_ts = 191.162598
last_seq = 620
current_ts = 191.171280
current_received_ts = 191.170914
current_seq = 621
count = 616
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 22us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.171280
last_received_ts = 191.170914
last_seq = 621
current_ts = 191.179611
current_received_ts = 191.179306
current_seq = 622
count = 617
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.179611
last_received_ts = 191.179306
last_seq = 622
current_ts = 191.187943
current_received_ts = 191.187592
current_seq = 623
count = 618
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.187943
last_received_ts = 191.187592
last_seq = 623
current_ts = 191.196274
current_received_ts = 191.195938
current_seq = 624
count = 619
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 26us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.196274
last_received_ts = 191.195938
last_seq = 624
current_ts = 191.204605
current_received_ts = 191.204269
current_seq = 625
count = 620
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.204605
last_received_ts = 191.204269
last_seq = 625
current_ts = 191.212952
current_received_ts = 191.212570
current_seq = 626
count = 621
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 29us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.212952
last_received_ts = 191.212570
last_seq = 626
current_ts = 191.221283
current_received_ts = 191.220993
current_seq = 627
count = 622
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.221283
last_received_ts = 191.220993
last_seq = 627
current_ts = 191.229614
current_received_ts = 191.229263
current_seq = 628
count = 623
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.229614
last_received_ts = 191.229263
last_seq = 628
current_ts = 191.237961
current_received_ts = 191.237610
current_seq = 629
count = 624
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 29us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.237961
last_received_ts = 191.237610
last_seq = 629
current_ts = 191.246292
current_received_ts = 191.245941
current_seq = 630
count = 625
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.246292
last_received_ts = 191.245941
last_seq = 630
current_ts = 191.254623
current_received_ts = 191.254318
current_seq = 631
count = 626
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.254623
last_received_ts = 191.254318
last_seq = 631
current_ts = 191.262955
current_received_ts = 191.262589
current_seq = 632
count = 627
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.262955
last_received_ts = 191.262589
last_seq = 632
current_ts = 191.271286
current_received_ts = 191.270950
current_seq = 633
count = 628
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.271286
last_received_ts = 191.270950
last_seq = 633
current_ts = 191.279633
current_received_ts = 191.279282
current_seq = 634
count = 629
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.279633
last_received_ts = 191.279282
last_seq = 634
current_ts = 191.287964
current_received_ts = 191.287567
current_seq = 635
count = 630
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.287964
last_received_ts = 191.287567
last_seq = 635
current_ts = 191.296295
current_received_ts = 191.295959
current_seq = 636
count = 631
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.296295
last_received_ts = 191.295959
last_seq = 636
current_ts = 191.304626
current_received_ts = 191.304291
current_seq = 637
count = 632
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.304626
last_received_ts = 191.304291
last_seq = 637
current_ts = 191.312958
current_received_ts = 191.312637
current_seq = 638
count = 633
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.312958
last_received_ts = 191.312637
last_seq = 638
current_ts = 191.321304
current_received_ts = 191.320953
current_seq = 639
count = 634
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.321304
last_received_ts = 191.320953
last_seq = 639
current_ts = 191.329636
current_received_ts = 191.329330
current_seq = 640
count = 635
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.329636
last_received_ts = 191.329330
last_seq = 640
current_ts = 191.337967
current_received_ts = 191.337616
current_seq = 641
count = 636
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.337967
last_received_ts = 191.337616
last_seq = 641
current_ts = 191.346298
current_received_ts = 191.345947
current_seq = 642
count = 637
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.346298
last_received_ts = 191.345947
last_seq = 642
current_ts = 191.354630
current_received_ts = 191.354355
current_seq = 643
count = 638
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.354630
last_received_ts = 191.354355
last_seq = 643
current_ts = 191.362976
current_received_ts = 191.362625
current_seq = 644
count = 639
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.362976
last_received_ts = 191.362625
last_seq = 644
current_ts = 191.371307
current_received_ts = 191.371017
current_seq = 645
count = 640
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.371307
last_received_ts = 191.371017
last_seq = 645
current_ts = 191.379639
current_received_ts = 191.379272
current_seq = 646
count = 641
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 28us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.379639
last_received_ts = 191.379272
last_seq = 646
current_ts = 191.387985
current_received_ts = 191.387680
current_seq = 647
count = 642
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.387985
last_received_ts = 191.387680
last_seq = 647
current_ts = 191.396317
current_received_ts = 191.395966
current_seq = 648
count = 643
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 40us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.396317
last_received_ts = 191.395966
last_seq = 648
current_ts = 191.404648
current_received_ts = 191.404297
current_seq = 649
count = 644
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.404648
last_received_ts = 191.404297
last_seq = 649
current_ts = 191.412979
current_received_ts = 191.412643
current_seq = 650
count = 645
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.412979
last_received_ts = 191.412643
last_seq = 650
current_ts = 191.421310
current_received_ts = 191.420975
current_seq = 651
count = 646
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 45us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.421310
last_received_ts = 191.420975
last_seq = 651
current_ts = 191.429657
current_received_ts = 191.429291
current_seq = 652
count = 647
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.429657
last_received_ts = 191.429291
last_seq = 652
current_ts = 191.437988
current_received_ts = 191.437637
current_seq = 653
count = 648
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 30us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.437988
last_received_ts = 191.437637
last_seq = 653
current_ts = 191.446320
current_received_ts = 191.445984
current_seq = 654
count = 649
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 47us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.446320
last_received_ts = 191.445984
last_seq = 654
current_ts = 191.454651
current_received_ts = 191.454361
current_seq = 655
count = 650
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 22us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.454651
last_received_ts = 191.454361
last_seq = 655
current_ts = 191.462982
current_received_ts = 191.462601
current_seq = 656
count = 651
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.462982
last_received_ts = 191.462601
last_seq = 656
current_ts = 191.471329
current_received_ts = 191.470963
current_seq = 657
count = 652
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 41us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.471329
last_received_ts = 191.470963
last_seq = 657
current_ts = 191.479660
current_received_ts = 191.479340
current_seq = 658
count = 653
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.479660
last_received_ts = 191.479340
last_seq = 658
current_ts = 191.487991
current_received_ts = 191.487625
current_seq = 659
count = 654
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.487991
last_received_ts = 191.487625
last_seq = 659
current_ts = 191.496323
current_received_ts = 191.495972
current_seq = 660
count = 655
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 29us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.496323
last_received_ts = 191.495972
last_seq = 660
current_ts = 191.504669
current_received_ts = 191.504333
current_seq = 661
count = 656
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.504669
last_received_ts = 191.504333
last_seq = 661
current_ts = 191.513000
current_received_ts = 191.512665
current_seq = 662
count = 657
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 33us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.513000
last_received_ts = 191.512665
last_seq = 662
current_ts = 191.521332
current_received_ts = 191.521057
current_seq = 663
count = 658
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.521332
last_received_ts = 191.521057
last_seq = 663
current_ts = 191.529663
current_received_ts = 191.529297
current_seq = 664
count = 659
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.529663
last_received_ts = 191.529297
last_seq = 664
current_ts = 191.537994
current_received_ts = 191.537704
current_seq = 665
count = 660
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.537994
last_received_ts = 191.537704
last_seq = 665
current_ts = 191.546341
current_received_ts = 191.545975
current_seq = 666
count = 661
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 50us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.546341
last_received_ts = 191.545975
last_seq = 666
current_ts = 191.554672
current_received_ts = 191.554306
current_seq = 667
count = 662
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.554672
last_received_ts = 191.554306
last_seq = 667
current_ts = 191.563004
current_received_ts = 191.562653
current_seq = 668
count = 663
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.563004
last_received_ts = 191.562653
last_seq = 668
current_ts = 191.571335
current_received_ts = 191.570984
current_seq = 669
count = 664
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 43us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.571335
last_received_ts = 191.570984
last_seq = 669
current_ts = 191.579681
current_received_ts = 191.579376
current_seq = 670
count = 665
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.579681
last_received_ts = 191.579376
last_seq = 670
current_ts = 191.588013
current_received_ts = 191.587662
current_seq = 671
count = 666
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 26us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.588013
last_received_ts = 191.587662
last_seq = 671
current_ts = 191.596344
current_received_ts = 191.596024
current_seq = 672
count = 667
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.596344
last_received_ts = 191.596024
last_seq = 672
current_ts = 191.604675
current_received_ts = 191.604340
current_seq = 673
count = 668
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.604675
last_received_ts = 191.604340
last_seq = 673
current_ts = 191.613007
current_received_ts = 191.612732
current_seq = 674
count = 669
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.613007
last_received_ts = 191.612732
last_seq = 674
current_ts = 191.621353
current_received_ts = 191.621017
current_seq = 675
count = 670
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 27us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.621353
last_received_ts = 191.621017
last_seq = 675
current_ts = 191.629669
current_received_ts = 191.629379
current_seq = 676
count = 671
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.629669
last_received_ts = 191.629379
last_seq = 676
current_ts = 191.638016
current_received_ts = 191.637665
current_seq = 677
count = 672
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 29us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.638016
last_received_ts = 191.637665
last_seq = 677
current_ts = 191.646347
current_received_ts = 191.645996
current_seq = 678
count = 673
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.646347
last_received_ts = 191.645996
last_seq = 678
current_ts = 191.654678
current_received_ts = 191.654327
current_seq = 679
count = 674
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.654678
last_received_ts = 191.654327
last_seq = 679
current_ts = 191.663010
current_received_ts = 191.662659
current_seq = 680
count = 675
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 25us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.663010
last_received_ts = 191.662659
last_seq = 680
current_ts = 191.671356
current_received_ts = 191.671066
current_seq = 681
count = 676
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.671356
last_received_ts = 191.671066
last_seq = 681
current_ts = 191.679688
current_received_ts = 191.679291
current_seq = 682
count = 677
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.679688
last_received_ts = 191.679291
last_seq = 682
current_ts = 191.688019
current_received_ts = 191.687683
current_seq = 683
count = 678
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 34us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.688019
last_received_ts = 191.687683
last_seq = 683
current_ts = 191.696365
current_received_ts = 191.695999
current_seq = 684
count = 679
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 24us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.696365
last_received_ts = 191.695999
last_seq = 684
current_ts = 191.704697
current_received_ts = 191.704361
current_seq = 685
count = 680
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 29us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.704697
last_received_ts = 191.704361
last_seq = 685
current_ts = 191.713028
current_received_ts = 191.712662
current_seq = 686
count = 681
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 23us
(kms_flip:2174) DEBUG: name = flip
last_ts = 191.713028
last_received_ts = 191.712662
last_seq = 686
current_ts = 191.721359
current_received_ts = 191.720978
current_seq = 687
count = 682
seq_step = 1
(kms_flip:2174) DEBUG: Vblank took 528us
(kms_flip:2174) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2174) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2174) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2174) igt_core-INFO: Stack trace:
(kms_flip:2174) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2174) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:2174) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:2174) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:2174) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:2174) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2174) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2174) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A1: FAIL (5.914s)

Dmesg

<6> [186.235691] [IGT] kms_flip: starting dynamic subtest C-HDMI-A1

<7> [186.236777] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:637]

<7> [186.237111] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:638]

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

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

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

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

<7> [186.262509] 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> [186.262672] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in lane_count (expected 4, found 0)

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

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

<7> [186.263216] 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 1920, found 0)

<7> [186.263378] 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 2080, found 0)

<7> [186.263537] 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 1920, found 0)

<7> [186.263697] 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 2080, found 0)

<7> [186.263861] 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 1968, found 0)

<7> [186.264042] 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 2000, found 0)

<7> [186.264221] 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 1080, found 0)

<7> [186.264386] 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 1080, found 0)

<7> [186.264549] 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 1083, found 0)

<7> [186.264709] 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 1088, found 0)

<7> [186.264888] 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 1144, found 0)

<7> [186.265066] 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 1144, found 0)

<7> [186.265226] 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 1920, found 0)

<7> [186.265385] 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 2080, found 0)

<7> [186.265544] 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 1920, found 0)

<7> [186.265702] 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 2080, found 0)

<7> [186.265860] 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 1968, found 0)

<7> [186.266045] 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 2000, found 0)

<7> [186.266230] 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 1080, found 0)

<7> [186.266387] 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 1080, found 0)

<7> [186.266545] 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 1083, found 0)

<7> [186.266702] 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 1088, found 0)

<7> [186.266860] 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 1144, found 0)

<7> [186.267039] 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 1144, found 0)

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

<7> [186.267376] 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 1, found 0)

<7> [186.267535] 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 4, found 0)

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

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

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

<7> [186.268211] 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 285500, found 0)

<7> [186.268370] 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 285500, found 0)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [186.270543] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:309:pipe B] releasing DPLL 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [186.273583] 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:309:pipe B]

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

<7> [186.285887] 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> [186.286525] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1)

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

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

<7> [186.287447] 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> [186.287464] 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> [186.287643] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B

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

<7> [186.293115] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x2, on? 1) for [CRTC:309:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [186.300099] 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> [186.300360] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24)

<7> [186.300590] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:447:pipe C] hw max bpp: 24, pipe bpp: 24, dithering: 0

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

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

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

<7> [186.301581] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [186.309365] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in dpll_hw_state

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

<7> [186.309822] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: cfgcr0: 0x0, cfgcr1: 0x0, 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> [186.310069] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [186.310304] i915 0000:00:02.0: [drm:intel_pipe_config_compare [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> [186.310529] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 24)

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

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

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

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

<7> [186.311576] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in avi infoframe

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [186.312315] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in spd infoframe

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

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

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

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

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

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

<7> [186.313030] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hdmi infoframe

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

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

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

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

<7> [186.313712] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:447:pipe C] fastset requirement not met, forcing full modeset

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

<7> [186.314238] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:447:pipe C] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4

<7> [186.314534] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:311:plane 1C] ddb ( 0 - 0) -> ( 0 - 1993), size 0 -> 1993

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

<7> [186.314980] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5,*wm6,*wm7,*twm, swm, stwm

<7> [186.315193] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 8, 8, 8, 8, 11, 16, 16, 0, 0, 0

<7> [186.315420] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 129, 129, 129, 129, 177, 257, 257, 30, 0, 0

<7> [186.315629] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] 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> [186.315917] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:447:pipe C] data rate 1142000 num active planes 1

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

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

<7> [186.316636] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:447:pipe C] min cdclk: 0 kHz -> 192000 kHz

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

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

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

<7> [186.317648] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:447:pipe C] allocated DPLL 0

<7> [186.317896] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:447:pipe C] reserving DPLL 0

<7> [186.317927] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off

<7> [186.318130] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:447:pipe C] enable: yes [modeset]

<7> [186.318272] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6

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

<7> [186.318446] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02

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

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

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

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

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

<7> [186.319636] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [186.320322] 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> [186.320554] 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> [186.320773] 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> [186.321012] 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> [186.321242] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

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

<7> [186.321705] 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> [186.321951] 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> [186.322176] 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> [186.322398] 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> [186.322631] 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> [186.322859] 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> [186.323110] 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> [186.323347] 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> [186.323583] 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> [186.323802] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0

<7> [186.324042] 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> [186.324265] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [186.328279] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:341:plane 2C] fb: [NOFB], visible: no

<7> [186.328438] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:371:plane 3C] fb: [NOFB], visible: no

<7> [186.328596] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:401:plane 4C] fb: [NOFB], visible: no

<7> [186.328755] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:411:plane 5C] fb: [NOFB], visible: no

<7> [186.328932] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:421:plane 6C] fb: [NOFB], visible: no

<7> [186.329110] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:431:plane 7C] fb: [NOFB], visible: no

<7> [186.329270] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:441:cursor C] fb: [NOFB], visible: no

<7> [186.330021] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on

<7> [186.330263] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off

<7> [186.330996] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00

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

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

<7> [186.332545] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_4

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [186.336918] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x4, on? 0) for [CRTC:447:pipe C]

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

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

<7> [186.337582] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe C

<7> [186.338302] 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> [186.338974] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1)

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

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

<7> [186.339921] 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> [186.339938] 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> [186.343390] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x810

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

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

<7> [186.348584] 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:447:pipe C], 64 bytes ELD

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

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

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

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

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

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

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

<7> [186.357885] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:447:pipe C]

<6> [192.152191] [IGT] kms_flip: finished subtest C-HDMI-A1, FAIL

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