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

Detail	Value
Duration	7.63 seconds
Hostname	shard-mtlp-8
Igt-Version	IGT-Version: 2.4-g1ff14e3a8 (x86_64) (Linux: 7.1.0-rc2-CI_DRM_18461-g11d2d2a0077b+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (7.627s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:3233) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:3233) CRITICAL: Failed assertion: end - start < 500 (kms_flip:3233) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.028214 last_received_ts = 174.027893 last_seq = 869 current_ts = 174.039337 current_received_ts = 174.039047 current_seq = 870 count = 449 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.039337 last_received_ts = 174.039047 last_seq = 870 current_ts = 174.050446 current_received_ts = 174.050140 current_seq = 871 count = 450 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.050446 last_received_ts = 174.050140 last_seq = 871 current_ts = 174.061569 current_received_ts = 174.061234 current_seq = 872 count = 451 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.061569 last_received_ts = 174.061234 last_seq = 872 current_ts = 174.072693 current_received_ts = 174.072357 current_seq = 873 count = 452 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.072693 last_received_ts = 174.072357 last_seq = 873 current_ts = 174.083801 current_received_ts = 174.083527 current_seq = 874 count = 453 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 6us (kms_flip:3233) DEBUG: name = flip last_ts = 174.083801 last_received_ts = 174.083527 last_seq = 874 current_ts = 174.094925 current_received_ts = 174.094589 current_seq = 875 count = 454 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 3us (kms_flip:3233) DEBUG: name = flip last_ts = 174.094925 last_received_ts = 174.094589 last_seq = 875 current_ts = 174.106033 current_received_ts = 174.105698 current_seq = 876 count = 455 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.106033 last_received_ts = 174.105698 last_seq = 876 current_ts = 174.117157 current_received_ts = 174.116867 current_seq = 877 count = 456 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.117157 last_received_ts = 174.116867 last_seq = 877 current_ts = 174.128265 current_received_ts = 174.127945 current_seq = 878 count = 457 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.128265 last_received_ts = 174.127945 last_seq = 878 current_ts = 174.139389 current_received_ts = 174.139053 current_seq = 879 count = 458 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.139389 last_received_ts = 174.139053 last_seq = 879 current_ts = 174.150497 current_received_ts = 174.150177 current_seq = 880 count = 459 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.150497 last_received_ts = 174.150177 last_seq = 880 current_ts = 174.161621 current_received_ts = 174.161301 current_seq = 881 count = 460 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.161621 last_received_ts = 174.161301 last_seq = 881 current_ts = 174.172729 current_received_ts = 174.172409 current_seq = 882 count = 461 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.172729 last_received_ts = 174.172409 last_seq = 882 current_ts = 174.183853 current_received_ts = 174.183517 current_seq = 883 count = 462 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.183853 last_received_ts = 174.183517 last_seq = 883 current_ts = 174.194977 current_received_ts = 174.194656 current_seq = 884 count = 463 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.194977 last_received_ts = 174.194656 last_seq = 884 current_ts = 174.206085 current_received_ts = 174.205826 current_seq = 885 count = 464 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.206085 last_received_ts = 174.205826 last_seq = 885 current_ts = 174.217194 current_received_ts = 174.216873 current_seq = 886 count = 465 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.217194 last_received_ts = 174.216873 last_seq = 886 current_ts = 174.228317 current_received_ts = 174.227997 current_seq = 887 count = 466 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.228317 last_received_ts = 174.227997 last_seq = 887 current_ts = 174.239441 current_received_ts = 174.239136 current_seq = 888 count = 467 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.239441 last_received_ts = 174.239136 last_seq = 888 current_ts = 174.250549 current_received_ts = 174.250214 current_seq = 889 count = 468 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.250549 last_received_ts = 174.250214 last_seq = 889 current_ts = 174.261658 current_received_ts = 174.261337 current_seq = 890 count = 469 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.261658 last_received_ts = 174.261337 last_seq = 890 current_ts = 174.272781 current_received_ts = 174.272491 current_seq = 891 count = 470 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.272781 last_received_ts = 174.272491 last_seq = 891 current_ts = 174.283890 current_received_ts = 174.283569 current_seq = 892 count = 471 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.283890 last_received_ts = 174.283569 last_seq = 892 current_ts = 174.295013 current_received_ts = 174.294708 current_seq = 893 count = 472 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.295013 last_received_ts = 174.294708 last_seq = 893 current_ts = 174.306137 current_received_ts = 174.305832 current_seq = 894 count = 473 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.306137 last_received_ts = 174.305832 last_seq = 894 current_ts = 174.317245 current_received_ts = 174.316925 current_seq = 895 count = 474 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.317245 last_received_ts = 174.316925 last_seq = 895 current_ts = 174.328369 current_received_ts = 174.328049 current_seq = 896 count = 475 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 21us (kms_flip:3233) DEBUG: name = flip last_ts = 174.328369 last_received_ts = 174.328049 last_seq = 896 current_ts = 174.339478 current_received_ts = 174.339188 current_seq = 897 count = 476 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 6us (kms_flip:3233) DEBUG: name = flip last_ts = 174.339478 last_received_ts = 174.339188 last_seq = 897 current_ts = 174.350601 current_received_ts = 174.350281 current_seq = 898 count = 477 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.350601 last_received_ts = 174.350281 last_seq = 898 current_ts = 174.361710 current_received_ts = 174.361404 current_seq = 899 count = 478 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 6us (kms_flip:3233) DEBUG: name = flip last_ts = 174.361710 last_received_ts = 174.361404 last_seq = 899 current_ts = 174.372833 current_received_ts = 174.372513 current_seq = 900 count = 479 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.372833 last_received_ts = 174.372513 last_seq = 900 current_ts = 174.383957 current_received_ts = 174.383621 current_seq = 901 count = 480 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 6us (kms_flip:3233) DEBUG: name = flip last_ts = 174.383957 last_received_ts = 174.383621 last_seq = 901 current_ts = 174.395065 current_received_ts = 174.394745 current_seq = 902 count = 481 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.395065 last_received_ts = 174.394745 last_seq = 902 current_ts = 174.406189 current_received_ts = 174.405884 current_seq = 903 count = 482 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 6us (kms_flip:3233) DEBUG: name = flip last_ts = 174.406189 last_received_ts = 174.405884 last_seq = 903 current_ts = 174.417297 current_received_ts = 174.416962 current_seq = 904 count = 483 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.417297 last_received_ts = 174.416962 last_seq = 904 current_ts = 174.428406 current_received_ts = 174.428085 current_seq = 905 count = 484 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.428406 last_received_ts = 174.428085 last_seq = 905 current_ts = 174.439529 current_received_ts = 174.439194 current_seq = 906 count = 485 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.439529 last_received_ts = 174.439194 last_seq = 906 current_ts = 174.450653 current_received_ts = 174.450333 current_seq = 907 count = 486 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.450653 last_received_ts = 174.450333 last_seq = 907 current_ts = 174.461761 current_received_ts = 174.461487 current_seq = 908 count = 487 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.461761 last_received_ts = 174.461487 last_seq = 908 current_ts = 174.472885 current_received_ts = 174.472580 current_seq = 909 count = 488 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.472885 last_received_ts = 174.472580 last_seq = 909 current_ts = 174.483994 current_received_ts = 174.483673 current_seq = 910 count = 489 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.483994 last_received_ts = 174.483673 last_seq = 910 current_ts = 174.495117 current_received_ts = 174.494812 current_seq = 911 count = 490 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.495117 last_received_ts = 174.494812 last_seq = 911 current_ts = 174.506226 current_received_ts = 174.505920 current_seq = 912 count = 491 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.506226 last_received_ts = 174.505920 last_seq = 912 current_ts = 174.517349 current_received_ts = 174.517044 current_seq = 913 count = 492 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 3us (kms_flip:3233) DEBUG: name = flip last_ts = 174.517349 last_received_ts = 174.517044 last_seq = 913 current_ts = 174.528458 current_received_ts = 174.528168 current_seq = 914 count = 493 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.528458 last_received_ts = 174.528168 last_seq = 914 current_ts = 174.539581 current_received_ts = 174.539246 current_seq = 915 count = 494 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.539581 last_received_ts = 174.539246 last_seq = 915 current_ts = 174.550690 current_received_ts = 174.550385 current_seq = 916 count = 495 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.550690 last_received_ts = 174.550385 last_seq = 916 current_ts = 174.561813 current_received_ts = 174.561508 current_seq = 917 count = 496 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.561813 last_received_ts = 174.561508 last_seq = 917 current_ts = 174.572937 current_received_ts = 174.572601 current_seq = 918 count = 497 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.572937 last_received_ts = 174.572601 last_seq = 918 current_ts = 174.584045 current_received_ts = 174.583725 current_seq = 919 count = 498 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.584045 last_received_ts = 174.583725 last_seq = 919 current_ts = 174.595169 current_received_ts = 174.594864 current_seq = 920 count = 499 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.595169 last_received_ts = 174.594864 last_seq = 920 current_ts = 174.606277 current_received_ts = 174.605942 current_seq = 921 count = 500 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.606277 last_received_ts = 174.605942 last_seq = 921 current_ts = 174.617401 current_received_ts = 174.617081 current_seq = 922 count = 501 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.617401 last_received_ts = 174.617081 last_seq = 922 current_ts = 174.628510 current_received_ts = 174.628128 current_seq = 923 count = 502 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.628510 last_received_ts = 174.628128 last_seq = 923 current_ts = 174.639633 current_received_ts = 174.639313 current_seq = 924 count = 503 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.639633 last_received_ts = 174.639313 last_seq = 924 current_ts = 174.650742 current_received_ts = 174.650467 current_seq = 925 count = 504 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.650742 last_received_ts = 174.650467 last_seq = 925 current_ts = 174.661865 current_received_ts = 174.661667 current_seq = 926 count = 505 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 9us (kms_flip:3233) DEBUG: name = flip last_ts = 174.661865 last_received_ts = 174.661667 last_seq = 926 current_ts = 174.672974 current_received_ts = 174.672668 current_seq = 927 count = 506 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.672974 last_received_ts = 174.672668 last_seq = 927 current_ts = 174.684097 current_received_ts = 174.683807 current_seq = 928 count = 507 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.684097 last_received_ts = 174.683807 last_seq = 928 current_ts = 174.695206 current_received_ts = 174.694901 current_seq = 929 count = 508 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.695206 last_received_ts = 174.694901 last_seq = 929 current_ts = 174.706329 current_received_ts = 174.706024 current_seq = 930 count = 509 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 6us (kms_flip:3233) DEBUG: name = flip last_ts = 174.706329 last_received_ts = 174.706024 last_seq = 930 current_ts = 174.717453 current_received_ts = 174.717133 current_seq = 931 count = 510 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.717453 last_received_ts = 174.717133 last_seq = 931 current_ts = 174.728561 current_received_ts = 174.728226 current_seq = 932 count = 511 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.728561 last_received_ts = 174.728226 last_seq = 932 current_ts = 174.739685 current_received_ts = 174.739380 current_seq = 933 count = 512 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.739685 last_received_ts = 174.739380 last_seq = 933 current_ts = 174.750793 current_received_ts = 174.750504 current_seq = 934 count = 513 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.750793 last_received_ts = 174.750504 last_seq = 934 current_ts = 174.761902 current_received_ts = 174.761597 current_seq = 935 count = 514 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.761902 last_received_ts = 174.761597 last_seq = 935 current_ts = 174.773026 current_received_ts = 174.772705 current_seq = 936 count = 515 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.773026 last_received_ts = 174.772705 last_seq = 936 current_ts = 174.784134 current_received_ts = 174.783844 current_seq = 937 count = 516 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.784134 last_received_ts = 174.783844 last_seq = 937 current_ts = 174.795258 current_received_ts = 174.794937 current_seq = 938 count = 517 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 6us (kms_flip:3233) DEBUG: name = flip last_ts = 174.795258 last_received_ts = 174.794937 last_seq = 938 current_ts = 174.806381 current_received_ts = 174.806046 current_seq = 939 count = 518 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.806381 last_received_ts = 174.806046 last_seq = 939 current_ts = 174.817490 current_received_ts = 174.817184 current_seq = 940 count = 519 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.817490 last_received_ts = 174.817184 last_seq = 940 current_ts = 174.828598 current_received_ts = 174.828278 current_seq = 941 count = 520 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 3us (kms_flip:3233) DEBUG: name = flip last_ts = 174.828598 last_received_ts = 174.828278 last_seq = 941 current_ts = 174.839722 current_received_ts = 174.839417 current_seq = 942 count = 521 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.839722 last_received_ts = 174.839417 last_seq = 942 current_ts = 174.850845 current_received_ts = 174.850571 current_seq = 943 count = 522 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.850845 last_received_ts = 174.850571 last_seq = 943 current_ts = 174.861954 current_received_ts = 174.861633 current_seq = 944 count = 523 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.861954 last_received_ts = 174.861633 last_seq = 944 current_ts = 174.873077 current_received_ts = 174.872787 current_seq = 945 count = 524 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.873077 last_received_ts = 174.872787 last_seq = 945 current_ts = 174.884186 current_received_ts = 174.883896 current_seq = 946 count = 525 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.884186 last_received_ts = 174.883896 last_seq = 946 current_ts = 174.895309 current_received_ts = 174.894989 current_seq = 947 count = 526 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 21us (kms_flip:3233) DEBUG: name = flip last_ts = 174.895309 last_received_ts = 174.894989 last_seq = 947 current_ts = 174.906418 current_received_ts = 174.906128 current_seq = 948 count = 527 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.906418 last_received_ts = 174.906128 last_seq = 948 current_ts = 174.917542 current_received_ts = 174.917221 current_seq = 949 count = 528 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.917542 last_received_ts = 174.917221 last_seq = 949 current_ts = 174.928650 current_received_ts = 174.928329 current_seq = 950 count = 529 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.928650 last_received_ts = 174.928329 last_seq = 950 current_ts = 174.939774 current_received_ts = 174.939484 current_seq = 951 count = 530 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 6us (kms_flip:3233) DEBUG: name = flip last_ts = 174.939774 last_received_ts = 174.939484 last_seq = 951 current_ts = 174.950882 current_received_ts = 174.950577 current_seq = 952 count = 531 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 174.950882 last_received_ts = 174.950577 last_seq = 952 current_ts = 174.962006 current_received_ts = 174.961670 current_seq = 953 count = 532 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.962006 last_received_ts = 174.961670 last_seq = 953 current_ts = 174.973114 current_received_ts = 174.972809 current_seq = 954 count = 533 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.973114 last_received_ts = 174.972809 last_seq = 954 current_ts = 174.984238 current_received_ts = 174.983932 current_seq = 955 count = 534 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 6us (kms_flip:3233) DEBUG: name = flip last_ts = 174.984238 last_received_ts = 174.983932 last_seq = 955 current_ts = 174.995346 current_received_ts = 174.995056 current_seq = 956 count = 535 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 174.995346 last_received_ts = 174.995056 last_seq = 956 current_ts = 175.006470 current_received_ts = 175.006180 current_seq = 957 count = 536 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.006470 last_received_ts = 175.006180 last_seq = 957 current_ts = 175.017593 current_received_ts = 175.017273 current_seq = 958 count = 537 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.017593 last_received_ts = 175.017273 last_seq = 958 current_ts = 175.028702 current_received_ts = 175.028366 current_seq = 959 count = 538 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.028702 last_received_ts = 175.028366 last_seq = 959 current_ts = 175.039810 current_received_ts = 175.039536 current_seq = 960 count = 539 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 6us (kms_flip:3233) DEBUG: name = flip last_ts = 175.039810 last_received_ts = 175.039536 last_seq = 960 current_ts = 175.050934 current_received_ts = 175.050598 current_seq = 961 count = 540 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.050934 last_received_ts = 175.050598 last_seq = 961 current_ts = 175.062057 current_received_ts = 175.061722 current_seq = 962 count = 541 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.062057 last_received_ts = 175.061722 last_seq = 962 current_ts = 175.073166 current_received_ts = 175.072845 current_seq = 963 count = 542 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.073166 last_received_ts = 175.072845 last_seq = 963 current_ts = 175.084274 current_received_ts = 175.083969 current_seq = 964 count = 543 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.084274 last_received_ts = 175.083969 last_seq = 964 current_ts = 175.095398 current_received_ts = 175.095062 current_seq = 965 count = 544 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.095398 last_received_ts = 175.095062 last_seq = 965 current_ts = 175.106506 current_received_ts = 175.106201 current_seq = 966 count = 545 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 3us (kms_flip:3233) DEBUG: name = flip last_ts = 175.106506 last_received_ts = 175.106201 last_seq = 966 current_ts = 175.117630 current_received_ts = 175.117310 current_seq = 967 count = 546 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.117630 last_received_ts = 175.117310 last_seq = 967 current_ts = 175.128754 current_received_ts = 175.128448 current_seq = 968 count = 547 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.128754 last_received_ts = 175.128448 last_seq = 968 current_ts = 175.139862 current_received_ts = 175.139542 current_seq = 969 count = 548 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.139862 last_received_ts = 175.139542 last_seq = 969 current_ts = 175.150986 current_received_ts = 175.150665 current_seq = 970 count = 549 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 6us (kms_flip:3233) DEBUG: name = flip last_ts = 175.150986 last_received_ts = 175.150665 last_seq = 970 current_ts = 175.162094 current_received_ts = 175.161774 current_seq = 971 count = 550 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.162094 last_received_ts = 175.161774 last_seq = 971 current_ts = 175.173218 current_received_ts = 175.172913 current_seq = 972 count = 551 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.173218 last_received_ts = 175.172913 last_seq = 972 current_ts = 175.184326 current_received_ts = 175.184036 current_seq = 973 count = 552 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.184326 last_received_ts = 175.184036 last_seq = 973 current_ts = 175.195435 current_received_ts = 175.195129 current_seq = 974 count = 553 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.195435 last_received_ts = 175.195129 last_seq = 974 current_ts = 175.206558 current_received_ts = 175.206253 current_seq = 975 count = 554 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.206558 last_received_ts = 175.206253 last_seq = 975 current_ts = 175.217682 current_received_ts = 175.217346 current_seq = 976 count = 555 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.217682 last_received_ts = 175.217346 last_seq = 976 current_ts = 175.228790 current_received_ts = 175.228470 current_seq = 977 count = 556 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.228790 last_received_ts = 175.228470 last_seq = 977 current_ts = 175.239914 current_received_ts = 175.239594 current_seq = 978 count = 557 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.239914 last_received_ts = 175.239594 last_seq = 978 current_ts = 175.251022 current_received_ts = 175.250702 current_seq = 979 count = 558 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.251022 last_received_ts = 175.250702 last_seq = 979 current_ts = 175.262146 current_received_ts = 175.261856 current_seq = 980 count = 559 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.262146 last_received_ts = 175.261856 last_seq = 980 current_ts = 175.273254 current_received_ts = 175.272934 current_seq = 981 count = 560 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.273254 last_received_ts = 175.272934 last_seq = 981 current_ts = 175.284378 current_received_ts = 175.284088 current_seq = 982 count = 561 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.284378 last_received_ts = 175.284088 last_seq = 982 current_ts = 175.295486 current_received_ts = 175.295212 current_seq = 983 count = 562 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.295486 last_received_ts = 175.295212 last_seq = 983 current_ts = 175.306610 current_received_ts = 175.306290 current_seq = 984 count = 563 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.306610 last_received_ts = 175.306290 last_seq = 984 current_ts = 175.317719 current_received_ts = 175.317398 current_seq = 985 count = 564 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.317719 last_received_ts = 175.317398 last_seq = 985 current_ts = 175.328842 current_received_ts = 175.328522 current_seq = 986 count = 565 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.328842 last_received_ts = 175.328522 last_seq = 986 current_ts = 175.339951 current_received_ts = 175.339645 current_seq = 987 count = 566 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.339951 last_received_ts = 175.339645 last_seq = 987 current_ts = 175.351074 current_received_ts = 175.350769 current_seq = 988 count = 567 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 5us (kms_flip:3233) DEBUG: name = flip last_ts = 175.351074 last_received_ts = 175.350769 last_seq = 988 current_ts = 175.362183 current_received_ts = 175.361877 current_seq = 989 count = 568 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 4us (kms_flip:3233) DEBUG: name = flip last_ts = 175.362183 last_received_ts = 175.361877 last_seq = 989 current_ts = 175.373306 current_received_ts = 175.372986 current_seq = 990 count = 569 seq_step = 1 (kms_flip:3233) DEBUG: Vblank took 917us (kms_flip:3233) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:3233) CRITICAL: Failed assertion: end - start < 500 (kms_flip:3233) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:3233) igt_core-INFO: Stack trace: (kms_flip:3233) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:3233) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:3233) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:3233) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() (kms_flip:3233) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:3233) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:3233) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:3233) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (7.627s)
Dmesg	<6> [228.346205] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [228.346676] i915 0000:00:02.0: [drm:i915_dpt_create [i915]] Allocating dpt from smem <7> [228.346918] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:566] <7> [228.347017] i915 0000:00:02.0: [drm:i915_dpt_create [i915]] Allocating dpt from smem <7> [228.347288] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:568] <7> [228.350187] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [228.350576] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [228.369452] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [228.369720] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [228.378503] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [228.378774] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [228.396363] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [228.396641] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [228.403754] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [228.403857] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [228.404049] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [228.404220] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [228.404381] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [228.404566] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 7483046/8388608 link 498869/524288, found tu 0, data 0/0 link 0/0) <7> [228.404745] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [228.404898] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [228.405050] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [228.405275] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [228.405431] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [228.405582] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [228.405738] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [228.405908] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [228.406113] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [228.406309] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1801, found 0) <7> [228.406495] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [228.406681] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [228.406836] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1878, found 0) <7> [228.406990] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1878, found 0) <7> [228.407143] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [228.407309] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [228.407465] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [228.407618] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [228.407773] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [228.407928] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [228.408086] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [228.408251] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1801, found 0) <7> [228.408405] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [228.408557] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [228.408721] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1878, found 0) <7> [228.408876] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1878, found 0) <7> [228.409032] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [228.409186] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [228.409353] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [228.409509] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [228.409666] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [228.409821] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 513820, found 0) <7> [228.409973] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 513820, found 0) <7> [228.410125] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 540000, found 0) <7> [228.410286] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in set_context_latency (expected 1, found 0) <7> [228.410437] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [228.410588] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:151:pipe A] releasing DPLL 0 <7> [228.410781] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [228.410952] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [228.411136] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:145:cursor A] ddb (4001 - 4096) -> ( 0 - 0), size 95 -> 0 <7> [228.411296] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:151:pipe A] min cdclk: 256910 kHz -> 0 kHz <7> [228.411453] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Can change cdclk via squashing <7> [228.411605] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz <7> [228.411755] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [228.411949] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:151:pipe A] enable: no [modeset] <7> [228.412108] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [228.412303] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [228.412460] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [228.412619] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [228.412771] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [228.412924] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [228.413213] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]] <7> [228.615133] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:508:eDP-1] set backlight PWM = 0 <7> [228.615860] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [228.621677] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turn panel power off <7> [228.622055] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x00000089, pins 0x00000010, long 0x00000000 <7> [228.622240] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 wait for panel power off time <7> [228.622777] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [228.622633] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:507:DDI A/PHY A] - short <7> [228.674684] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010 <7> [228.675264] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:507:DDI A/PHY A] - long <7> [228.675783] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [228.682301] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [228.682821] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [228.682947] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring short hpd on eDP [ENCODER:507:DDI A/PHY A] <7> [228.683483] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:507:DDI A/PHY A] <7> [228.684640] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0 <7> [228.685224] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A <7> [228.685576] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A] <7> [228.685855] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:516:DDI B/PHY B] <7> [228.686143] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DP-MST A] <7> [228.686412] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:519:DP-MST B] <7> [228.686782] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST C] <7> [228.687203] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST D] <7> [228.687590] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:534:DDI TC1/PHY TC1] <7> [228.687867] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST A] <7> [228.688141] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST B] <7> [228.688313] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST C] <7> [228.688482] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST D] <7> [228.688629] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:543:DDI TC2/PHY TC2] <7> [228.688787] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DDI TC3/PHY TC3] <7> [228.688976] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST A] <7> [228.689155] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST B] <7> [228.689322] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST C] <7> [228.689481] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:552:DP-MST D] <7> [228.689625] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:556:DDI TC4/PHY TC4] <7> [228.689770] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:558:DP-MST A] <7> [228.689916] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:559:DP-MST B] <7> [228.690093] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:560:DP-MST C] <7> [228.690240] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:561:DP-MST D] <7> [228.690397] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:508:eDP-1] <7> [228.690605] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no) <7> [228.690780] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: yes -> no (pipe: ) <7> [228.690982] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [228.691280] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_A <7> [228.691458] i915 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [i915]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [228.691689] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:151:pipe A] <7> [228.691935] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Post changing CDCLK to 172800 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [228.692179] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=432 <7> [228.692539] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [228.692686] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C] <7> [228.692798] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D] <7> [228.692917] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [228.692944] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:508:eDP-1] <7> [228.693007] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:508:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [228.693208] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:507:DDI A/PHY A][CRTC:269:pipe B] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [228.693351] i915 0000:00:02.0: [drm:intel_dp_compute_output_format [i915]] DP lane count 4 clock 540000 bpp input 30 compressed 0.0000 HDR no link rate required 1926825 available 2160000 <7> [228.693515] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:269:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [228.693674] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:507:DDI A/PHY A] [CRTC:269:pipe B] <7> [228.693818] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [228.693976] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [228.694165] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [228.694347] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [228.694507] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7483046/8388608 link 498869/524288) <7> [228.694663] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [228.694818] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [228.695001] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [228.695183] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [228.695336] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [228.695485] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [228.695636] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [228.695793] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [228.695947] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [228.696115] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1801) <7> [228.696268] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [228.696419] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [228.696581] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1878) <7> [228.696734] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1878) <7> [228.696887] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [228.697100] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [228.697656] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [228.698211] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [228.698630] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [228.699033] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [228.699415] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [228.699680] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1801) <7> [228.699899] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [228.700131] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [228.700353] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1878) <7> [228.700565] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1878) <7> [228.700775] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [228.700989] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [228.701202] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [228.701349] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [228.701496] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [228.701640] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 513820) <7> [228.701785] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 513820) <7> [228.701934] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in port_clock (expected 0, found 540000) <7> [228.702096] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in set_context_latency (expected 0, found 1) <7> [228.702242] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:269:pipe B] fastset requirement not met, forcing full modeset <7> [228.702418] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [228.702561] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:269:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [228.702722] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:153:plane 1B] ddb ( 0 - 0) -> ( 0 - 4001), size 0 -> 4001 <7> [228.702863] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:263:cursor B] ddb ( 0 - 0) -> (4001 - 4096), size 0 -> 95 <7> [228.703012] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153: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> [228.703153] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 16, 16, 19, 19, 28, 0, 0, 0, 4, 0 <7> [228.703293] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 365, 365, 434, 434, 638, 0, 0, 197, 92, 197 <7> [228.703434] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 547, 547, 729, 0, 0, 198, 183, 198 <7> [228.703585] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:269:pipe B] data rate 2055280 num active planes 1 <7> [228.703736] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200 <7> [228.703885] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [228.704050] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [228.704194] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [228.704339] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159 <7> [228.704487] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:269:pipe B] min cdclk: 0 kHz -> 256910 kHz <7> [228.704645] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Can change cdclk via squashing <7> [228.704790] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 307200 kHz, actual 307200 kHz <7> [228.704933] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [228.705112] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:269:pipe B] allocated DPLL 0 <7> [228.705262] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:269:pipe B] reserving DPLL 0 <7> [228.705415] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:269:pipe B] enable: yes [modeset] <7> [228.705565] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [228.705714] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [228.705861] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [228.706012] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [228.706160] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [228.706308] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [228.706454] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m_n: lanes: 4; data_m: 7483046, data_n: 8388608, link_m: 498869, link_n: 524288, tu: 64 <7> [228.706600] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [228.706744] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled <7> [228.706888] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled <7> [228.707084] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [228.707233] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum hblank: 0 <7> [228.707377] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [228.707522] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] DP SDP: VSC, revision 4, length 14 <7> [228.707666] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB <7> [228.707810] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB <7> [228.707957] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0 <7> [228.708125] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range <7> [228.708273] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined <7> [228.708434] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1 <7> [228.708579] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 1 <7> [228.708724] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1878, vmax: 1878, flipline: 1878, pipeline full: 0, guardband: 76 vsync start: 75, vsync end: 69 <7> [228.708869] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1878, vmax vtotal: 1878 <7> [228.709024] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [228.709173] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa <7> [228.709321] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa <7> [228.709467] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1801-1878 vs=1803-1809 vt=1878, flags=0xa <7> [228.709613] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x40 0xa <7> [228.709759] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1801-1878 vs=1803-1809 vt=1878, flags=0xa <7> [228.709906] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 540000, pixel rate 513820, min cdclk 256910, min voltage level 0 <7> [228.710073] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 48, ips linetime: 0 <7> [228.710052] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off <7> [228.710219] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [228.710307] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6 <7> [228.710364] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 2880x1800+0+0 <7> [228.710510] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [228.710532] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02 <7> [228.710672] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [228.710818] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [228.710967] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [228.711129] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] c10pll_hw_state: fracen: yes, <7> [228.711274] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] quot: 40960, rem: 0, den: 1, <7> [228.711419] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] multiplier: 140, tx_clk_div: 0. <7> [228.711566] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] c10pll_rawhw_state: <7> [228.711712] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] tx: 0x10, cmn: 0x21 <7> [228.711857] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[0] = 0xf4, pll[1] = 0x0, pll[2] = 0xf8, pll[3] = 0x0 <7> [228.712017] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [228.712168] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [228.712314] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[12] = 0xa0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x0 <7> [228.712458] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[16] = 0x84, pll[17] = 0x4f, pll[18] = 0xe5, pll[19] = 0x23 <7> [228.712602] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [228.712747] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [228.712894] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [228.713051] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [228.713198] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [228.713344] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [228.713489] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [228.713635] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [228.713782] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [228.713931] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [228.714085] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [228.714231] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [228.714376] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:153:plane 1B] fb: [FB:566] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [228.714521] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [228.714667] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [228.714814] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:183:plane 2B] fb: [NOFB], visible: no <7> [228.714959] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:213:plane 3B] fb: [NOFB], visible: no <7> [228.715127] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:243:plane 4B] fb: [NOFB], visible: no <7> [228.715272] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:253:plane 5B] fb: [NOFB], visible: no <7> [228.715416] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:263:cursor B] fb: [NOFB], visible: no <7> [228.718398] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off <7> [228.718724] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00 <7> [228.718950] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [228.719140] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_B <7> [228.719336] i915 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [i915]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [228.719510] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 307200 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [228.719693] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=768 <7> [228.719842] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A] <7> [228.719990] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:516:DDI B/PHY B] <7> [228.720159] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DP-MST A] <7> [228.720304] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:519:DP-MST B] <7> [228.720449] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST C] <7> [228.720595] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST D] <7> [228.720738] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:534:DDI TC1/PHY TC1] <7> [228.720881] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST A] <7> [228.721035] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST B] <7> [228.721181] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST C] <7> [228.721325] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST D] <7> [228.721476] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:543:DDI TC2/PHY TC2] <7> [228.721651] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DDI TC3/PHY TC3] <7> [228.721826] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST A] <7> [228.721973] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST B] <7> [228.722137] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST C] <7> [228.722281] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:552:DP-MST D] <7> [228.722427] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:556:DDI TC4/PHY TC4] <7> [228.722571] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:558:DP-MST A] <7> [228.722715] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:559:DP-MST B] <7> [228.722859] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:560:DP-MST C] <7> [228.723012] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:561:DP-MST D] <7> [228.723186] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0xf <7> [228.723430] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: no -> yes (pipe: *) <7> [228.723586] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 4 (mbus joined: yes) <7> [228.723808] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A <7> [228.725082] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:269:pipe B] <7> [228.725264] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0 <7> [228.727231] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turn panel power on <7> [228.727395] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 wait for panel power cycle (456 ms remaining) <7> [229.191143] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x00000000 PP_CONTROL: 0x00000060 <7> [229.201796] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [229.202370] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 wait for panel power on <7> [229.202956] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [229.234439] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010 <7> [229.235022] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:507:DDI A/PHY A] - long <7> [229.235546] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [229.236169] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:507:DDI A/PHY A] <7> [229.407683] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [229.408449] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turning VDD on <7> [229.409174] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [229.412391] i915 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c4 41 00 00 01 c0 02 00 00 00 00 0b 80 <7> [229.413804] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [229.414662] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 07 <7> [229.415799] i915 0000:00:02.0: [drm:intel_dp_set_signal_levels [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [229.416829] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [229.417794] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Clock recovery OK <7> [229.417928] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using DP training pattern TPS3 <7> [229.419231] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [229.419365] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Link Training passed at link rate = 540000, lane count = 4 <7> [229.420011] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [229.420267] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]] <7> [229.420400] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe B <7> [229.420625] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:508:eDP-1] set backlight PWM = 13892 <7> [229.442657] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR2 <7> [229.444245] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:508:eDP-1] <7> [229.444511] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:269:pipe B] <7> [231.965225] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turning VDD off <7> [231.965849] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [235.805283] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off <7> [235.805883] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6 <7> [235.806456] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02 <6> [235.976149] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

