igt@kms_flip@flip-vs-expired-vblank@b-edp1 on shard-lnl@IGTPW

Detail	Value
Duration	11.22 seconds
Hostname	shard-lnl-5
Igt-Version	IGT-Version: 2.4-g2badc4665 (x86_64) (Linux: 7.0.0-rc6-lgci-xe-xe-4835-3bc4b20741a977a59-debug+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1891 run_test() #3 ../tests/kms_flip.c:2126 __igt_unique____real_main2047() #4 ../tests/kms_flip.c:2047 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (11.225s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:12003) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:12003) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:12003) DEBUG: name = flip last_ts = 561.761597 last_received_ts = 561.761047 last_seq = 771 current_ts = 561.778259 current_received_ts = 561.777649 current_seq = 772 count = 469 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 561.778259 last_received_ts = 561.777649 last_seq = 772 current_ts = 561.794861 current_received_ts = 561.794312 current_seq = 773 count = 470 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 148us (kms_flip:12003) DEBUG: name = flip last_ts = 561.794861 last_received_ts = 561.794312 last_seq = 773 current_ts = 561.811523 current_received_ts = 561.810913 current_seq = 774 count = 471 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 130us (kms_flip:12003) DEBUG: name = flip last_ts = 561.811523 last_received_ts = 561.810913 last_seq = 774 current_ts = 561.828125 current_received_ts = 561.827576 current_seq = 775 count = 472 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 561.828125 last_received_ts = 561.827576 last_seq = 775 current_ts = 561.844788 current_received_ts = 561.844177 current_seq = 776 count = 473 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 561.844788 last_received_ts = 561.844177 last_seq = 776 current_ts = 561.861450 current_received_ts = 561.860840 current_seq = 777 count = 474 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 561.861450 last_received_ts = 561.860840 last_seq = 777 current_ts = 561.878052 current_received_ts = 561.877502 current_seq = 778 count = 475 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 62us (kms_flip:12003) DEBUG: name = flip last_ts = 561.878052 last_received_ts = 561.877502 last_seq = 778 current_ts = 561.894714 current_received_ts = 561.894104 current_seq = 779 count = 476 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 561.894714 last_received_ts = 561.894104 last_seq = 779 current_ts = 561.911316 current_received_ts = 561.910767 current_seq = 780 count = 477 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 561.911316 last_received_ts = 561.910767 last_seq = 780 current_ts = 561.927979 current_received_ts = 561.927368 current_seq = 781 count = 478 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 84us (kms_flip:12003) DEBUG: name = flip last_ts = 561.927979 last_received_ts = 561.927368 last_seq = 781 current_ts = 561.944641 current_received_ts = 561.944092 current_seq = 782 count = 479 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 79us (kms_flip:12003) DEBUG: name = flip last_ts = 561.944641 last_received_ts = 561.944092 last_seq = 782 current_ts = 561.961243 current_received_ts = 561.960693 current_seq = 783 count = 480 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 100us (kms_flip:12003) DEBUG: name = flip last_ts = 561.961243 last_received_ts = 561.960693 last_seq = 783 current_ts = 561.977905 current_received_ts = 561.977295 current_seq = 784 count = 481 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 139us (kms_flip:12003) DEBUG: name = flip last_ts = 561.977905 last_received_ts = 561.977295 last_seq = 784 current_ts = 561.994507 current_received_ts = 561.993958 current_seq = 785 count = 482 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 105us (kms_flip:12003) DEBUG: name = flip last_ts = 561.994507 last_received_ts = 561.993958 last_seq = 785 current_ts = 562.011169 current_received_ts = 562.010559 current_seq = 786 count = 483 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 92us (kms_flip:12003) DEBUG: name = flip last_ts = 562.011169 last_received_ts = 562.010559 last_seq = 786 current_ts = 562.027832 current_received_ts = 562.027222 current_seq = 787 count = 484 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 562.027832 last_received_ts = 562.027222 last_seq = 787 current_ts = 562.044434 current_received_ts = 562.043884 current_seq = 788 count = 485 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 87us (kms_flip:12003) DEBUG: name = flip last_ts = 562.044434 last_received_ts = 562.043884 last_seq = 788 current_ts = 562.061096 current_received_ts = 562.060547 current_seq = 789 count = 486 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.061096 last_received_ts = 562.060547 last_seq = 789 current_ts = 562.077698 current_received_ts = 562.077148 current_seq = 790 count = 487 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.077698 last_received_ts = 562.077148 last_seq = 790 current_ts = 562.094360 current_received_ts = 562.093811 current_seq = 791 count = 488 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 562.094360 last_received_ts = 562.093811 last_seq = 791 current_ts = 562.110962 current_received_ts = 562.110413 current_seq = 792 count = 489 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.110962 last_received_ts = 562.110413 last_seq = 792 current_ts = 562.127625 current_received_ts = 562.127075 current_seq = 793 count = 490 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 85us (kms_flip:12003) DEBUG: name = flip last_ts = 562.127625 last_received_ts = 562.127075 last_seq = 793 current_ts = 562.144287 current_received_ts = 562.143677 current_seq = 794 count = 491 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 88us (kms_flip:12003) DEBUG: name = flip last_ts = 562.144287 last_received_ts = 562.143677 last_seq = 794 current_ts = 562.160889 current_received_ts = 562.160339 current_seq = 795 count = 492 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 562.160889 last_received_ts = 562.160339 last_seq = 795 current_ts = 562.177551 current_received_ts = 562.177002 current_seq = 796 count = 493 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 78us (kms_flip:12003) DEBUG: name = flip last_ts = 562.177551 last_received_ts = 562.177002 last_seq = 796 current_ts = 562.194214 current_received_ts = 562.193604 current_seq = 797 count = 494 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 562.194214 last_received_ts = 562.193604 last_seq = 797 current_ts = 562.210815 current_received_ts = 562.210266 current_seq = 798 count = 495 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 143us (kms_flip:12003) DEBUG: name = flip last_ts = 562.210815 last_received_ts = 562.210266 last_seq = 798 current_ts = 562.227478 current_received_ts = 562.226868 current_seq = 799 count = 496 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 122us (kms_flip:12003) DEBUG: name = flip last_ts = 562.227478 last_received_ts = 562.226868 last_seq = 799 current_ts = 562.244080 current_received_ts = 562.243530 current_seq = 800 count = 497 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 562.244080 last_received_ts = 562.243530 last_seq = 800 current_ts = 562.260742 current_received_ts = 562.260498 current_seq = 801 count = 498 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 67us (kms_flip:12003) DEBUG: name = flip last_ts = 562.260742 last_received_ts = 562.260498 last_seq = 801 current_ts = 562.277405 current_received_ts = 562.276794 current_seq = 802 count = 499 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 101us (kms_flip:12003) DEBUG: name = flip last_ts = 562.277405 last_received_ts = 562.276794 last_seq = 802 current_ts = 562.294006 current_received_ts = 562.293335 current_seq = 803 count = 500 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.294006 last_received_ts = 562.293335 last_seq = 803 current_ts = 562.310669 current_received_ts = 562.310059 current_seq = 804 count = 501 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 562.310669 last_received_ts = 562.310059 last_seq = 804 current_ts = 562.327271 current_received_ts = 562.326721 current_seq = 805 count = 502 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 101us (kms_flip:12003) DEBUG: name = flip last_ts = 562.327271 last_received_ts = 562.326721 last_seq = 805 current_ts = 562.343933 current_received_ts = 562.343262 current_seq = 806 count = 503 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 142us (kms_flip:12003) DEBUG: name = flip last_ts = 562.343933 last_received_ts = 562.343262 last_seq = 806 current_ts = 562.360535 current_received_ts = 562.359924 current_seq = 807 count = 504 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 118us (kms_flip:12003) DEBUG: name = flip last_ts = 562.360535 last_received_ts = 562.359924 last_seq = 807 current_ts = 562.377197 current_received_ts = 562.376587 current_seq = 808 count = 505 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 562.377197 last_received_ts = 562.376587 last_seq = 808 current_ts = 562.393860 current_received_ts = 562.393188 current_seq = 809 count = 506 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 99us (kms_flip:12003) DEBUG: name = flip last_ts = 562.393860 last_received_ts = 562.393188 last_seq = 809 current_ts = 562.410461 current_received_ts = 562.409851 current_seq = 810 count = 507 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 102us (kms_flip:12003) DEBUG: name = flip last_ts = 562.410461 last_received_ts = 562.409851 last_seq = 810 current_ts = 562.427124 current_received_ts = 562.426453 current_seq = 811 count = 508 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 562.427124 last_received_ts = 562.426453 last_seq = 811 current_ts = 562.443787 current_received_ts = 562.443115 current_seq = 812 count = 509 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 562.443787 last_received_ts = 562.443115 last_seq = 812 current_ts = 562.460388 current_received_ts = 562.459778 current_seq = 813 count = 510 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.460388 last_received_ts = 562.459778 last_seq = 813 current_ts = 562.477051 current_received_ts = 562.476379 current_seq = 814 count = 511 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.477051 last_received_ts = 562.476379 last_seq = 814 current_ts = 562.493713 current_received_ts = 562.493042 current_seq = 815 count = 512 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 84us (kms_flip:12003) DEBUG: name = flip last_ts = 562.493713 last_received_ts = 562.493042 last_seq = 815 current_ts = 562.510315 current_received_ts = 562.509644 current_seq = 816 count = 513 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.510315 last_received_ts = 562.509644 last_seq = 816 current_ts = 562.526978 current_received_ts = 562.526428 current_seq = 817 count = 514 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.526978 last_received_ts = 562.526428 last_seq = 817 current_ts = 562.543579 current_received_ts = 562.543091 current_seq = 818 count = 515 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 99us (kms_flip:12003) DEBUG: name = flip last_ts = 562.543579 last_received_ts = 562.543091 last_seq = 818 current_ts = 562.560242 current_received_ts = 562.559692 current_seq = 819 count = 516 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 99us (kms_flip:12003) DEBUG: name = flip last_ts = 562.560242 last_received_ts = 562.559692 last_seq = 819 current_ts = 562.576904 current_received_ts = 562.576355 current_seq = 820 count = 517 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 562.576904 last_received_ts = 562.576355 last_seq = 820 current_ts = 562.593506 current_received_ts = 562.592957 current_seq = 821 count = 518 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 78us (kms_flip:12003) DEBUG: name = flip last_ts = 562.593506 last_received_ts = 562.592957 last_seq = 821 current_ts = 562.610168 current_received_ts = 562.609619 current_seq = 822 count = 519 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 562.610168 last_received_ts = 562.609619 last_seq = 822 current_ts = 562.626831 current_received_ts = 562.626282 current_seq = 823 count = 520 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 155us (kms_flip:12003) DEBUG: name = flip last_ts = 562.626831 last_received_ts = 562.626282 last_seq = 823 current_ts = 562.643433 current_received_ts = 562.642883 current_seq = 824 count = 521 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 116us (kms_flip:12003) DEBUG: name = flip last_ts = 562.643433 last_received_ts = 562.642883 last_seq = 824 current_ts = 562.660095 current_received_ts = 562.659546 current_seq = 825 count = 522 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.660095 last_received_ts = 562.659546 last_seq = 825 current_ts = 562.676758 current_received_ts = 562.676147 current_seq = 826 count = 523 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 92us (kms_flip:12003) DEBUG: name = flip last_ts = 562.676758 last_received_ts = 562.676147 last_seq = 826 current_ts = 562.693359 current_received_ts = 562.692810 current_seq = 827 count = 524 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 76us (kms_flip:12003) DEBUG: name = flip last_ts = 562.693359 last_received_ts = 562.692810 last_seq = 827 current_ts = 562.710022 current_received_ts = 562.709473 current_seq = 828 count = 525 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.710022 last_received_ts = 562.709473 last_seq = 828 current_ts = 562.726624 current_received_ts = 562.726135 current_seq = 829 count = 526 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 96us (kms_flip:12003) DEBUG: name = flip last_ts = 562.726624 last_received_ts = 562.726135 last_seq = 829 current_ts = 562.743286 current_received_ts = 562.742737 current_seq = 830 count = 527 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 87us (kms_flip:12003) DEBUG: name = flip last_ts = 562.743286 last_received_ts = 562.742737 last_seq = 830 current_ts = 562.759949 current_received_ts = 562.759399 current_seq = 831 count = 528 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.759949 last_received_ts = 562.759399 last_seq = 831 current_ts = 562.776550 current_received_ts = 562.776062 current_seq = 832 count = 529 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 88us (kms_flip:12003) DEBUG: name = flip last_ts = 562.776550 last_received_ts = 562.776062 last_seq = 832 current_ts = 562.793213 current_received_ts = 562.792664 current_seq = 833 count = 530 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.793213 last_received_ts = 562.792664 last_seq = 833 current_ts = 562.809875 current_received_ts = 562.809265 current_seq = 834 count = 531 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 126us (kms_flip:12003) DEBUG: name = flip last_ts = 562.809875 last_received_ts = 562.809265 last_seq = 834 current_ts = 562.826477 current_received_ts = 562.825928 current_seq = 835 count = 532 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 135us (kms_flip:12003) DEBUG: name = flip last_ts = 562.826477 last_received_ts = 562.825928 last_seq = 835 current_ts = 562.843140 current_received_ts = 562.842590 current_seq = 836 count = 533 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 99us (kms_flip:12003) DEBUG: name = flip last_ts = 562.843140 last_received_ts = 562.842590 last_seq = 836 current_ts = 562.859802 current_received_ts = 562.859192 current_seq = 837 count = 534 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 92us (kms_flip:12003) DEBUG: name = flip last_ts = 562.859802 last_received_ts = 562.859192 last_seq = 837 current_ts = 562.876404 current_received_ts = 562.875854 current_seq = 838 count = 535 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 92us (kms_flip:12003) DEBUG: name = flip last_ts = 562.876404 last_received_ts = 562.875854 last_seq = 838 current_ts = 562.893066 current_received_ts = 562.892517 current_seq = 839 count = 536 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 562.893066 last_received_ts = 562.892517 last_seq = 839 current_ts = 562.909668 current_received_ts = 562.909119 current_seq = 840 count = 537 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 97us (kms_flip:12003) DEBUG: name = flip last_ts = 562.909668 last_received_ts = 562.909119 last_seq = 840 current_ts = 562.926331 current_received_ts = 562.925781 current_seq = 841 count = 538 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 93us (kms_flip:12003) DEBUG: name = flip last_ts = 562.926331 last_received_ts = 562.925781 last_seq = 841 current_ts = 562.942993 current_received_ts = 562.942444 current_seq = 842 count = 539 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 562.942993 last_received_ts = 562.942444 last_seq = 842 current_ts = 562.959595 current_received_ts = 562.959106 current_seq = 843 count = 540 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 94us (kms_flip:12003) DEBUG: name = flip last_ts = 562.959595 last_received_ts = 562.959106 last_seq = 843 current_ts = 562.976257 current_received_ts = 562.975708 current_seq = 844 count = 541 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 92us (kms_flip:12003) DEBUG: name = flip last_ts = 562.976257 last_received_ts = 562.975708 last_seq = 844 current_ts = 562.992920 current_received_ts = 562.992371 current_seq = 845 count = 542 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 99us (kms_flip:12003) DEBUG: name = flip last_ts = 562.992920 last_received_ts = 562.992371 last_seq = 845 current_ts = 563.009521 current_received_ts = 563.008972 current_seq = 846 count = 543 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 92us (kms_flip:12003) DEBUG: name = flip last_ts = 563.009521 last_received_ts = 563.008972 last_seq = 846 current_ts = 563.026184 current_received_ts = 563.025635 current_seq = 847 count = 544 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 563.026184 last_received_ts = 563.025635 last_seq = 847 current_ts = 563.042847 current_received_ts = 563.042297 current_seq = 848 count = 545 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 145us (kms_flip:12003) DEBUG: name = flip last_ts = 563.042847 last_received_ts = 563.042297 last_seq = 848 current_ts = 563.059448 current_received_ts = 563.058899 current_seq = 849 count = 546 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 122us (kms_flip:12003) DEBUG: name = flip last_ts = 563.059448 last_received_ts = 563.058899 last_seq = 849 current_ts = 563.076111 current_received_ts = 563.075562 current_seq = 850 count = 547 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 99us (kms_flip:12003) DEBUG: name = flip last_ts = 563.076111 last_received_ts = 563.075562 last_seq = 850 current_ts = 563.092712 current_received_ts = 563.092163 current_seq = 851 count = 548 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 86us (kms_flip:12003) DEBUG: name = flip last_ts = 563.092712 last_received_ts = 563.092163 last_seq = 851 current_ts = 563.109375 current_received_ts = 563.108826 current_seq = 852 count = 549 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 563.109375 last_received_ts = 563.108826 last_seq = 852 current_ts = 563.126038 current_received_ts = 563.125488 current_seq = 853 count = 550 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 99us (kms_flip:12003) DEBUG: name = flip last_ts = 563.126038 last_received_ts = 563.125488 last_seq = 853 current_ts = 563.142639 current_received_ts = 563.142090 current_seq = 854 count = 551 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 82us (kms_flip:12003) DEBUG: name = flip last_ts = 563.142639 last_received_ts = 563.142090 last_seq = 854 current_ts = 563.159302 current_received_ts = 563.158752 current_seq = 855 count = 552 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 80us (kms_flip:12003) DEBUG: name = flip last_ts = 563.159302 last_received_ts = 563.158752 last_seq = 855 current_ts = 563.175964 current_received_ts = 563.175415 current_seq = 856 count = 553 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 89us (kms_flip:12003) DEBUG: name = flip last_ts = 563.175964 last_received_ts = 563.175415 last_seq = 856 current_ts = 563.192566 current_received_ts = 563.192078 current_seq = 857 count = 554 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 88us (kms_flip:12003) DEBUG: name = flip last_ts = 563.192566 last_received_ts = 563.192078 last_seq = 857 current_ts = 563.209229 current_received_ts = 563.208679 current_seq = 858 count = 555 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 80us (kms_flip:12003) DEBUG: name = flip last_ts = 563.209229 last_received_ts = 563.208679 last_seq = 858 current_ts = 563.225891 current_received_ts = 563.225342 current_seq = 859 count = 556 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 96us (kms_flip:12003) DEBUG: name = flip last_ts = 563.225891 last_received_ts = 563.225342 last_seq = 859 current_ts = 563.242493 current_received_ts = 563.241943 current_seq = 860 count = 557 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 121us (kms_flip:12003) DEBUG: name = flip last_ts = 563.242493 last_received_ts = 563.241943 last_seq = 860 current_ts = 563.259155 current_received_ts = 563.258606 current_seq = 861 count = 558 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 563.259155 last_received_ts = 563.258606 last_seq = 861 current_ts = 563.275757 current_received_ts = 563.275208 current_seq = 862 count = 559 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 563.275757 last_received_ts = 563.275208 last_seq = 862 current_ts = 563.292419 current_received_ts = 563.291870 current_seq = 863 count = 560 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 82us (kms_flip:12003) DEBUG: name = flip last_ts = 563.292419 last_received_ts = 563.291870 last_seq = 863 current_ts = 563.309082 current_received_ts = 563.308533 current_seq = 864 count = 561 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 80us (kms_flip:12003) DEBUG: name = flip last_ts = 563.309082 last_received_ts = 563.308533 last_seq = 864 current_ts = 563.325684 current_received_ts = 563.325195 current_seq = 865 count = 562 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 88us (kms_flip:12003) DEBUG: name = flip last_ts = 563.325684 last_received_ts = 563.325195 last_seq = 865 current_ts = 563.342346 current_received_ts = 563.341797 current_seq = 866 count = 563 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 86us (kms_flip:12003) DEBUG: name = flip last_ts = 563.342346 last_received_ts = 563.341797 last_seq = 866 current_ts = 563.359009 current_received_ts = 563.358459 current_seq = 867 count = 564 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 563.359009 last_received_ts = 563.358459 last_seq = 867 current_ts = 563.375610 current_received_ts = 563.375061 current_seq = 868 count = 565 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 100us (kms_flip:12003) DEBUG: name = flip last_ts = 563.375610 last_received_ts = 563.375061 last_seq = 868 current_ts = 563.392273 current_received_ts = 563.391724 current_seq = 869 count = 566 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 92us (kms_flip:12003) DEBUG: name = flip last_ts = 563.392273 last_received_ts = 563.391724 last_seq = 869 current_ts = 563.408936 current_received_ts = 563.408386 current_seq = 870 count = 567 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 156us (kms_flip:12003) DEBUG: name = flip last_ts = 563.408936 last_received_ts = 563.408386 last_seq = 870 current_ts = 563.425537 current_received_ts = 563.424988 current_seq = 871 count = 568 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 96us (kms_flip:12003) DEBUG: name = flip last_ts = 563.425537 last_received_ts = 563.424988 last_seq = 871 current_ts = 563.442200 current_received_ts = 563.441650 current_seq = 872 count = 569 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 563.442200 last_received_ts = 563.441650 last_seq = 872 current_ts = 563.458862 current_received_ts = 563.458252 current_seq = 873 count = 570 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 149us (kms_flip:12003) DEBUG: name = flip last_ts = 563.458862 last_received_ts = 563.458252 last_seq = 873 current_ts = 563.475464 current_received_ts = 563.474854 current_seq = 874 count = 571 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 92us (kms_flip:12003) DEBUG: name = flip last_ts = 563.475464 last_received_ts = 563.474854 last_seq = 874 current_ts = 563.492126 current_received_ts = 563.491455 current_seq = 875 count = 572 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 563.492126 last_received_ts = 563.491455 last_seq = 875 current_ts = 563.508789 current_received_ts = 563.508118 current_seq = 876 count = 573 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 563.508789 last_received_ts = 563.508118 last_seq = 876 current_ts = 563.525391 current_received_ts = 563.524780 current_seq = 877 count = 574 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 92us (kms_flip:12003) DEBUG: name = flip last_ts = 563.525391 last_received_ts = 563.524780 last_seq = 877 current_ts = 563.542053 current_received_ts = 563.541382 current_seq = 878 count = 575 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 91us (kms_flip:12003) DEBUG: name = flip last_ts = 563.542053 last_received_ts = 563.541382 last_seq = 878 current_ts = 563.558716 current_received_ts = 563.558044 current_seq = 879 count = 576 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 87us (kms_flip:12003) DEBUG: name = flip last_ts = 563.558716 last_received_ts = 563.558044 last_seq = 879 current_ts = 563.575317 current_received_ts = 563.574707 current_seq = 880 count = 577 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 86us (kms_flip:12003) DEBUG: name = flip last_ts = 563.575317 last_received_ts = 563.574707 last_seq = 880 current_ts = 563.591980 current_received_ts = 563.591370 current_seq = 881 count = 578 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 99us (kms_flip:12003) DEBUG: name = flip last_ts = 563.591980 last_received_ts = 563.591370 last_seq = 881 current_ts = 563.608643 current_received_ts = 563.607971 current_seq = 882 count = 579 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 119us (kms_flip:12003) DEBUG: name = flip last_ts = 563.608643 last_received_ts = 563.607971 last_seq = 882 current_ts = 563.625244 current_received_ts = 563.624634 current_seq = 883 count = 580 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 86us (kms_flip:12003) DEBUG: name = flip last_ts = 563.625244 last_received_ts = 563.624634 last_seq = 883 current_ts = 563.641907 current_received_ts = 563.641235 current_seq = 884 count = 581 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 155us (kms_flip:12003) DEBUG: name = flip last_ts = 563.641907 last_received_ts = 563.641235 last_seq = 884 current_ts = 563.658569 current_received_ts = 563.657898 current_seq = 885 count = 582 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 115us (kms_flip:12003) DEBUG: name = flip last_ts = 563.658569 last_received_ts = 563.657898 last_seq = 885 current_ts = 563.675171 current_received_ts = 563.674561 current_seq = 886 count = 583 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 81us (kms_flip:12003) DEBUG: name = flip last_ts = 563.675171 last_received_ts = 563.674561 last_seq = 886 current_ts = 563.691833 current_received_ts = 563.691284 current_seq = 887 count = 584 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 144us (kms_flip:12003) DEBUG: name = flip last_ts = 563.691833 last_received_ts = 563.691284 last_seq = 887 current_ts = 563.708496 current_received_ts = 563.707947 current_seq = 888 count = 585 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 139us (kms_flip:12003) DEBUG: name = flip last_ts = 563.708496 last_received_ts = 563.707947 last_seq = 888 current_ts = 563.725098 current_received_ts = 563.724548 current_seq = 889 count = 586 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 99us (kms_flip:12003) DEBUG: name = flip last_ts = 563.725098 last_received_ts = 563.724548 last_seq = 889 current_ts = 563.741760 current_received_ts = 563.741211 current_seq = 890 count = 587 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 90us (kms_flip:12003) DEBUG: name = flip last_ts = 563.741760 last_received_ts = 563.741211 last_seq = 890 current_ts = 563.758423 current_received_ts = 563.757874 current_seq = 891 count = 588 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 99us (kms_flip:12003) DEBUG: name = flip last_ts = 563.758423 last_received_ts = 563.757874 last_seq = 891 current_ts = 563.775024 current_received_ts = 563.774475 current_seq = 892 count = 589 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 83us (kms_flip:12003) DEBUG: name = flip last_ts = 563.775024 last_received_ts = 563.774475 last_seq = 892 current_ts = 563.791687 current_received_ts = 563.791321 current_seq = 893 count = 590 seq_step = 1 (kms_flip:12003) DEBUG: Vblank took 559us (kms_flip:12003) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:12003) CRITICAL: Failed assertion: end - start < 500 (kms_flip:12003) igt_core-INFO: Stack trace: (kms_flip:12003) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:12003) igt_core-INFO: #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() (kms_flip:12003) igt_core-INFO: #2 ../tests/kms_flip.c:1891 run_test() (kms_flip:12003) igt_core-INFO: #3 ../tests/kms_flip.c:2126 __igt_unique____real_main2047() (kms_flip:12003) igt_core-INFO: #4 ../tests/kms_flip.c:2047 main() (kms_flip:12003) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:12003) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:12003) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (11.225s)
Dmesg	<6> [583.287817] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [583.307096] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [583.307249] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [583.307354] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [583.307702] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431] <7> [583.308043] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [583.380691] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [583.381019] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [583.381508] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [583.381938] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [583.382351] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [583.382867] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [583.383255] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [583.383687] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [583.384067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [583.384426] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [583.384906] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [583.385360] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [583.385784] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [583.386130] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [583.386488] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [583.386867] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [583.387209] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [583.387531] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [583.387823] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [583.388106] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [583.388387] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [583.388730] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [583.389042] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [583.389313] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [583.389566] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [583.389803] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [583.390064] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [583.390310] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [583.390550] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [583.390784] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [583.390999] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [583.391209] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [583.391415] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [583.391638] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [583.391835] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [583.392023] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [583.392209] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [583.392417] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [583.392612] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [583.392790] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [583.392958] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [583.393207] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [583.393373] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [583.393582] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [583.393769] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [583.393958] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [583.394125] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [583.394287] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [583.394477] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [583.394688] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [583.394847] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [583.394990] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [583.395129] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [583.395265] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [583.395403] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [583.395607] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [583.395746] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [583.396007] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [583.396134] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [583.604710] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [583.605227] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [583.618949] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [583.619483] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [583.619945] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [583.671903] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [583.672475] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [583.678978] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [583.679613] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [583.679790] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [583.681501] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [583.682235] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [583.682894] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [583.683363] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [583.683804] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [583.684200] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [583.684637] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [583.685082] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [583.685459] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [583.685880] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [583.686260] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [583.686633] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [583.687109] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [583.687476] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [583.687877] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [583.688244] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [583.688735] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [583.689115] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [583.689463] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [583.690085] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [583.690567] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [583.691214] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [583.691683] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [583.692239] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [583.692627] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [583.693611] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [583.694024] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [583.694323] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [583.694390] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [583.694559] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [583.694952] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [583.695262] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [583.695574] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [583.695891] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [583.696173] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [583.696438] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [583.696687] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [583.697025] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [583.697262] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [583.697489] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [583.697698] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [583.697936] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [583.698165] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [583.698364] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [583.698545] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [583.698729] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [583.698902] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [583.699067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [583.699256] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [583.699437] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [583.699600] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [583.699756] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [583.699900] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [583.700039] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [583.700177] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [583.700314] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [583.700445] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [583.700573] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [583.700696] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [583.700837] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [583.700956] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [583.701074] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [583.701189] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [583.701303] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [583.701419] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [583.701532] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [583.701642] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [583.701757] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [583.701865] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [583.701969] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [583.702067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [583.702164] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [583.702274] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [583.702430] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [583.702519] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [583.702629] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [583.702702] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:264:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [583.702785] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [583.702858] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [583.702931] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [583.703001] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [583.703088] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [583.703184] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [583.703277] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [583.703369] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [583.703457] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [583.703541] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [583.703624] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [583.703724] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [583.703814] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [583.703906] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [583.704009] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [583.704106] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [583.704194] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [583.704281] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [583.704366] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [583.704452] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [583.704536] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [583.704620] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [583.704702] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [583.704799] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [583.704880] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [583.704963] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [583.705039] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [583.705112] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [583.705187] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [583.705261] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [583.705334] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [583.705406] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [583.705479] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [583.705550] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [583.705621] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [583.705692] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [583.705766] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [583.705848] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [583.705941] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [583.706032] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [583.706121] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [583.706199] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [583.706277] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [583.706354] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [583.706432] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [583.706509] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [583.706588] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0 <7> [583.706665] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [583.706736] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [583.706823] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [583.706900] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [583.706977] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [583.707047] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [583.707119] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [583.707192] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [583.707264] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [583.707337] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [583.707409] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [583.707481] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [583.707552] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [583.707624] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [583.707699] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [583.707781] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [583.707861] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [583.707938] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [583.708015] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [583.708091] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [583.708168] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [583.708245] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [583.708320] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [583.708398] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [583.708474] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [583.708547] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [583.708618] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [583.708687] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [583.708632] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [583.708758] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:431] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [583.708843] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [583.708859] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [583.708937] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [583.708958] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [583.709016] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [583.709093] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [583.709169] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [583.709191] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [583.709263] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [583.709354] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [583.709798] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [583.709967] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [583.710131] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [583.710252] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [583.710368] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [583.710474] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [583.710580] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [583.710672] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [583.710750] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [583.710846] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [583.710917] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [583.710990] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [583.711056] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [583.711120] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [583.711185] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [583.711247] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [583.711309] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [583.711370] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [583.711431] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [583.711515] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [583.711668] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [583.711732] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [583.711847] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [583.712915] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [583.713019] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [583.714987] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [583.715078] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (465 ms remaining) <7> [584.190882] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [584.232117] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [584.232487] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [584.232887] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [584.269153] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [584.269597] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [584.269996] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [584.270668] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [584.444031] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [584.444601] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [584.445042] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [584.447362] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [584.449163] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [584.450330] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [584.451877] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [584.453529] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [584.455001] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [584.455594] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [584.457618] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [584.458261] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [584.459382] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [584.460159] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [584.460791] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [584.461394] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 192000 <7> [584.477046] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [584.478908] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [584.479383] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <7> [587.024576] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off <7> [587.025034] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [594.361329] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [594.361920] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [594.362454] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [594.514616] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

11.22 seconds

Hostname

shard-lnl-5

Igt-Version

IGT-Version: 2.4-g2badc4665 (x86_64) (Linux: 7.0.0-rc6-lgci-xe-xe-4835-3bc4b20741a977a59-debug+ x86_64)

Out

Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1891 run_test()
  #3 ../tests/kms_flip.c:2126 __igt_unique____real_main2047()
  #4 ../tests/kms_flip.c:2047 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (11.225s)

Err

Starting dynamic subtest: B-eDP1
(kms_flip:12003) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:12003) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.761597
last_received_ts = 561.761047
last_seq = 771
current_ts = 561.778259
current_received_ts = 561.777649
current_seq = 772
count = 469
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.778259
last_received_ts = 561.777649
last_seq = 772
current_ts = 561.794861
current_received_ts = 561.794312
current_seq = 773
count = 470
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 148us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.794861
last_received_ts = 561.794312
last_seq = 773
current_ts = 561.811523
current_received_ts = 561.810913
current_seq = 774
count = 471
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 130us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.811523
last_received_ts = 561.810913
last_seq = 774
current_ts = 561.828125
current_received_ts = 561.827576
current_seq = 775
count = 472
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.828125
last_received_ts = 561.827576
last_seq = 775
current_ts = 561.844788
current_received_ts = 561.844177
current_seq = 776
count = 473
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.844788
last_received_ts = 561.844177
last_seq = 776
current_ts = 561.861450
current_received_ts = 561.860840
current_seq = 777
count = 474
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.861450
last_received_ts = 561.860840
last_seq = 777
current_ts = 561.878052
current_received_ts = 561.877502
current_seq = 778
count = 475
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 62us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.878052
last_received_ts = 561.877502
last_seq = 778
current_ts = 561.894714
current_received_ts = 561.894104
current_seq = 779
count = 476
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.894714
last_received_ts = 561.894104
last_seq = 779
current_ts = 561.911316
current_received_ts = 561.910767
current_seq = 780
count = 477
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.911316
last_received_ts = 561.910767
last_seq = 780
current_ts = 561.927979
current_received_ts = 561.927368
current_seq = 781
count = 478
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 84us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.927979
last_received_ts = 561.927368
last_seq = 781
current_ts = 561.944641
current_received_ts = 561.944092
current_seq = 782
count = 479
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 79us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.944641
last_received_ts = 561.944092
last_seq = 782
current_ts = 561.961243
current_received_ts = 561.960693
current_seq = 783
count = 480
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 100us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.961243
last_received_ts = 561.960693
last_seq = 783
current_ts = 561.977905
current_received_ts = 561.977295
current_seq = 784
count = 481
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 139us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.977905
last_received_ts = 561.977295
last_seq = 784
current_ts = 561.994507
current_received_ts = 561.993958
current_seq = 785
count = 482
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 105us
(kms_flip:12003) DEBUG: name = flip
last_ts = 561.994507
last_received_ts = 561.993958
last_seq = 785
current_ts = 562.011169
current_received_ts = 562.010559
current_seq = 786
count = 483
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 92us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.011169
last_received_ts = 562.010559
last_seq = 786
current_ts = 562.027832
current_received_ts = 562.027222
current_seq = 787
count = 484
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.027832
last_received_ts = 562.027222
last_seq = 787
current_ts = 562.044434
current_received_ts = 562.043884
current_seq = 788
count = 485
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 87us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.044434
last_received_ts = 562.043884
last_seq = 788
current_ts = 562.061096
current_received_ts = 562.060547
current_seq = 789
count = 486
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.061096
last_received_ts = 562.060547
last_seq = 789
current_ts = 562.077698
current_received_ts = 562.077148
current_seq = 790
count = 487
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.077698
last_received_ts = 562.077148
last_seq = 790
current_ts = 562.094360
current_received_ts = 562.093811
current_seq = 791
count = 488
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.094360
last_received_ts = 562.093811
last_seq = 791
current_ts = 562.110962
current_received_ts = 562.110413
current_seq = 792
count = 489
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.110962
last_received_ts = 562.110413
last_seq = 792
current_ts = 562.127625
current_received_ts = 562.127075
current_seq = 793
count = 490
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 85us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.127625
last_received_ts = 562.127075
last_seq = 793
current_ts = 562.144287
current_received_ts = 562.143677
current_seq = 794
count = 491
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 88us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.144287
last_received_ts = 562.143677
last_seq = 794
current_ts = 562.160889
current_received_ts = 562.160339
current_seq = 795
count = 492
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.160889
last_received_ts = 562.160339
last_seq = 795
current_ts = 562.177551
current_received_ts = 562.177002
current_seq = 796
count = 493
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 78us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.177551
last_received_ts = 562.177002
last_seq = 796
current_ts = 562.194214
current_received_ts = 562.193604
current_seq = 797
count = 494
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.194214
last_received_ts = 562.193604
last_seq = 797
current_ts = 562.210815
current_received_ts = 562.210266
current_seq = 798
count = 495
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 143us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.210815
last_received_ts = 562.210266
last_seq = 798
current_ts = 562.227478
current_received_ts = 562.226868
current_seq = 799
count = 496
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 122us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.227478
last_received_ts = 562.226868
last_seq = 799
current_ts = 562.244080
current_received_ts = 562.243530
current_seq = 800
count = 497
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.244080
last_received_ts = 562.243530
last_seq = 800
current_ts = 562.260742
current_received_ts = 562.260498
current_seq = 801
count = 498
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 67us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.260742
last_received_ts = 562.260498
last_seq = 801
current_ts = 562.277405
current_received_ts = 562.276794
current_seq = 802
count = 499
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 101us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.277405
last_received_ts = 562.276794
last_seq = 802
current_ts = 562.294006
current_received_ts = 562.293335
current_seq = 803
count = 500
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.294006
last_received_ts = 562.293335
last_seq = 803
current_ts = 562.310669
current_received_ts = 562.310059
current_seq = 804
count = 501
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.310669
last_received_ts = 562.310059
last_seq = 804
current_ts = 562.327271
current_received_ts = 562.326721
current_seq = 805
count = 502
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 101us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.327271
last_received_ts = 562.326721
last_seq = 805
current_ts = 562.343933
current_received_ts = 562.343262
current_seq = 806
count = 503
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 142us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.343933
last_received_ts = 562.343262
last_seq = 806
current_ts = 562.360535
current_received_ts = 562.359924
current_seq = 807
count = 504
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 118us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.360535
last_received_ts = 562.359924
last_seq = 807
current_ts = 562.377197
current_received_ts = 562.376587
current_seq = 808
count = 505
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.377197
last_received_ts = 562.376587
last_seq = 808
current_ts = 562.393860
current_received_ts = 562.393188
current_seq = 809
count = 506
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 99us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.393860
last_received_ts = 562.393188
last_seq = 809
current_ts = 562.410461
current_received_ts = 562.409851
current_seq = 810
count = 507
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 102us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.410461
last_received_ts = 562.409851
last_seq = 810
current_ts = 562.427124
current_received_ts = 562.426453
current_seq = 811
count = 508
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.427124
last_received_ts = 562.426453
last_seq = 811
current_ts = 562.443787
current_received_ts = 562.443115
current_seq = 812
count = 509
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.443787
last_received_ts = 562.443115
last_seq = 812
current_ts = 562.460388
current_received_ts = 562.459778
current_seq = 813
count = 510
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.460388
last_received_ts = 562.459778
last_seq = 813
current_ts = 562.477051
current_received_ts = 562.476379
current_seq = 814
count = 511
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.477051
last_received_ts = 562.476379
last_seq = 814
current_ts = 562.493713
current_received_ts = 562.493042
current_seq = 815
count = 512
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 84us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.493713
last_received_ts = 562.493042
last_seq = 815
current_ts = 562.510315
current_received_ts = 562.509644
current_seq = 816
count = 513
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.510315
last_received_ts = 562.509644
last_seq = 816
current_ts = 562.526978
current_received_ts = 562.526428
current_seq = 817
count = 514
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.526978
last_received_ts = 562.526428
last_seq = 817
current_ts = 562.543579
current_received_ts = 562.543091
current_seq = 818
count = 515
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 99us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.543579
last_received_ts = 562.543091
last_seq = 818
current_ts = 562.560242
current_received_ts = 562.559692
current_seq = 819
count = 516
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 99us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.560242
last_received_ts = 562.559692
last_seq = 819
current_ts = 562.576904
current_received_ts = 562.576355
current_seq = 820
count = 517
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.576904
last_received_ts = 562.576355
last_seq = 820
current_ts = 562.593506
current_received_ts = 562.592957
current_seq = 821
count = 518
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 78us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.593506
last_received_ts = 562.592957
last_seq = 821
current_ts = 562.610168
current_received_ts = 562.609619
current_seq = 822
count = 519
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.610168
last_received_ts = 562.609619
last_seq = 822
current_ts = 562.626831
current_received_ts = 562.626282
current_seq = 823
count = 520
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 155us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.626831
last_received_ts = 562.626282
last_seq = 823
current_ts = 562.643433
current_received_ts = 562.642883
current_seq = 824
count = 521
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 116us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.643433
last_received_ts = 562.642883
last_seq = 824
current_ts = 562.660095
current_received_ts = 562.659546
current_seq = 825
count = 522
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.660095
last_received_ts = 562.659546
last_seq = 825
current_ts = 562.676758
current_received_ts = 562.676147
current_seq = 826
count = 523
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 92us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.676758
last_received_ts = 562.676147
last_seq = 826
current_ts = 562.693359
current_received_ts = 562.692810
current_seq = 827
count = 524
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 76us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.693359
last_received_ts = 562.692810
last_seq = 827
current_ts = 562.710022
current_received_ts = 562.709473
current_seq = 828
count = 525
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.710022
last_received_ts = 562.709473
last_seq = 828
current_ts = 562.726624
current_received_ts = 562.726135
current_seq = 829
count = 526
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 96us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.726624
last_received_ts = 562.726135
last_seq = 829
current_ts = 562.743286
current_received_ts = 562.742737
current_seq = 830
count = 527
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 87us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.743286
last_received_ts = 562.742737
last_seq = 830
current_ts = 562.759949
current_received_ts = 562.759399
current_seq = 831
count = 528
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.759949
last_received_ts = 562.759399
last_seq = 831
current_ts = 562.776550
current_received_ts = 562.776062
current_seq = 832
count = 529
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 88us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.776550
last_received_ts = 562.776062
last_seq = 832
current_ts = 562.793213
current_received_ts = 562.792664
current_seq = 833
count = 530
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.793213
last_received_ts = 562.792664
last_seq = 833
current_ts = 562.809875
current_received_ts = 562.809265
current_seq = 834
count = 531
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 126us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.809875
last_received_ts = 562.809265
last_seq = 834
current_ts = 562.826477
current_received_ts = 562.825928
current_seq = 835
count = 532
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 135us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.826477
last_received_ts = 562.825928
last_seq = 835
current_ts = 562.843140
current_received_ts = 562.842590
current_seq = 836
count = 533
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 99us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.843140
last_received_ts = 562.842590
last_seq = 836
current_ts = 562.859802
current_received_ts = 562.859192
current_seq = 837
count = 534
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 92us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.859802
last_received_ts = 562.859192
last_seq = 837
current_ts = 562.876404
current_received_ts = 562.875854
current_seq = 838
count = 535
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 92us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.876404
last_received_ts = 562.875854
last_seq = 838
current_ts = 562.893066
current_received_ts = 562.892517
current_seq = 839
count = 536
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.893066
last_received_ts = 562.892517
last_seq = 839
current_ts = 562.909668
current_received_ts = 562.909119
current_seq = 840
count = 537
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 97us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.909668
last_received_ts = 562.909119
last_seq = 840
current_ts = 562.926331
current_received_ts = 562.925781
current_seq = 841
count = 538
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 93us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.926331
last_received_ts = 562.925781
last_seq = 841
current_ts = 562.942993
current_received_ts = 562.942444
current_seq = 842
count = 539
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.942993
last_received_ts = 562.942444
last_seq = 842
current_ts = 562.959595
current_received_ts = 562.959106
current_seq = 843
count = 540
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 94us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.959595
last_received_ts = 562.959106
last_seq = 843
current_ts = 562.976257
current_received_ts = 562.975708
current_seq = 844
count = 541
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 92us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.976257
last_received_ts = 562.975708
last_seq = 844
current_ts = 562.992920
current_received_ts = 562.992371
current_seq = 845
count = 542
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 99us
(kms_flip:12003) DEBUG: name = flip
last_ts = 562.992920
last_received_ts = 562.992371
last_seq = 845
current_ts = 563.009521
current_received_ts = 563.008972
current_seq = 846
count = 543
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 92us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.009521
last_received_ts = 563.008972
last_seq = 846
current_ts = 563.026184
current_received_ts = 563.025635
current_seq = 847
count = 544
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.026184
last_received_ts = 563.025635
last_seq = 847
current_ts = 563.042847
current_received_ts = 563.042297
current_seq = 848
count = 545
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 145us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.042847
last_received_ts = 563.042297
last_seq = 848
current_ts = 563.059448
current_received_ts = 563.058899
current_seq = 849
count = 546
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 122us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.059448
last_received_ts = 563.058899
last_seq = 849
current_ts = 563.076111
current_received_ts = 563.075562
current_seq = 850
count = 547
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 99us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.076111
last_received_ts = 563.075562
last_seq = 850
current_ts = 563.092712
current_received_ts = 563.092163
current_seq = 851
count = 548
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 86us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.092712
last_received_ts = 563.092163
last_seq = 851
current_ts = 563.109375
current_received_ts = 563.108826
current_seq = 852
count = 549
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.109375
last_received_ts = 563.108826
last_seq = 852
current_ts = 563.126038
current_received_ts = 563.125488
current_seq = 853
count = 550
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 99us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.126038
last_received_ts = 563.125488
last_seq = 853
current_ts = 563.142639
current_received_ts = 563.142090
current_seq = 854
count = 551
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 82us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.142639
last_received_ts = 563.142090
last_seq = 854
current_ts = 563.159302
current_received_ts = 563.158752
current_seq = 855
count = 552
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 80us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.159302
last_received_ts = 563.158752
last_seq = 855
current_ts = 563.175964
current_received_ts = 563.175415
current_seq = 856
count = 553
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 89us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.175964
last_received_ts = 563.175415
last_seq = 856
current_ts = 563.192566
current_received_ts = 563.192078
current_seq = 857
count = 554
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 88us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.192566
last_received_ts = 563.192078
last_seq = 857
current_ts = 563.209229
current_received_ts = 563.208679
current_seq = 858
count = 555
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 80us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.209229
last_received_ts = 563.208679
last_seq = 858
current_ts = 563.225891
current_received_ts = 563.225342
current_seq = 859
count = 556
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 96us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.225891
last_received_ts = 563.225342
last_seq = 859
current_ts = 563.242493
current_received_ts = 563.241943
current_seq = 860
count = 557
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 121us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.242493
last_received_ts = 563.241943
last_seq = 860
current_ts = 563.259155
current_received_ts = 563.258606
current_seq = 861
count = 558
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.259155
last_received_ts = 563.258606
last_seq = 861
current_ts = 563.275757
current_received_ts = 563.275208
current_seq = 862
count = 559
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.275757
last_received_ts = 563.275208
last_seq = 862
current_ts = 563.292419
current_received_ts = 563.291870
current_seq = 863
count = 560
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 82us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.292419
last_received_ts = 563.291870
last_seq = 863
current_ts = 563.309082
current_received_ts = 563.308533
current_seq = 864
count = 561
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 80us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.309082
last_received_ts = 563.308533
last_seq = 864
current_ts = 563.325684
current_received_ts = 563.325195
current_seq = 865
count = 562
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 88us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.325684
last_received_ts = 563.325195
last_seq = 865
current_ts = 563.342346
current_received_ts = 563.341797
current_seq = 866
count = 563
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 86us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.342346
last_received_ts = 563.341797
last_seq = 866
current_ts = 563.359009
current_received_ts = 563.358459
current_seq = 867
count = 564
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.359009
last_received_ts = 563.358459
last_seq = 867
current_ts = 563.375610
current_received_ts = 563.375061
current_seq = 868
count = 565
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 100us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.375610
last_received_ts = 563.375061
last_seq = 868
current_ts = 563.392273
current_received_ts = 563.391724
current_seq = 869
count = 566
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 92us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.392273
last_received_ts = 563.391724
last_seq = 869
current_ts = 563.408936
current_received_ts = 563.408386
current_seq = 870
count = 567
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 156us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.408936
last_received_ts = 563.408386
last_seq = 870
current_ts = 563.425537
current_received_ts = 563.424988
current_seq = 871
count = 568
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 96us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.425537
last_received_ts = 563.424988
last_seq = 871
current_ts = 563.442200
current_received_ts = 563.441650
current_seq = 872
count = 569
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.442200
last_received_ts = 563.441650
last_seq = 872
current_ts = 563.458862
current_received_ts = 563.458252
current_seq = 873
count = 570
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 149us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.458862
last_received_ts = 563.458252
last_seq = 873
current_ts = 563.475464
current_received_ts = 563.474854
current_seq = 874
count = 571
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 92us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.475464
last_received_ts = 563.474854
last_seq = 874
current_ts = 563.492126
current_received_ts = 563.491455
current_seq = 875
count = 572
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.492126
last_received_ts = 563.491455
last_seq = 875
current_ts = 563.508789
current_received_ts = 563.508118
current_seq = 876
count = 573
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.508789
last_received_ts = 563.508118
last_seq = 876
current_ts = 563.525391
current_received_ts = 563.524780
current_seq = 877
count = 574
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 92us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.525391
last_received_ts = 563.524780
last_seq = 877
current_ts = 563.542053
current_received_ts = 563.541382
current_seq = 878
count = 575
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 91us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.542053
last_received_ts = 563.541382
last_seq = 878
current_ts = 563.558716
current_received_ts = 563.558044
current_seq = 879
count = 576
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 87us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.558716
last_received_ts = 563.558044
last_seq = 879
current_ts = 563.575317
current_received_ts = 563.574707
current_seq = 880
count = 577
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 86us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.575317
last_received_ts = 563.574707
last_seq = 880
current_ts = 563.591980
current_received_ts = 563.591370
current_seq = 881
count = 578
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 99us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.591980
last_received_ts = 563.591370
last_seq = 881
current_ts = 563.608643
current_received_ts = 563.607971
current_seq = 882
count = 579
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 119us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.608643
last_received_ts = 563.607971
last_seq = 882
current_ts = 563.625244
current_received_ts = 563.624634
current_seq = 883
count = 580
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 86us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.625244
last_received_ts = 563.624634
last_seq = 883
current_ts = 563.641907
current_received_ts = 563.641235
current_seq = 884
count = 581
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 155us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.641907
last_received_ts = 563.641235
last_seq = 884
current_ts = 563.658569
current_received_ts = 563.657898
current_seq = 885
count = 582
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 115us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.658569
last_received_ts = 563.657898
last_seq = 885
current_ts = 563.675171
current_received_ts = 563.674561
current_seq = 886
count = 583
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 81us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.675171
last_received_ts = 563.674561
last_seq = 886
current_ts = 563.691833
current_received_ts = 563.691284
current_seq = 887
count = 584
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 144us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.691833
last_received_ts = 563.691284
last_seq = 887
current_ts = 563.708496
current_received_ts = 563.707947
current_seq = 888
count = 585
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 139us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.708496
last_received_ts = 563.707947
last_seq = 888
current_ts = 563.725098
current_received_ts = 563.724548
current_seq = 889
count = 586
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 99us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.725098
last_received_ts = 563.724548
last_seq = 889
current_ts = 563.741760
current_received_ts = 563.741211
current_seq = 890
count = 587
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 90us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.741760
last_received_ts = 563.741211
last_seq = 890
current_ts = 563.758423
current_received_ts = 563.757874
current_seq = 891
count = 588
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 99us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.758423
last_received_ts = 563.757874
last_seq = 891
current_ts = 563.775024
current_received_ts = 563.774475
current_seq = 892
count = 589
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 83us
(kms_flip:12003) DEBUG: name = flip
last_ts = 563.775024
last_received_ts = 563.774475
last_seq = 892
current_ts = 563.791687
current_received_ts = 563.791321
current_seq = 893
count = 590
seq_step = 1
(kms_flip:12003) DEBUG: Vblank took 559us
(kms_flip:12003) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:12003) CRITICAL: Failed assertion: end - start < 500
(kms_flip:12003) igt_core-INFO: Stack trace:
(kms_flip:12003) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:12003) igt_core-INFO:   #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0()
(kms_flip:12003) igt_core-INFO:   #2 ../tests/kms_flip.c:1891 run_test()
(kms_flip:12003) igt_core-INFO:   #3 ../tests/kms_flip.c:2126 __igt_unique____real_main2047()
(kms_flip:12003) igt_core-INFO:   #4 ../tests/kms_flip.c:2047 main()
(kms_flip:12003) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:12003) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:12003) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (11.225s)