7.63 seconds

Hostname

shard-mtlp-8

Igt-Version

IGT-Version: 2.4-g1ff14e3a8 (x86_64) (Linux: 7.1.0-rc2-CI_DRM_18461-g11d2d2a0077b+ x86_64)

Out

Starting dynamic subtest: B-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (7.627s)

Err

Starting dynamic subtest: B-eDP1
(kms_flip:3233) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:3233) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3233) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.028214
last_received_ts = 174.027893
last_seq = 869
current_ts = 174.039337
current_received_ts = 174.039047
current_seq = 870
count = 449
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.039337
last_received_ts = 174.039047
last_seq = 870
current_ts = 174.050446
current_received_ts = 174.050140
current_seq = 871
count = 450
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.050446
last_received_ts = 174.050140
last_seq = 871
current_ts = 174.061569
current_received_ts = 174.061234
current_seq = 872
count = 451
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.061569
last_received_ts = 174.061234
last_seq = 872
current_ts = 174.072693
current_received_ts = 174.072357
current_seq = 873
count = 452
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.072693
last_received_ts = 174.072357
last_seq = 873
current_ts = 174.083801
current_received_ts = 174.083527
current_seq = 874
count = 453
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 6us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.083801
last_received_ts = 174.083527
last_seq = 874
current_ts = 174.094925
current_received_ts = 174.094589
current_seq = 875
count = 454
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 3us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.094925
last_received_ts = 174.094589
last_seq = 875
current_ts = 174.106033
current_received_ts = 174.105698
current_seq = 876
count = 455
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.106033
last_received_ts = 174.105698
last_seq = 876
current_ts = 174.117157
current_received_ts = 174.116867
current_seq = 877
count = 456
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.117157
last_received_ts = 174.116867
last_seq = 877
current_ts = 174.128265
current_received_ts = 174.127945
current_seq = 878
count = 457
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.128265
last_received_ts = 174.127945
last_seq = 878
current_ts = 174.139389
current_received_ts = 174.139053
current_seq = 879
count = 458
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.139389
last_received_ts = 174.139053
last_seq = 879
current_ts = 174.150497
current_received_ts = 174.150177
current_seq = 880
count = 459
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.150497
last_received_ts = 174.150177
last_seq = 880
current_ts = 174.161621
current_received_ts = 174.161301
current_seq = 881
count = 460
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.161621
last_received_ts = 174.161301
last_seq = 881
current_ts = 174.172729
current_received_ts = 174.172409
current_seq = 882
count = 461
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.172729
last_received_ts = 174.172409
last_seq = 882
current_ts = 174.183853
current_received_ts = 174.183517
current_seq = 883
count = 462
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.183853
last_received_ts = 174.183517
last_seq = 883
current_ts = 174.194977
current_received_ts = 174.194656
current_seq = 884
count = 463
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.194977
last_received_ts = 174.194656
last_seq = 884
current_ts = 174.206085
current_received_ts = 174.205826
current_seq = 885
count = 464
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.206085
last_received_ts = 174.205826
last_seq = 885
current_ts = 174.217194
current_received_ts = 174.216873
current_seq = 886
count = 465
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.217194
last_received_ts = 174.216873
last_seq = 886
current_ts = 174.228317
current_received_ts = 174.227997
current_seq = 887
count = 466
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.228317
last_received_ts = 174.227997
last_seq = 887
current_ts = 174.239441
current_received_ts = 174.239136
current_seq = 888
count = 467
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.239441
last_received_ts = 174.239136
last_seq = 888
current_ts = 174.250549
current_received_ts = 174.250214
current_seq = 889
count = 468
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.250549
last_received_ts = 174.250214
last_seq = 889
current_ts = 174.261658
current_received_ts = 174.261337
current_seq = 890
count = 469
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.261658
last_received_ts = 174.261337
last_seq = 890
current_ts = 174.272781
current_received_ts = 174.272491
current_seq = 891
count = 470
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.272781
last_received_ts = 174.272491
last_seq = 891
current_ts = 174.283890
current_received_ts = 174.283569
current_seq = 892
count = 471
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.283890
last_received_ts = 174.283569
last_seq = 892
current_ts = 174.295013
current_received_ts = 174.294708
current_seq = 893
count = 472
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.295013
last_received_ts = 174.294708
last_seq = 893
current_ts = 174.306137
current_received_ts = 174.305832
current_seq = 894
count = 473
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.306137
last_received_ts = 174.305832
last_seq = 894
current_ts = 174.317245
current_received_ts = 174.316925
current_seq = 895
count = 474
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.317245
last_received_ts = 174.316925
last_seq = 895
current_ts = 174.328369
current_received_ts = 174.328049
current_seq = 896
count = 475
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 21us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.328369
last_received_ts = 174.328049
last_seq = 896
current_ts = 174.339478
current_received_ts = 174.339188
current_seq = 897
count = 476
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 6us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.339478
last_received_ts = 174.339188
last_seq = 897
current_ts = 174.350601
current_received_ts = 174.350281
current_seq = 898
count = 477
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.350601
last_received_ts = 174.350281
last_seq = 898
current_ts = 174.361710
current_received_ts = 174.361404
current_seq = 899
count = 478
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 6us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.361710
last_received_ts = 174.361404
last_seq = 899
current_ts = 174.372833
current_received_ts = 174.372513
current_seq = 900
count = 479
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.372833
last_received_ts = 174.372513
last_seq = 900
current_ts = 174.383957
current_received_ts = 174.383621
current_seq = 901
count = 480
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 6us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.383957
last_received_ts = 174.383621
last_seq = 901
current_ts = 174.395065
current_received_ts = 174.394745
current_seq = 902
count = 481
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.395065
last_received_ts = 174.394745
last_seq = 902
current_ts = 174.406189
current_received_ts = 174.405884
current_seq = 903
count = 482
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 6us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.406189
last_received_ts = 174.405884
last_seq = 903
current_ts = 174.417297
current_received_ts = 174.416962
current_seq = 904
count = 483
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.417297
last_received_ts = 174.416962
last_seq = 904
current_ts = 174.428406
current_received_ts = 174.428085
current_seq = 905
count = 484
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.428406
last_received_ts = 174.428085
last_seq = 905
current_ts = 174.439529
current_received_ts = 174.439194
current_seq = 906
count = 485
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.439529
last_received_ts = 174.439194
last_seq = 906
current_ts = 174.450653
current_received_ts = 174.450333
current_seq = 907
count = 486
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.450653
last_received_ts = 174.450333
last_seq = 907
current_ts = 174.461761
current_received_ts = 174.461487
current_seq = 908
count = 487
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.461761
last_received_ts = 174.461487
last_seq = 908
current_ts = 174.472885
current_received_ts = 174.472580
current_seq = 909
count = 488
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.472885
last_received_ts = 174.472580
last_seq = 909
current_ts = 174.483994
current_received_ts = 174.483673
current_seq = 910
count = 489
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.483994
last_received_ts = 174.483673
last_seq = 910
current_ts = 174.495117
current_received_ts = 174.494812
current_seq = 911
count = 490
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.495117
last_received_ts = 174.494812
last_seq = 911
current_ts = 174.506226
current_received_ts = 174.505920
current_seq = 912
count = 491
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.506226
last_received_ts = 174.505920
last_seq = 912
current_ts = 174.517349
current_received_ts = 174.517044
current_seq = 913
count = 492
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 3us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.517349
last_received_ts = 174.517044
last_seq = 913
current_ts = 174.528458
current_received_ts = 174.528168
current_seq = 914
count = 493
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.528458
last_received_ts = 174.528168
last_seq = 914
current_ts = 174.539581
current_received_ts = 174.539246
current_seq = 915
count = 494
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.539581
last_received_ts = 174.539246
last_seq = 915
current_ts = 174.550690
current_received_ts = 174.550385
current_seq = 916
count = 495
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.550690
last_received_ts = 174.550385
last_seq = 916
current_ts = 174.561813
current_received_ts = 174.561508
current_seq = 917
count = 496
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.561813
last_received_ts = 174.561508
last_seq = 917
current_ts = 174.572937
current_received_ts = 174.572601
current_seq = 918
count = 497
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.572937
last_received_ts = 174.572601
last_seq = 918
current_ts = 174.584045
current_received_ts = 174.583725
current_seq = 919
count = 498
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.584045
last_received_ts = 174.583725
last_seq = 919
current_ts = 174.595169
current_received_ts = 174.594864
current_seq = 920
count = 499
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.595169
last_received_ts = 174.594864
last_seq = 920
current_ts = 174.606277
current_received_ts = 174.605942
current_seq = 921
count = 500
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.606277
last_received_ts = 174.605942
last_seq = 921
current_ts = 174.617401
current_received_ts = 174.617081
current_seq = 922
count = 501
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.617401
last_received_ts = 174.617081
last_seq = 922
current_ts = 174.628510
current_received_ts = 174.628128
current_seq = 923
count = 502
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.628510
last_received_ts = 174.628128
last_seq = 923
current_ts = 174.639633
current_received_ts = 174.639313
current_seq = 924
count = 503
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.639633
last_received_ts = 174.639313
last_seq = 924
current_ts = 174.650742
current_received_ts = 174.650467
current_seq = 925
count = 504
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.650742
last_received_ts = 174.650467
last_seq = 925
current_ts = 174.661865
current_received_ts = 174.661667
current_seq = 926
count = 505
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 9us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.661865
last_received_ts = 174.661667
last_seq = 926
current_ts = 174.672974
current_received_ts = 174.672668
current_seq = 927
count = 506
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.672974
last_received_ts = 174.672668
last_seq = 927
current_ts = 174.684097
current_received_ts = 174.683807
current_seq = 928
count = 507
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.684097
last_received_ts = 174.683807
last_seq = 928
current_ts = 174.695206
current_received_ts = 174.694901
current_seq = 929
count = 508
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.695206
last_received_ts = 174.694901
last_seq = 929
current_ts = 174.706329
current_received_ts = 174.706024
current_seq = 930
count = 509
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 6us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.706329
last_received_ts = 174.706024
last_seq = 930
current_ts = 174.717453
current_received_ts = 174.717133
current_seq = 931
count = 510
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.717453
last_received_ts = 174.717133
last_seq = 931
current_ts = 174.728561
current_received_ts = 174.728226
current_seq = 932
count = 511
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.728561
last_received_ts = 174.728226
last_seq = 932
current_ts = 174.739685
current_received_ts = 174.739380
current_seq = 933
count = 512
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.739685
last_received_ts = 174.739380
last_seq = 933
current_ts = 174.750793
current_received_ts = 174.750504
current_seq = 934
count = 513
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.750793
last_received_ts = 174.750504
last_seq = 934
current_ts = 174.761902
current_received_ts = 174.761597
current_seq = 935
count = 514
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.761902
last_received_ts = 174.761597
last_seq = 935
current_ts = 174.773026
current_received_ts = 174.772705
current_seq = 936
count = 515
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.773026
last_received_ts = 174.772705
last_seq = 936
current_ts = 174.784134
current_received_ts = 174.783844
current_seq = 937
count = 516
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.784134
last_received_ts = 174.783844
last_seq = 937
current_ts = 174.795258
current_received_ts = 174.794937
current_seq = 938
count = 517
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 6us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.795258
last_received_ts = 174.794937
last_seq = 938
current_ts = 174.806381
current_received_ts = 174.806046
current_seq = 939
count = 518
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.806381
last_received_ts = 174.806046
last_seq = 939
current_ts = 174.817490
current_received_ts = 174.817184
current_seq = 940
count = 519
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.817490
last_received_ts = 174.817184
last_seq = 940
current_ts = 174.828598
current_received_ts = 174.828278
current_seq = 941
count = 520
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 3us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.828598
last_received_ts = 174.828278
last_seq = 941
current_ts = 174.839722
current_received_ts = 174.839417
current_seq = 942
count = 521
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.839722
last_received_ts = 174.839417
last_seq = 942
current_ts = 174.850845
current_received_ts = 174.850571
current_seq = 943
count = 522
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.850845
last_received_ts = 174.850571
last_seq = 943
current_ts = 174.861954
current_received_ts = 174.861633
current_seq = 944
count = 523
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.861954
last_received_ts = 174.861633
last_seq = 944
current_ts = 174.873077
current_received_ts = 174.872787
current_seq = 945
count = 524
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.873077
last_received_ts = 174.872787
last_seq = 945
current_ts = 174.884186
current_received_ts = 174.883896
current_seq = 946
count = 525
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.884186
last_received_ts = 174.883896
last_seq = 946
current_ts = 174.895309
current_received_ts = 174.894989
current_seq = 947
count = 526
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 21us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.895309
last_received_ts = 174.894989
last_seq = 947
current_ts = 174.906418
current_received_ts = 174.906128
current_seq = 948
count = 527
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.906418
last_received_ts = 174.906128
last_seq = 948
current_ts = 174.917542
current_received_ts = 174.917221
current_seq = 949
count = 528
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.917542
last_received_ts = 174.917221
last_seq = 949
current_ts = 174.928650
current_received_ts = 174.928329
current_seq = 950
count = 529
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.928650
last_received_ts = 174.928329
last_seq = 950
current_ts = 174.939774
current_received_ts = 174.939484
current_seq = 951
count = 530
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 6us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.939774
last_received_ts = 174.939484
last_seq = 951
current_ts = 174.950882
current_received_ts = 174.950577
current_seq = 952
count = 531
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.950882
last_received_ts = 174.950577
last_seq = 952
current_ts = 174.962006
current_received_ts = 174.961670
current_seq = 953
count = 532
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.962006
last_received_ts = 174.961670
last_seq = 953
current_ts = 174.973114
current_received_ts = 174.972809
current_seq = 954
count = 533
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.973114
last_received_ts = 174.972809
last_seq = 954
current_ts = 174.984238
current_received_ts = 174.983932
current_seq = 955
count = 534
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 6us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.984238
last_received_ts = 174.983932
last_seq = 955
current_ts = 174.995346
current_received_ts = 174.995056
current_seq = 956
count = 535
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 174.995346
last_received_ts = 174.995056
last_seq = 956
current_ts = 175.006470
current_received_ts = 175.006180
current_seq = 957
count = 536
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.006470
last_received_ts = 175.006180
last_seq = 957
current_ts = 175.017593
current_received_ts = 175.017273
current_seq = 958
count = 537
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.017593
last_received_ts = 175.017273
last_seq = 958
current_ts = 175.028702
current_received_ts = 175.028366
current_seq = 959
count = 538
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.028702
last_received_ts = 175.028366
last_seq = 959
current_ts = 175.039810
current_received_ts = 175.039536
current_seq = 960
count = 539
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 6us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.039810
last_received_ts = 175.039536
last_seq = 960
current_ts = 175.050934
current_received_ts = 175.050598
current_seq = 961
count = 540
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.050934
last_received_ts = 175.050598
last_seq = 961
current_ts = 175.062057
current_received_ts = 175.061722
current_seq = 962
count = 541
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.062057
last_received_ts = 175.061722
last_seq = 962
current_ts = 175.073166
current_received_ts = 175.072845
current_seq = 963
count = 542
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.073166
last_received_ts = 175.072845
last_seq = 963
current_ts = 175.084274
current_received_ts = 175.083969
current_seq = 964
count = 543
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.084274
last_received_ts = 175.083969
last_seq = 964
current_ts = 175.095398
current_received_ts = 175.095062
current_seq = 965
count = 544
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.095398
last_received_ts = 175.095062
last_seq = 965
current_ts = 175.106506
current_received_ts = 175.106201
current_seq = 966
count = 545
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 3us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.106506
last_received_ts = 175.106201
last_seq = 966
current_ts = 175.117630
current_received_ts = 175.117310
current_seq = 967
count = 546
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.117630
last_received_ts = 175.117310
last_seq = 967
current_ts = 175.128754
current_received_ts = 175.128448
current_seq = 968
count = 547
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.128754
last_received_ts = 175.128448
last_seq = 968
current_ts = 175.139862
current_received_ts = 175.139542
current_seq = 969
count = 548
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.139862
last_received_ts = 175.139542
last_seq = 969
current_ts = 175.150986
current_received_ts = 175.150665
current_seq = 970
count = 549
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 6us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.150986
last_received_ts = 175.150665
last_seq = 970
current_ts = 175.162094
current_received_ts = 175.161774
current_seq = 971
count = 550
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.162094
last_received_ts = 175.161774
last_seq = 971
current_ts = 175.173218
current_received_ts = 175.172913
current_seq = 972
count = 551
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.173218
last_received_ts = 175.172913
last_seq = 972
current_ts = 175.184326
current_received_ts = 175.184036
current_seq = 973
count = 552
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.184326
last_received_ts = 175.184036
last_seq = 973
current_ts = 175.195435
current_received_ts = 175.195129
current_seq = 974
count = 553
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.195435
last_received_ts = 175.195129
last_seq = 974
current_ts = 175.206558
current_received_ts = 175.206253
current_seq = 975
count = 554
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.206558
last_received_ts = 175.206253
last_seq = 975
current_ts = 175.217682
current_received_ts = 175.217346
current_seq = 976
count = 555
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.217682
last_received_ts = 175.217346
last_seq = 976
current_ts = 175.228790
current_received_ts = 175.228470
current_seq = 977
count = 556
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.228790
last_received_ts = 175.228470
last_seq = 977
current_ts = 175.239914
current_received_ts = 175.239594
current_seq = 978
count = 557
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.239914
last_received_ts = 175.239594
last_seq = 978
current_ts = 175.251022
current_received_ts = 175.250702
current_seq = 979
count = 558
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.251022
last_received_ts = 175.250702
last_seq = 979
current_ts = 175.262146
current_received_ts = 175.261856
current_seq = 980
count = 559
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.262146
last_received_ts = 175.261856
last_seq = 980
current_ts = 175.273254
current_received_ts = 175.272934
current_seq = 981
count = 560
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.273254
last_received_ts = 175.272934
last_seq = 981
current_ts = 175.284378
current_received_ts = 175.284088
current_seq = 982
count = 561
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.284378
last_received_ts = 175.284088
last_seq = 982
current_ts = 175.295486
current_received_ts = 175.295212
current_seq = 983
count = 562
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.295486
last_received_ts = 175.295212
last_seq = 983
current_ts = 175.306610
current_received_ts = 175.306290
current_seq = 984
count = 563
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.306610
last_received_ts = 175.306290
last_seq = 984
current_ts = 175.317719
current_received_ts = 175.317398
current_seq = 985
count = 564
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.317719
last_received_ts = 175.317398
last_seq = 985
current_ts = 175.328842
current_received_ts = 175.328522
current_seq = 986
count = 565
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.328842
last_received_ts = 175.328522
last_seq = 986
current_ts = 175.339951
current_received_ts = 175.339645
current_seq = 987
count = 566
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.339951
last_received_ts = 175.339645
last_seq = 987
current_ts = 175.351074
current_received_ts = 175.350769
current_seq = 988
count = 567
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 5us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.351074
last_received_ts = 175.350769
last_seq = 988
current_ts = 175.362183
current_received_ts = 175.361877
current_seq = 989
count = 568
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 4us
(kms_flip:3233) DEBUG: name = flip
last_ts = 175.362183
last_received_ts = 175.361877
last_seq = 989
current_ts = 175.373306
current_received_ts = 175.372986
current_seq = 990
count = 569
seq_step = 1
(kms_flip:3233) DEBUG: Vblank took 917us
(kms_flip:3233) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:3233) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3233) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:3233) igt_core-INFO: Stack trace:
(kms_flip:3233) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:3233) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:3233) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:3233) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:3233) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:3233) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3233) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3233) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (7.627s)

Dmesg

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

<7> [228.346676] i915 0000:00:02.0: [drm:i915_dpt_create [i915]] Allocating dpt from smem

<7> [228.346918] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:566]

<7> [228.347017] i915 0000:00:02.0: [drm:i915_dpt_create [i915]] Allocating dpt from smem

<7> [228.347288] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:568]

<7> [228.350187] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [228.350576] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [228.369452] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [228.369720] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [228.378503] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [228.378774] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [228.396363] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [228.396641] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [228.403754] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [228.411136] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:145:cursor A] ddb (4001 - 4096) -> ( 0 - 0), size 95 -> 0

<7> [228.411296] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:151:pipe A] min cdclk: 256910 kHz -> 0 kHz

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

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

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

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

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

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

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

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

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

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

<7> [228.413213] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]]

<7> [228.615133] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:508:eDP-1] set backlight PWM = 0

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

<7> [228.621677] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turn panel power off

<7> [228.622055] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x00000089, pins 0x00000010, long 0x00000000

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

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

<7> [228.622633] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:507:DDI A/PHY A] - short

<7> [228.674684] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010

<7> [228.675264] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:507:DDI A/PHY A] - long

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

<7> [228.682301] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete

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

<7> [228.682947] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring short hpd on eDP [ENCODER:507:DDI A/PHY A]