Dmesg

<6> [583.287817] [IGT] kms_flip: starting dynamic subtest B-eDP1

<7> [583.307096] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

<7> [583.307249] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6

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

<7> [583.307702] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431]

<7> [583.308043] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432]

<7> [583.380691] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

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

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

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

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

<7> [583.382867] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0)

<7> [583.383255] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)

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

<7> [583.384067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0)

<7> [583.384426] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0)

<7> [583.384906] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0)

<7> [583.385360] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0)

<7> [583.385784] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0)

<7> [583.386130] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0)

<7> [583.386488] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0)

<7> [583.386867] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0)

<7> [583.387209] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0)

<7> [583.387531] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0)

<7> [583.387823] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0)

<7> [583.388106] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0)

<7> [583.388387] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0)

<7> [583.388730] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0)

<7> [583.389042] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0)

<7> [583.389313] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0)

<7> [583.389566] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0)

<7> [583.389803] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0)

<7> [583.390064] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0)

<7> [583.390310] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0)

<7> [583.390550] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0)

<7> [583.390784] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0)

<7> [583.390999] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0)

<7> [583.391209] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0)

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

<7> [583.391638] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)

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

<7> [583.392023] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0)

<7> [583.392209] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0)

<7> [583.392417] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0)

<7> [583.392612] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0)

<7> [583.392790] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

<7> [583.392958] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0

<7> [583.393207] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no

<7> [583.393373] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0

<7> [583.393582] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0

<7> [583.393769] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz

<7> [583.393958] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing

<7> [583.394125] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz

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

<7> [583.394477] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset]

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

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

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

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

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

<7> [583.395403] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no

<7> [583.395607] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off

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

<7> [583.396007] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM

<7> [583.396134] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]]

<7> [583.604710] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0

<7> [583.605227] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A

<7> [583.618949] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off

<7> [583.619483] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time

<7> [583.619945] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060

<7> [583.671903] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000

<7> [583.672475] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short

<7> [583.678978] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

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

<7> [583.679790] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A]

<7> [583.681501] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0

<7> [583.682235] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A

<7> [583.682894] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A]

<7> [583.683363] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1]

<7> [583.683804] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A]

<7> [583.684200] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B]

<7> [583.684637] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C]

<7> [583.685082] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2]

<7> [583.685459] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A]

<7> [583.685880] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B]

<7> [583.686260] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C]

<7> [583.686633] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3]

<7> [583.687109] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A]

<7> [583.687476] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B]

<7> [583.687877] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C]

<7> [583.688244] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1]

<7> [583.688735] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [583.689115] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: *)

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

<7> [583.690085] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A