<7> [228.683483] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:507:DDI A/PHY A]

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

<7> [228.685224] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A

<7> [228.685576] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [228.690397] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:508:eDP-1]

<7> [228.690605] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no)

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

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

<7> [228.691280] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_A

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

<7> [228.691689] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:151:pipe A]

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

<7> [228.692179] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=432

<7> [228.692539] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]

<7> [228.692686] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C]

<7> [228.692798] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D]

<7> [228.692917] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]

<7> [228.692944] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:508:eDP-1]

<7> [228.693007] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:508:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)

<7> [228.693208] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:507:DDI A/PHY A][CRTC:269:pipe B] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000

<7> [228.693351] i915 0000:00:02.0: [drm:intel_dp_compute_output_format [i915]] DP lane count 4 clock 540000 bpp input 30 compressed 0.0000 HDR no link rate required 1926825 available 2160000

<7> [228.693515] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:269:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0

<7> [228.693674] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:507:DDI A/PHY A] [CRTC:269:pipe B]

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

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

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

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

<7> [228.694507] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7483046/8388608 link 498869/524288)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [228.702722] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:153:plane 1B] ddb ( 0 - 0) -> ( 0 - 4001), size 0 -> 4001

<7> [228.702863] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:263:cursor B] ddb ( 0 - 0) -> (4001 - 4096), size 0 -> 95

<7> [228.703012] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153: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> [228.703153] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 16, 16, 19, 19, 28, 0, 0, 0, 4, 0

<7> [228.703293] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 365, 365, 434, 434, 638, 0, 0, 197, 92, 197

<7> [228.703434] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 547, 547, 729, 0, 0, 198, 183, 198

<7> [228.703585] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:269:pipe B] data rate 2055280 num active planes 1

<7> [228.703736] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200

<7> [228.703885] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200

<7> [228.704050] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200

<7> [228.704194] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200

<7> [228.704339] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159

<7> [228.704487] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:269:pipe B] min cdclk: 0 kHz -> 256910 kHz

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

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

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

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

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

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

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

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

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

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

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

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

<7> [228.706454] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m_n: lanes: 4; data_m: 7483046, data_n: 8388608, link_m: 498869, link_n: 524288, tu: 64

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

<7> [228.706744] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled

<7> [228.706888] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled

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

<7> [228.707233] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum hblank: 0

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

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

<7> [228.707666] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB

<7> [228.707810] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB

<7> [228.707957] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0

<7> [228.708125] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range

<7> [228.708273] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined

<7> [228.708434] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1

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

<7> [228.708724] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1878, vmax: 1878, flipline: 1878, pipeline full: 0, guardband: 76 vsync start: 75, vsync end: 69