<7> [583.690567] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000)

<7> [583.691214] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A]

<7> [583.691683] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

<7> [583.692239] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [583.692627] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384

<7> [583.693611] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B]

<7> [583.694024] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C]

<7> [583.694323] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B]

<7> [583.694390] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1]

<7> [583.694559] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)

<7> [583.694952] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000

<7> [583.695262] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000

<7> [583.695574] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0

<7> [583.695891] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B]

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

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

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

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

<7> [583.697262] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288)

<7> [583.697489] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)

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

<7> [583.697936] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)

<7> [583.698165] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)

<7> [583.698364] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)

<7> [583.698545] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)

<7> [583.698729] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)

<7> [583.698902] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)

<7> [583.699067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)

<7> [583.699256] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800)

<7> [583.699437] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)

<7> [583.699600] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)

<7> [583.699756] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906)

<7> [583.699900] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906)

<7> [583.700039] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)

<7> [583.700177] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)

<7> [583.700314] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)

<7> [583.700445] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)

<7> [583.700573] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)

<7> [583.700696] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)

<7> [583.700837] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)

<7> [583.700956] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800)

<7> [583.701074] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)

<7> [583.701189] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)

<7> [583.701303] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906)

<7> [583.701419] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906)

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

<7> [583.701642] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)

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