<7> [228.708869] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1878, vmax vtotal: 1878

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

<7> [228.709173] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa

<7> [228.709321] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa

<7> [228.709467] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1801-1878 vs=1803-1809 vt=1878, flags=0xa

<7> [228.709613] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x40 0xa

<7> [228.709759] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1801-1878 vs=1803-1809 vt=1878, flags=0xa

<7> [228.709906] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 540000, pixel rate 513820, min cdclk 256910, min voltage level 0

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

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

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

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

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

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

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

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

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

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

<7> [228.711129] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] c10pll_hw_state: fracen: yes,

<7> [228.711274] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] quot: 40960, rem: 0, den: 1,

<7> [228.711419] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] multiplier: 140, tx_clk_div: 0.

<7> [228.711566] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] c10pll_rawhw_state:

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

<7> [228.711857] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[0] = 0xf4, pll[1] = 0x0, pll[2] = 0xf8, pll[3] = 0x0

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

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

<7> [228.712314] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[12] = 0xa0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x0

<7> [228.712458] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[16] = 0x84, pll[17] = 0x4f, pll[18] = 0xe5, pll[19] = 0x23

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [228.719140] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_B

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

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

<7> [228.719693] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=768

<7> [228.719842] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [228.723586] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 4 (mbus joined: yes)

<7> [228.723808] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A

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

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

<7> [228.727231] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turn panel power on

<7> [228.727395] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 wait for panel power cycle (456 ms remaining)

<7> [229.191143] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x00000000 PP_CONTROL: 0x00000060

<7> [229.201796] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete

<7> [229.202370] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 wait for panel power on

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

<7> [229.234439] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010

<7> [229.235022] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:507:DDI A/PHY A] - long

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

<7> [229.236169] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:507:DDI A/PHY A]

<7> [229.407683] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete

<7> [229.408449] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turning VDD on

<7> [229.409174] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b

<7> [229.412391] i915 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c4 41 00 00 01 c0 02 00 00 00 00 0b 80

<7> [229.413804] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Reloading eDP link rates

<7> [229.414662] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 07

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

<7> [229.416829] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using DP training pattern TPS1

<7> [229.417794] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Clock recovery OK

<7> [229.417928] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using DP training pattern TPS3

<7> [229.419231] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful

<7> [229.419365] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Link Training passed at link rate = 540000, lane count = 4

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

<7> [229.420267] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]]

<7> [229.420400] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe B

<7> [229.420625] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:508:eDP-1] set backlight PWM = 13892

<7> [229.442657] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR2

<7> [229.444245] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:508:eDP-1]

<7> [229.444511] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:269:pipe B]

<7> [231.965225] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turning VDD off

<7> [231.965849] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067

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

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

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

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

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