<7> [583.701865] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30)

<7> [583.701969] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710)

<7> [583.702067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710)

<7> [583.702164] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in port_clock (expected 0, found 432000)

<7> [583.702274] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset

<7> [583.702430] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes

<7> [583.702519] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2

<7> [583.702629] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

<7> [583.702702] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:264:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45

<7> [583.702785] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm

<7> [583.702858] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0

<7> [583.702931] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197

<7> [583.703001] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198

<7> [583.703088] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1

<7> [583.703184] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400

<7> [583.703277] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400

<7> [583.703369] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400

<7> [583.703457] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400

<7> [583.703541] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461

<7> [583.703624] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz

<7> [583.703724] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing

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

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

<7> [583.704009] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0

<7> [583.704106] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0

<7> [583.704194] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset]

<7> [583.704281] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB

<7> [583.704366] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0

<7> [583.704452] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid>

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

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

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

<7> [583.704799] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64

<7> [583.704880] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0

<7> [583.704963] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

<7> [583.705039] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled

<7> [583.705112] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled

<7> [583.705187] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0

<7> [583.705261] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4

<7> [583.705334] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14

<7> [583.705406] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB

<7> [583.705479] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB

<7> [583.705550] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0

<7> [583.705621] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range

<7> [583.705692] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined

<7> [583.705766] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1

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

<7> [583.705941] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97

<7> [583.706032] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906

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

<7> [583.706199] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

<7> [583.706277] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

<7> [583.706354] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [583.706432] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa

<7> [583.706509] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [583.706588] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0

<7> [583.706665] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

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

<7> [583.706823] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0

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

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

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

<7> [583.707119] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no

<7> [583.707192] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

<7> [583.707264] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1.

<7> [583.707337] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state:

<7> [583.707409] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21

<7> [583.707481] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1

<7> [583.707552] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0

<7> [583.707624] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0

<7> [583.707699] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1

<7> [583.707781] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23

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

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

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

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

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

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

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

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

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

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

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

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

<7> [583.708632] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

<7> [583.708758] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:431] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes

<7> [583.708843] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long

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

<7> [583.708937] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0

<7> [583.708958] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10

<7> [583.709016] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no

<7> [583.709093] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no

<7> [583.709169] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no

<7> [583.709191] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A]

<7> [583.709263] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no

<7> [583.709354] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no

<7> [583.709798] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2

<7> [583.709967] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B

<7> [583.710131] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000)

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

<7> [583.710368] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [583.710474] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480

<7> [583.710580] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A]

<7> [583.710672] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1]

<7> [583.710750] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A]

<7> [583.710846] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B]

<7> [583.710917] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C]

<7> [583.710990] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2]

<7> [583.711056] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A]

<7> [583.711120] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B]

<7> [583.711185] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C]

<7> [583.711247] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3]

<7> [583.711309] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A]

<7> [583.711370] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B]

<7> [583.711431] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C]

<7> [583.711515] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf

<7> [583.711668] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *)

<7> [583.711732] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes)

<7> [583.711847] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A

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

<7> [583.713019] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0

<7> [583.714987] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on

<7> [583.715078] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (465 ms remaining)

<7> [584.190882] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060

<7> [584.232117] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [584.232487] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on

<7> [584.232887] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063

<7> [584.269153] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

<7> [584.269597] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long

<7> [584.269996] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20

<7> [584.270668] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A]

<7> [584.444031] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [584.444601] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on

<7> [584.445042] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b

<7> [584.447362] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80

<7> [584.449163] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates

<7> [584.450330] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05

<7> [584.451877] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0

<7> [584.453529] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1

<7> [584.455001] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK

<7> [584.455594] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4

<7> [584.457618] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful

<7> [584.458261] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4

<7> [584.459382] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B

<7> [584.460159] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]]

<7> [584.460791] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B

<7> [584.461394] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 192000

<7> [584.477046] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2

<7> [584.478908] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1]

<7> [584.479383] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B]

<7> [587.024576] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off

<7> [587.025034] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067

<7> [594.361329] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

<7> [594.361920] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6

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

<6> [594.514616] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank@b-edp1