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

Detail	Value
Duration	6.18 seconds
Hostname	shard-tglu-9
Igt-Version	IGT-Version: 2.4-g02b0e01dd (x86_64) (Linux: 7.1.0-rc1-CI_DRM_18377-ga53aafc879e9+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A1 1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c: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-HDMI-A1: FAIL (6.181s)
Err	Starting dynamic subtest: B-HDMI-A1 (kms_flip:18182) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:18182) CRITICAL: Failed assertion: end - start < 500 (kms_flip:18182) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-HDMI-A1 failed. ** DEBUG (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 214.639267 last_received_ts = 214.638931 last_seq = 889 current_ts = 214.647614 current_received_ts = 214.647293 current_seq = 890 count = 594 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.647614 last_received_ts = 214.647293 last_seq = 890 current_ts = 214.655945 current_received_ts = 214.655670 current_seq = 891 count = 595 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 214.655945 last_received_ts = 214.655670 last_seq = 891 current_ts = 214.664291 current_received_ts = 214.663986 current_seq = 892 count = 596 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.664291 last_received_ts = 214.663986 last_seq = 892 current_ts = 214.672623 current_received_ts = 214.672379 current_seq = 893 count = 597 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 32us (kms_flip:18182) DEBUG: name = flip last_ts = 214.672623 last_received_ts = 214.672379 last_seq = 893 current_ts = 214.680969 current_received_ts = 214.680649 current_seq = 894 count = 598 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 27us (kms_flip:18182) DEBUG: name = flip last_ts = 214.680969 last_received_ts = 214.680649 last_seq = 894 current_ts = 214.689301 current_received_ts = 214.688934 current_seq = 895 count = 599 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.689301 last_received_ts = 214.688934 last_seq = 895 current_ts = 214.697647 current_received_ts = 214.697311 current_seq = 896 count = 600 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.697647 last_received_ts = 214.697311 last_seq = 896 current_ts = 214.705978 current_received_ts = 214.705627 current_seq = 897 count = 601 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 24us (kms_flip:18182) DEBUG: name = flip last_ts = 214.705978 last_received_ts = 214.705627 last_seq = 897 current_ts = 214.714310 current_received_ts = 214.714096 current_seq = 898 count = 602 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.714310 last_received_ts = 214.714096 last_seq = 898 current_ts = 214.722656 current_received_ts = 214.722321 current_seq = 899 count = 603 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 29us (kms_flip:18182) DEBUG: name = flip last_ts = 214.722656 last_received_ts = 214.722321 last_seq = 899 current_ts = 214.731003 current_received_ts = 214.730667 current_seq = 900 count = 604 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 28us (kms_flip:18182) DEBUG: name = flip last_ts = 214.731003 last_received_ts = 214.730667 last_seq = 900 current_ts = 214.739334 current_received_ts = 214.738968 current_seq = 901 count = 605 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 27us (kms_flip:18182) DEBUG: name = flip last_ts = 214.739334 last_received_ts = 214.738968 last_seq = 901 current_ts = 214.747681 current_received_ts = 214.747345 current_seq = 902 count = 606 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 29us (kms_flip:18182) DEBUG: name = flip last_ts = 214.747681 last_received_ts = 214.747345 last_seq = 902 current_ts = 214.756012 current_received_ts = 214.755661 current_seq = 903 count = 607 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 22us (kms_flip:18182) DEBUG: name = flip last_ts = 214.756012 last_received_ts = 214.755661 last_seq = 903 current_ts = 214.764343 current_received_ts = 214.764038 current_seq = 904 count = 608 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 214.764343 last_received_ts = 214.764038 last_seq = 904 current_ts = 214.772690 current_received_ts = 214.772354 current_seq = 905 count = 609 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.772690 last_received_ts = 214.772354 last_seq = 905 current_ts = 214.781021 current_received_ts = 214.780716 current_seq = 906 count = 610 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 33us (kms_flip:18182) DEBUG: name = flip last_ts = 214.781021 last_received_ts = 214.780716 last_seq = 906 current_ts = 214.789368 current_received_ts = 214.789078 current_seq = 907 count = 611 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 32us (kms_flip:18182) DEBUG: name = flip last_ts = 214.789368 last_received_ts = 214.789078 last_seq = 907 current_ts = 214.797699 current_received_ts = 214.797455 current_seq = 908 count = 612 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 214.797699 last_received_ts = 214.797455 last_seq = 908 current_ts = 214.806030 current_received_ts = 214.805710 current_seq = 909 count = 613 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 27us (kms_flip:18182) DEBUG: name = flip last_ts = 214.806030 last_received_ts = 214.805710 last_seq = 909 current_ts = 214.814377 current_received_ts = 214.814804 current_seq = 910 count = 614 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 214.814377 last_received_ts = 214.814804 last_seq = 910 current_ts = 214.822708 current_received_ts = 214.822388 current_seq = 911 count = 615 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.822708 last_received_ts = 214.822388 last_seq = 911 current_ts = 214.831055 current_received_ts = 214.830719 current_seq = 912 count = 616 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.831055 last_received_ts = 214.830719 last_seq = 912 current_ts = 214.839401 current_received_ts = 214.839066 current_seq = 913 count = 617 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 30us (kms_flip:18182) DEBUG: name = flip last_ts = 214.839401 last_received_ts = 214.839066 last_seq = 913 current_ts = 214.847733 current_received_ts = 214.847458 current_seq = 914 count = 618 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 22us (kms_flip:18182) DEBUG: name = flip last_ts = 214.847733 last_received_ts = 214.847458 last_seq = 914 current_ts = 214.856079 current_received_ts = 214.855759 current_seq = 915 count = 619 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 29us (kms_flip:18182) DEBUG: name = flip last_ts = 214.856079 last_received_ts = 214.855759 last_seq = 915 current_ts = 214.864410 current_received_ts = 214.864151 current_seq = 916 count = 620 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.864410 last_received_ts = 214.864151 last_seq = 916 current_ts = 214.872742 current_received_ts = 214.872406 current_seq = 917 count = 621 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.872742 last_received_ts = 214.872406 last_seq = 917 current_ts = 214.881088 current_received_ts = 214.880859 current_seq = 918 count = 622 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 24us (kms_flip:18182) DEBUG: name = flip last_ts = 214.881088 last_received_ts = 214.880859 last_seq = 918 current_ts = 214.889420 current_received_ts = 214.889069 current_seq = 919 count = 623 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 34us (kms_flip:18182) DEBUG: name = flip last_ts = 214.889420 last_received_ts = 214.889069 last_seq = 919 current_ts = 214.897766 current_received_ts = 214.897476 current_seq = 920 count = 624 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 22us (kms_flip:18182) DEBUG: name = flip last_ts = 214.897766 last_received_ts = 214.897476 last_seq = 920 current_ts = 214.906097 current_received_ts = 214.905731 current_seq = 921 count = 625 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.906097 last_received_ts = 214.905731 last_seq = 921 current_ts = 214.914444 current_received_ts = 214.914078 current_seq = 922 count = 626 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 214.914444 last_received_ts = 214.914078 last_seq = 922 current_ts = 214.922775 current_received_ts = 214.922455 current_seq = 923 count = 627 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 214.922775 last_received_ts = 214.922455 last_seq = 923 current_ts = 214.931122 current_received_ts = 214.930786 current_seq = 924 count = 628 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 22us (kms_flip:18182) DEBUG: name = flip last_ts = 214.931122 last_received_ts = 214.930786 last_seq = 924 current_ts = 214.939453 current_received_ts = 214.939148 current_seq = 925 count = 629 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 214.939453 last_received_ts = 214.939148 last_seq = 925 current_ts = 214.947784 current_received_ts = 214.947495 current_seq = 926 count = 630 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 24us (kms_flip:18182) DEBUG: name = flip last_ts = 214.947784 last_received_ts = 214.947495 last_seq = 926 current_ts = 214.956131 current_received_ts = 214.955795 current_seq = 927 count = 631 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.956131 last_received_ts = 214.955795 last_seq = 927 current_ts = 214.964462 current_received_ts = 214.964218 current_seq = 928 count = 632 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.964462 last_received_ts = 214.964218 last_seq = 928 current_ts = 214.972809 current_received_ts = 214.972580 current_seq = 929 count = 633 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 35us (kms_flip:18182) DEBUG: name = flip last_ts = 214.972809 last_received_ts = 214.972580 last_seq = 929 current_ts = 214.981140 current_received_ts = 214.980881 current_seq = 930 count = 634 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 30us (kms_flip:18182) DEBUG: name = flip last_ts = 214.981140 last_received_ts = 214.980881 last_seq = 930 current_ts = 214.989487 current_received_ts = 214.989212 current_seq = 931 count = 635 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 34us (kms_flip:18182) DEBUG: name = flip last_ts = 214.989487 last_received_ts = 214.989212 last_seq = 931 current_ts = 214.997818 current_received_ts = 214.997528 current_seq = 932 count = 636 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 214.997818 last_received_ts = 214.997528 last_seq = 932 current_ts = 215.006165 current_received_ts = 215.005844 current_seq = 933 count = 637 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 35us (kms_flip:18182) DEBUG: name = flip last_ts = 215.006165 last_received_ts = 215.005844 last_seq = 933 current_ts = 215.014496 current_received_ts = 215.014221 current_seq = 934 count = 638 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 27us (kms_flip:18182) DEBUG: name = flip last_ts = 215.014496 last_received_ts = 215.014221 last_seq = 934 current_ts = 215.022827 current_received_ts = 215.022522 current_seq = 935 count = 639 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 38us (kms_flip:18182) DEBUG: name = flip last_ts = 215.022827 last_received_ts = 215.022522 last_seq = 935 current_ts = 215.031174 current_received_ts = 215.030899 current_seq = 936 count = 640 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 215.031174 last_received_ts = 215.030899 last_seq = 936 current_ts = 215.039505 current_received_ts = 215.039185 current_seq = 937 count = 641 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 34us (kms_flip:18182) DEBUG: name = flip last_ts = 215.039505 last_received_ts = 215.039185 last_seq = 937 current_ts = 215.047852 current_received_ts = 215.047562 current_seq = 938 count = 642 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 215.047852 last_received_ts = 215.047562 last_seq = 938 current_ts = 215.056183 current_received_ts = 215.055801 current_seq = 939 count = 643 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 215.056183 last_received_ts = 215.055801 last_seq = 939 current_ts = 215.064529 current_received_ts = 215.064178 current_seq = 940 count = 644 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 215.064529 last_received_ts = 215.064178 last_seq = 940 current_ts = 215.072861 current_received_ts = 215.072601 current_seq = 941 count = 645 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 24us (kms_flip:18182) DEBUG: name = flip last_ts = 215.072861 last_received_ts = 215.072601 last_seq = 941 current_ts = 215.081207 current_received_ts = 215.080856 current_seq = 942 count = 646 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 20us (kms_flip:18182) DEBUG: name = flip last_ts = 215.081207 last_received_ts = 215.080856 last_seq = 942 current_ts = 215.089539 current_received_ts = 215.089249 current_seq = 943 count = 647 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 22us (kms_flip:18182) DEBUG: name = flip last_ts = 215.089539 last_received_ts = 215.089249 last_seq = 943 current_ts = 215.097885 current_received_ts = 215.097565 current_seq = 944 count = 648 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 29us (kms_flip:18182) DEBUG: name = flip last_ts = 215.097885 last_received_ts = 215.097565 last_seq = 944 current_ts = 215.106216 current_received_ts = 215.105881 current_seq = 945 count = 649 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 215.106216 last_received_ts = 215.105881 last_seq = 945 current_ts = 215.114563 current_received_ts = 215.114212 current_seq = 946 count = 650 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.114563 last_received_ts = 215.114212 last_seq = 946 current_ts = 215.122894 current_received_ts = 215.122559 current_seq = 947 count = 651 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 31us (kms_flip:18182) DEBUG: name = flip last_ts = 215.122894 last_received_ts = 215.122559 last_seq = 947 current_ts = 215.131241 current_received_ts = 215.130890 current_seq = 948 count = 652 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 50us (kms_flip:18182) DEBUG: name = flip last_ts = 215.131241 last_received_ts = 215.130890 last_seq = 948 current_ts = 215.139572 current_received_ts = 215.139282 current_seq = 949 count = 653 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 24us (kms_flip:18182) DEBUG: name = flip last_ts = 215.139572 last_received_ts = 215.139282 last_seq = 949 current_ts = 215.147903 current_received_ts = 215.147629 current_seq = 950 count = 654 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.147903 last_received_ts = 215.147629 last_seq = 950 current_ts = 215.156235 current_received_ts = 215.155884 current_seq = 951 count = 655 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 22us (kms_flip:18182) DEBUG: name = flip last_ts = 215.156235 last_received_ts = 215.155884 last_seq = 951 current_ts = 215.164581 current_received_ts = 215.164261 current_seq = 952 count = 656 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 215.164581 last_received_ts = 215.164261 last_seq = 952 current_ts = 215.172928 current_received_ts = 215.172577 current_seq = 953 count = 657 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 28us (kms_flip:18182) DEBUG: name = flip last_ts = 215.172928 last_received_ts = 215.172577 last_seq = 953 current_ts = 215.181259 current_received_ts = 215.180954 current_seq = 954 count = 658 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 46us (kms_flip:18182) DEBUG: name = flip last_ts = 215.181259 last_received_ts = 215.180954 last_seq = 954 current_ts = 215.189590 current_received_ts = 215.189255 current_seq = 955 count = 659 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.189590 last_received_ts = 215.189255 last_seq = 955 current_ts = 215.197937 current_received_ts = 215.197586 current_seq = 956 count = 660 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 215.197937 last_received_ts = 215.197586 last_seq = 956 current_ts = 215.206268 current_received_ts = 215.205917 current_seq = 957 count = 661 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 24us (kms_flip:18182) DEBUG: name = flip last_ts = 215.206268 last_received_ts = 215.205917 last_seq = 957 current_ts = 215.214615 current_received_ts = 215.214279 current_seq = 958 count = 662 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 24us (kms_flip:18182) DEBUG: name = flip last_ts = 215.214615 last_received_ts = 215.214279 last_seq = 958 current_ts = 215.222946 current_received_ts = 215.222717 current_seq = 959 count = 663 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.222946 last_received_ts = 215.222717 last_seq = 959 current_ts = 215.231293 current_received_ts = 215.230988 current_seq = 960 count = 664 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 32us (kms_flip:18182) DEBUG: name = flip last_ts = 215.231293 last_received_ts = 215.230988 last_seq = 960 current_ts = 215.239624 current_received_ts = 215.239334 current_seq = 961 count = 665 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 215.239624 last_received_ts = 215.239334 last_seq = 961 current_ts = 215.247955 current_received_ts = 215.247650 current_seq = 962 count = 666 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 34us (kms_flip:18182) DEBUG: name = flip last_ts = 215.247955 last_received_ts = 215.247650 last_seq = 962 current_ts = 215.256302 current_received_ts = 215.256012 current_seq = 963 count = 667 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 36us (kms_flip:18182) DEBUG: name = flip last_ts = 215.256302 last_received_ts = 215.256012 last_seq = 963 current_ts = 215.264633 current_received_ts = 215.264328 current_seq = 964 count = 668 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.264633 last_received_ts = 215.264328 last_seq = 964 current_ts = 215.272980 current_received_ts = 215.272659 current_seq = 965 count = 669 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 215.272980 last_received_ts = 215.272659 last_seq = 965 current_ts = 215.281311 current_received_ts = 215.281158 current_seq = 966 count = 670 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.281311 last_received_ts = 215.281158 last_seq = 966 current_ts = 215.289658 current_received_ts = 215.289322 current_seq = 967 count = 671 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.289658 last_received_ts = 215.289322 last_seq = 967 current_ts = 215.298004 current_received_ts = 215.297653 current_seq = 968 count = 672 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.298004 last_received_ts = 215.297653 last_seq = 968 current_ts = 215.306335 current_received_ts = 215.305984 current_seq = 969 count = 673 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 36us (kms_flip:18182) DEBUG: name = flip last_ts = 215.306335 last_received_ts = 215.305984 last_seq = 969 current_ts = 215.314667 current_received_ts = 215.314331 current_seq = 970 count = 674 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.314667 last_received_ts = 215.314331 last_seq = 970 current_ts = 215.323013 current_received_ts = 215.322662 current_seq = 971 count = 675 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 24us (kms_flip:18182) DEBUG: name = flip last_ts = 215.323013 last_received_ts = 215.322662 last_seq = 971 current_ts = 215.331345 current_received_ts = 215.331024 current_seq = 972 count = 676 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.331345 last_received_ts = 215.331024 last_seq = 972 current_ts = 215.339691 current_received_ts = 215.339325 current_seq = 973 count = 677 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 22us (kms_flip:18182) DEBUG: name = flip last_ts = 215.339691 last_received_ts = 215.339325 last_seq = 973 current_ts = 215.348022 current_received_ts = 215.347809 current_seq = 974 count = 678 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 215.348022 last_received_ts = 215.347809 last_seq = 974 current_ts = 215.356369 current_received_ts = 215.356049 current_seq = 975 count = 679 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.356369 last_received_ts = 215.356049 last_seq = 975 current_ts = 215.364700 current_received_ts = 215.364471 current_seq = 976 count = 680 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 22us (kms_flip:18182) DEBUG: name = flip last_ts = 215.364700 last_received_ts = 215.364471 last_seq = 976 current_ts = 215.373032 current_received_ts = 215.372711 current_seq = 977 count = 681 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.373032 last_received_ts = 215.372711 last_seq = 977 current_ts = 215.381378 current_received_ts = 215.381058 current_seq = 978 count = 682 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 215.381378 last_received_ts = 215.381058 last_seq = 978 current_ts = 215.389709 current_received_ts = 215.389389 current_seq = 979 count = 683 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.389709 last_received_ts = 215.389389 last_seq = 979 current_ts = 215.398056 current_received_ts = 215.397720 current_seq = 980 count = 684 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 29us (kms_flip:18182) DEBUG: name = flip last_ts = 215.398056 last_received_ts = 215.397720 last_seq = 980 current_ts = 215.406387 current_received_ts = 215.406097 current_seq = 981 count = 685 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.406387 last_received_ts = 215.406097 last_seq = 981 current_ts = 215.414734 current_received_ts = 215.414413 current_seq = 982 count = 686 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 27us (kms_flip:18182) DEBUG: name = flip last_ts = 215.414734 last_received_ts = 215.414413 last_seq = 982 current_ts = 215.423065 current_received_ts = 215.422729 current_seq = 983 count = 687 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.423065 last_received_ts = 215.422729 last_seq = 983 current_ts = 215.431412 current_received_ts = 215.431046 current_seq = 984 count = 688 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 22us (kms_flip:18182) DEBUG: name = flip last_ts = 215.431412 last_received_ts = 215.431046 last_seq = 984 current_ts = 215.439743 current_received_ts = 215.439468 current_seq = 985 count = 689 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.439743 last_received_ts = 215.439468 last_seq = 985 current_ts = 215.448090 current_received_ts = 215.447723 current_seq = 986 count = 690 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 20us (kms_flip:18182) DEBUG: name = flip last_ts = 215.448090 last_received_ts = 215.447723 last_seq = 986 current_ts = 215.456421 current_received_ts = 215.456116 current_seq = 987 count = 691 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 22us (kms_flip:18182) DEBUG: name = flip last_ts = 215.456421 last_received_ts = 215.456116 last_seq = 987 current_ts = 215.464752 current_received_ts = 215.464493 current_seq = 988 count = 692 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 27us (kms_flip:18182) DEBUG: name = flip last_ts = 215.464752 last_received_ts = 215.464493 last_seq = 988 current_ts = 215.473099 current_received_ts = 215.472748 current_seq = 989 count = 693 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 215.473099 last_received_ts = 215.472748 last_seq = 989 current_ts = 215.481430 current_received_ts = 215.481110 current_seq = 990 count = 694 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.481430 last_received_ts = 215.481110 last_seq = 990 current_ts = 215.489761 current_received_ts = 215.489410 current_seq = 991 count = 695 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 215.489761 last_received_ts = 215.489410 last_seq = 991 current_ts = 215.498108 current_received_ts = 215.497955 current_seq = 992 count = 696 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 45us (kms_flip:18182) DEBUG: name = flip last_ts = 215.498108 last_received_ts = 215.497955 last_seq = 992 current_ts = 215.506454 current_received_ts = 215.506134 current_seq = 993 count = 697 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 24us (kms_flip:18182) DEBUG: name = flip last_ts = 215.506454 last_received_ts = 215.506134 last_seq = 993 current_ts = 215.514786 current_received_ts = 215.514557 current_seq = 994 count = 698 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 215.514786 last_received_ts = 215.514557 last_seq = 994 current_ts = 215.523132 current_received_ts = 215.522797 current_seq = 995 count = 699 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 28us (kms_flip:18182) DEBUG: name = flip last_ts = 215.523132 last_received_ts = 215.522797 last_seq = 995 current_ts = 215.531464 current_received_ts = 215.531189 current_seq = 996 count = 700 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 215.531464 last_received_ts = 215.531189 last_seq = 996 current_ts = 215.539810 current_received_ts = 215.539459 current_seq = 997 count = 701 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 24us (kms_flip:18182) DEBUG: name = flip last_ts = 215.539810 last_received_ts = 215.539459 last_seq = 997 current_ts = 215.548141 current_received_ts = 215.547729 current_seq = 998 count = 702 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 22us (kms_flip:18182) DEBUG: name = flip last_ts = 215.548141 last_received_ts = 215.547729 last_seq = 998 current_ts = 215.556473 current_received_ts = 215.556183 current_seq = 999 count = 703 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 27us (kms_flip:18182) DEBUG: name = flip last_ts = 215.556473 last_received_ts = 215.556183 last_seq = 999 current_ts = 215.564819 current_received_ts = 215.564590 current_seq = 1000 count = 704 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 27us (kms_flip:18182) DEBUG: name = flip last_ts = 215.564819 last_received_ts = 215.564590 last_seq = 1000 current_ts = 215.573151 current_received_ts = 215.572830 current_seq = 1001 count = 705 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 24us (kms_flip:18182) DEBUG: name = flip last_ts = 215.573151 last_received_ts = 215.572830 last_seq = 1001 current_ts = 215.581482 current_received_ts = 215.581207 current_seq = 1002 count = 706 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 47us (kms_flip:18182) DEBUG: name = flip last_ts = 215.581482 last_received_ts = 215.581207 last_seq = 1002 current_ts = 215.589828 current_received_ts = 215.589554 current_seq = 1003 count = 707 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.589828 last_received_ts = 215.589554 last_seq = 1003 current_ts = 215.598175 current_received_ts = 215.597916 current_seq = 1004 count = 708 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 215.598175 last_received_ts = 215.597916 last_seq = 1004 current_ts = 215.606506 current_received_ts = 215.606186 current_seq = 1005 count = 709 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 26us (kms_flip:18182) DEBUG: name = flip last_ts = 215.606506 last_received_ts = 215.606186 last_seq = 1005 current_ts = 215.614838 current_received_ts = 215.614563 current_seq = 1006 count = 710 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 215.614838 last_received_ts = 215.614563 last_seq = 1006 current_ts = 215.623184 current_received_ts = 215.622818 current_seq = 1007 count = 711 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 20us (kms_flip:18182) DEBUG: name = flip last_ts = 215.623184 last_received_ts = 215.622818 last_seq = 1007 current_ts = 215.631516 current_received_ts = 215.631226 current_seq = 1008 count = 712 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 25us (kms_flip:18182) DEBUG: name = flip last_ts = 215.631516 last_received_ts = 215.631226 last_seq = 1008 current_ts = 215.639862 current_received_ts = 215.639496 current_seq = 1009 count = 713 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 23us (kms_flip:18182) DEBUG: name = flip last_ts = 215.639862 last_received_ts = 215.639496 last_seq = 1009 current_ts = 215.648193 current_received_ts = 215.647964 current_seq = 1010 count = 714 seq_step = 1 (kms_flip:18182) DEBUG: Vblank took 746us (kms_flip:18182) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:18182) CRITICAL: Failed assertion: end - start < 500 (kms_flip:18182) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:18182) igt_core-INFO: Stack trace: (kms_flip:18182) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:18182) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:18182) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:18182) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() (kms_flip:18182) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:18182) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:18182) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:18182) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A1: FAIL (6.181s)
Dmesg	<6> [287.461596] [IGT] kms_flip: starting dynamic subtest B-HDMI-A1 <7> [287.462761] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:636] <7> [287.462984] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:650] <7> [287.486572] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:171:pipe A] <7> [287.486690] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [287.486895] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [287.487093] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [287.487369] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [287.487611] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [287.487856] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [287.488113] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [287.488353] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2080, found 0) <7> [287.488592] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [287.488851] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2080, found 0) <7> [287.489106] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1968, found 0) <7> [287.489341] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2000, found 0) <7> [287.489577] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [287.489815] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [287.490102] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [287.490336] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [287.490572] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1144, found 0) <7> [287.490809] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1144, found 0) <7> [287.491059] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [287.491300] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2080, found 0) <7> [287.491538] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [287.491776] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2080, found 0) <7> [287.492020] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1968, found 0) <7> [287.492259] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2000, found 0) <7> [287.492495] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [287.492752] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [287.492993] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [287.493269] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [287.493510] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1144, found 0) <7> [287.493748] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1144, found 0) <7> [287.493988] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [287.494290] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [287.494530] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [287.494767] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [287.495013] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in has_infoframe (expected yes, found no) <7> [287.495255] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [287.495492] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 285500, found 0) <7> [287.495726] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 285500, found 0) <7> [287.495957] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in port_clock (expected 285500, found 0) <7> [287.496221] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [287.496456] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in avi infoframe <7> [287.496693] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [287.496926] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [287.496930] i915 0000:00:02.0: colorspace: RGB <7> [287.496933] i915 0000:00:02.0: scan mode: Underscan <7> [287.496936] i915 0000:00:02.0: colorimetry: No Data <7> [287.496939] i915 0000:00:02.0: picture aspect: No Data <7> [287.496942] i915 0000:00:02.0: active aspect: Same as Picture <7> [287.496945] i915 0000:00:02.0: itc: No Data <7> [287.496948] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [287.496951] i915 0000:00:02.0: quantization range: Full <7> [287.496954] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [287.496957] i915 0000:00:02.0: video code: 0 <7> [287.496960] i915 0000:00:02.0: ycc quantization range: Full <7> [287.496963] i915 0000:00:02.0: hdmi content type: Graphics <7> [287.496966] i915 0000:00:02.0: pixel repeat: 0 <7> [287.496969] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [287.496972] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [287.497241] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in spd infoframe <7> [287.497482] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [287.497718] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [287.497721] i915 0000:00:02.0: vendor: Intel <7> [287.497724] i915 0000:00:02.0: product: Integrated gfx <7> [287.497728] i915 0000:00:02.0: source device information: PC General (0x9) <7> [287.497731] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [287.497968] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hdmi infoframe <7> [287.498233] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [287.498469] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [287.498472] i915 0000:00:02.0: empty frame <7> [287.498475] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [287.498714] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:171:pipe A] fastset requirement not met, forcing full modeset <7> [287.498953] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:171:pipe A] releasing DPLL 0 <7> [287.499274] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no <7> [287.499509] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:171:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [287.499801] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:165:cursor A] ddb (1993 - 2048) -> ( 0 - 0), size 55 -> 0 <7> [287.500080] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:171:pipe A] min cdclk: 192000 kHz -> 0 kHz <7> [287.500375] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [287.500616] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz <7> [287.500852] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [287.501114] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:171:pipe A] enable: no [modeset] <7> [287.501358] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [287.501601] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [287.501842] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [287.502104] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [287.502342] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [287.502577] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:145:plane 6A] fb: [NOFB], visible: no <7> [287.502816] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:155:plane 7A] fb: [NOFB], visible: no <7> [287.503063] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:165:cursor A] fb: [NOFB], visible: no <7> [287.503432] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:588:HDMI-A-1][ENCODER:587:DDI B/PHY B] Disable audio codec on [CRTC:171:pipe A] <7> [287.516096] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [287.521003] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:588:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10 <7> [287.521585] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [287.521737] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [287.522285] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [287.522455] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:588:HDMI-A-1] Failed to read TMDS config: -6 <7> [287.522471] i915 0000:00:02.0: [drm:intel_ddi_disable [i915]] [CONNECTOR:588:HDMI-A-1] Failed to reset sink scrambling/TMDS bit clock ratio <7> [287.522651] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [287.524395] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [287.524592] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:171:pipe A] <7> [287.524788] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0 <7> [287.524970] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 172800 kHz, VCO 345600 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [287.525300] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI B/PHY B] <7> [287.525491] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DDI TC1/PHY TC1] <7> [287.525655] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST A] <7> [287.525827] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST B] <7> [287.526000] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST C] <7> [287.526161] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:602:DP-MST D] <7> [287.526352] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DDI TC2/PHY TC2] <7> [287.526532] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST A] <7> [287.526701] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST B] <7> [287.526860] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST C] <7> [287.527044] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST D] <7> [287.527203] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DDI TC3/PHY TC3] <7> [287.527361] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST A] <7> [287.527529] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST B] <7> [287.527728] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST C] <7> [287.527887] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:621:DP-MST D] <7> [287.528069] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DDI TC4/PHY TC4] <7> [287.528249] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST A] <7> [287.528406] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST B] <7> [287.528562] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST C] <7> [287.528718] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:630:DP-MST D] <7> [287.528880] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:588:HDMI-A-1] <7> [287.529275] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [287.529499] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_3 <7> [287.529683] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [287.529871] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:171:pipe A] <7> [287.530510] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe B] <7> [287.530684] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe C] <7> [287.530844] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:585:pipe D] <7> [287.531052] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe B] <7> [287.531107] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:588:HDMI-A-1] <7> [287.531199] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:588:HDMI-A-1] Limiting target display pipe bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36) <7> [287.531393] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [287.531556] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [287.531725] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:587:DDI B/PHY B] [CRTC:309:pipe B] <7> [287.531880] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [287.532060] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [287.532232] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [287.532393] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [287.532555] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [287.532716] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [287.532880] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [287.533104] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2080) <7> [287.533336] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [287.533499] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2080) <7> [287.533667] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1968) <7> [287.533846] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2000) <7> [287.534015] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [287.534175] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [287.534334] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [287.534494] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [287.534652] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1144) <7> [287.534815] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1144) <7> [287.535034] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [287.535195] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2080) <7> [287.535363] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [287.535529] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2080) <7> [287.535689] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1968) <7> [287.535848] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2000) <7> [287.536047] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [287.536249] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [287.536408] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [287.536575] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [287.536743] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1144) <7> [287.536902] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1144) <7> [287.537086] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [287.537244] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [287.537408] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [287.537585] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [287.537743] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in has_infoframe (expected no, found yes) <7> [287.537901] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [287.538073] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 285500) <7> [287.538230] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 285500) <7> [287.538388] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in port_clock (expected 0, found 285500) <7> [287.538544] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [287.538701] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in avi infoframe <7> [287.538859] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [287.539126] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [287.539284] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [287.539287] i915 0000:00:02.0: colorspace: RGB <7> [287.539289] i915 0000:00:02.0: scan mode: Underscan <7> [287.539290] i915 0000:00:02.0: colorimetry: No Data <7> [287.539292] i915 0000:00:02.0: picture aspect: No Data <7> [287.539293] i915 0000:00:02.0: active aspect: Same as Picture <7> [287.539295] i915 0000:00:02.0: itc: No Data <7> [287.539296] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [287.539297] i915 0000:00:02.0: quantization range: Full <7> [287.539299] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [287.539300] i915 0000:00:02.0: video code: 0 <7> [287.539302] i915 0000:00:02.0: ycc quantization range: Full <7> [287.539303] i915 0000:00:02.0: hdmi content type: Graphics <7> [287.539305] i915 0000:00:02.0: pixel repeat: 0 <7> [287.539306] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [287.539308] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in spd infoframe <7> [287.539474] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [287.539636] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [287.539796] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [287.539798] i915 0000:00:02.0: vendor: Intel <7> [287.539800] i915 0000:00:02.0: product: Integrated gfx <7> [287.539801] i915 0000:00:02.0: source device information: PC General (0x9) <7> [287.539803] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hdmi infoframe <7> [287.539996] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [287.540163] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [287.540322] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [287.540324] i915 0000:00:02.0: empty frame <7> [287.540326] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe B] fastset requirement not met, forcing full modeset <7> [287.540526] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no <7> [287.540686] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:309:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2 <7> [287.540882] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:173:plane 1B] ddb ( 0 - 0) -> ( 0 - 1993), size 0 -> 1993 <7> [287.541055] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:303:cursor B] ddb ( 0 - 0) -> (1993 - 2048), size 0 -> 55 <7> [287.541214] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,*twm, swm, stwm <7> [287.541371] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 8, 8, 8, 8, 11, 16, 16, 0, 0, 0 <7> [287.541529] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 129, 129, 129, 129, 177, 257, 257, 30, 0, 0 <7> [287.541684] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 143, 143, 143, 143, 196, 284, 284, 31, 0, 0 <7> [287.541878] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:309:pipe B] data rate 1142000 num active planes 1 <7> [287.542057] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 14993 required 1142 <7> [287.542221] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [287.542413] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:309:pipe B] min cdclk: 0 kHz -> 192000 kHz <7> [287.542621] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [287.542780] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [287.542938] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [287.543170] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:309:pipe B] allocated DPLL 0 <7> [287.543338] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:309:pipe B] reserving DPLL 0 <7> [287.543515] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:309:pipe B] enable: yes [modeset] <7> [287.543689] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [287.543853] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [287.544030] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [287.544189] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [287.544396] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [287.544555] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [287.544721] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [287.544888] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x0 <7> [287.545059] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [287.545061] i915 0000:00:02.0: colorspace: RGB <7> [287.545063] i915 0000:00:02.0: scan mode: Underscan <7> [287.545065] i915 0000:00:02.0: colorimetry: No Data <7> [287.545066] i915 0000:00:02.0: picture aspect: No Data <7> [287.545068] i915 0000:00:02.0: active aspect: Same as Picture <7> [287.545070] i915 0000:00:02.0: itc: No Data <7> [287.545071] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [287.545073] i915 0000:00:02.0: quantization range: Full <7> [287.545074] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [287.545076] i915 0000:00:02.0: video code: 0 <7> [287.545078] i915 0000:00:02.0: ycc quantization range: Full <7> [287.545079] i915 0000:00:02.0: hdmi content type: Graphics <7> [287.545081] i915 0000:00:02.0: pixel repeat: 0 <7> [287.545083] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [287.545085] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [287.545086] i915 0000:00:02.0: vendor: Intel <7> [287.545088] i915 0000:00:02.0: product: Integrated gfx <7> [287.545090] i915 0000:00:02.0: source device information: PC General (0x9) <7> [287.545091] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [287.545093] i915 0000:00:02.0: empty frame <7> [287.545095] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 0f 00 6d a2 00 7f 00 00 00 00 00 00 00 00 <7> [287.545255] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 0d 82 34 12 66 69 74 48 65 61 64 6c 65 73 73 47 <7> [287.545412] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 53 7f 7f 28 0f 7f 07 17 7f ff 3f 7f ff 47 7f ff <7> [287.545567] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 5f 7f 82 7f 7f 00 7f 7f 51 7f 7f 30 77 7f 03 00 <7> [287.545754] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [287.545917] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [287.546096] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1144, vmax: 1144, flipline: 1144, pipeline full: 61, guardband: 63 vsync start: 0, vsync end: 0 <7> [287.546257] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1081, vmax vblank: 1081, vmin vtotal: 1144, vmax vtotal: 1144 <7> [287.546416] 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> [287.546575] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 <7> [287.546734] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 <7> [287.546891] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5 <7> [287.547084] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x40 0x5 <7> [287.547241] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5 <7> [287.547400] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 285500, pixel rate 285500, min cdclk 192000, min voltage level 0 <7> [287.547558] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [287.547714] 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> [287.547871] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [287.548042] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [287.548199] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [287.548356] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [287.548513] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1801be, cfgcr1: 0x488, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0 <7> [287.548672] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [287.548832] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [287.548998] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [287.549157] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [287.549356] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [287.549587] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [287.549823] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [287.550073] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [287.550301] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [287.550534] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [287.550772] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [287.551001] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [287.551223] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:173:plane 1B] fb: [FB:636] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [287.551448] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [287.551673] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [287.551901] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:203:plane 2B] fb: [NOFB], visible: no <7> [287.552132] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:233:plane 3B] fb: [NOFB], visible: no <7> [287.552292] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:263:plane 4B] fb: [NOFB], visible: no <7> [287.552450] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:273:plane 5B] fb: [NOFB], visible: no <7> [287.552607] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:283:plane 6B] fb: [NOFB], visible: no <7> [287.552764] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:293:plane 7B] fb: [NOFB], visible: no <7> [287.552922] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:303:cursor B] fb: [NOFB], visible: no <7> [287.553681] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [287.553865] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_3 <7> [287.554085] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 192000 kHz, VCO 384000 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [287.554357] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI B/PHY B] <7> [287.554524] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DDI TC1/PHY TC1] <7> [287.554688] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST A] <7> [287.554850] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST B] <7> [287.555025] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST C] <7> [287.555186] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:602:DP-MST D] <7> [287.555347] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DDI TC2/PHY TC2] <7> [287.555505] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST A] <7> [287.555663] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST B] <7> [287.555823] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST C] <7> [287.555994] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST D] <7> [287.556158] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DDI TC3/PHY TC3] <7> [287.556318] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST A] <7> [287.556479] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST B] <7> [287.556645] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST C] <7> [287.556802] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:621:DP-MST D] <7> [287.556966] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DDI TC4/PHY TC4] <7> [287.557126] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST A] <7> [287.557283] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST B] <7> [287.557441] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST C] <7> [287.557651] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:630:DP-MST D] <7> [287.558097] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [287.558379] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:309:pipe B] <7> [287.558617] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0 <7> [287.558905] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B <7> [287.559258] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [287.560144] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:588:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10 <7> [287.560786] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [287.561022] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [287.561640] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [287.561877] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:588:HDMI-A-1] Failed to read TMDS config: -6 <7> [287.561904] i915 0000:00:02.0: [drm:intel_ddi_enable [i915]] [CONNECTOR:588:HDMI-A-1] Failed to configure sink scrambling/TMDS bit clock ratio <7> [287.570665] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:588:HDMI-A-1][ENCODER:587:DDI B/PHY B] Enable audio codec on [CRTC:309:pipe B], 64 bytes ELD <7> [287.579003] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] HDMI audio pixel clock setting for 285500 not found, falling back to defaults <7> [287.579191] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000) <7> [287.579351] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <6> [287.579517] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 5 not expected <6> [287.579520] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 0 not expected <6> [287.579521] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 10 not expected <6> [287.579523] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 6 not expected <7> [287.579666] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:588:HDMI-A-1] <7> [287.579925] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:309:pipe B] <7> [287.595009] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x810 <7> [287.599541] azx_init_pci: snd_hda_intel 0000:00:1f.3: Clearing TCSEL <7> [287.599582] azx_init_pci: snd_hda_intel 0000:00:1f.3: SCH snoop: Enabled <6> [293.645785] [IGT] kms_flip: finished subtest B-HDMI-A1, FAIL

Detail

Value

Duration

6.18 seconds

Hostname

shard-tglu-9

Igt-Version

IGT-Version: 2.4-g02b0e01dd (x86_64) (Linux: 7.1.0-rc1-CI_DRM_18377-ga53aafc879e9+ x86_64)

Out

Starting dynamic subtest: B-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c: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-HDMI-A1: FAIL (6.181s)

Err

Starting dynamic subtest: B-HDMI-A1
(kms_flip:18182) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:18182) CRITICAL: Failed assertion: end - start < 500
(kms_flip:18182) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.639267
last_received_ts = 214.638931
last_seq = 889
current_ts = 214.647614
current_received_ts = 214.647293
current_seq = 890
count = 594
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.647614
last_received_ts = 214.647293
last_seq = 890
current_ts = 214.655945
current_received_ts = 214.655670
current_seq = 891
count = 595
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.655945
last_received_ts = 214.655670
last_seq = 891
current_ts = 214.664291
current_received_ts = 214.663986
current_seq = 892
count = 596
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.664291
last_received_ts = 214.663986
last_seq = 892
current_ts = 214.672623
current_received_ts = 214.672379
current_seq = 893
count = 597
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 32us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.672623
last_received_ts = 214.672379
last_seq = 893
current_ts = 214.680969
current_received_ts = 214.680649
current_seq = 894
count = 598
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 27us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.680969
last_received_ts = 214.680649
last_seq = 894
current_ts = 214.689301
current_received_ts = 214.688934
current_seq = 895
count = 599
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.689301
last_received_ts = 214.688934
last_seq = 895
current_ts = 214.697647
current_received_ts = 214.697311
current_seq = 896
count = 600
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.697647
last_received_ts = 214.697311
last_seq = 896
current_ts = 214.705978
current_received_ts = 214.705627
current_seq = 897
count = 601
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 24us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.705978
last_received_ts = 214.705627
last_seq = 897
current_ts = 214.714310
current_received_ts = 214.714096
current_seq = 898
count = 602
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.714310
last_received_ts = 214.714096
last_seq = 898
current_ts = 214.722656
current_received_ts = 214.722321
current_seq = 899
count = 603
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 29us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.722656
last_received_ts = 214.722321
last_seq = 899
current_ts = 214.731003
current_received_ts = 214.730667
current_seq = 900
count = 604
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 28us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.731003
last_received_ts = 214.730667
last_seq = 900
current_ts = 214.739334
current_received_ts = 214.738968
current_seq = 901
count = 605
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 27us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.739334
last_received_ts = 214.738968
last_seq = 901
current_ts = 214.747681
current_received_ts = 214.747345
current_seq = 902
count = 606
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 29us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.747681
last_received_ts = 214.747345
last_seq = 902
current_ts = 214.756012
current_received_ts = 214.755661
current_seq = 903
count = 607
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 22us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.756012
last_received_ts = 214.755661
last_seq = 903
current_ts = 214.764343
current_received_ts = 214.764038
current_seq = 904
count = 608
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.764343
last_received_ts = 214.764038
last_seq = 904
current_ts = 214.772690
current_received_ts = 214.772354
current_seq = 905
count = 609
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.772690
last_received_ts = 214.772354
last_seq = 905
current_ts = 214.781021
current_received_ts = 214.780716
current_seq = 906
count = 610
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 33us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.781021
last_received_ts = 214.780716
last_seq = 906
current_ts = 214.789368
current_received_ts = 214.789078
current_seq = 907
count = 611
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 32us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.789368
last_received_ts = 214.789078
last_seq = 907
current_ts = 214.797699
current_received_ts = 214.797455
current_seq = 908
count = 612
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.797699
last_received_ts = 214.797455
last_seq = 908
current_ts = 214.806030
current_received_ts = 214.805710
current_seq = 909
count = 613
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 27us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.806030
last_received_ts = 214.805710
last_seq = 909
current_ts = 214.814377
current_received_ts = 214.814804
current_seq = 910
count = 614
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.814377
last_received_ts = 214.814804
last_seq = 910
current_ts = 214.822708
current_received_ts = 214.822388
current_seq = 911
count = 615
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.822708
last_received_ts = 214.822388
last_seq = 911
current_ts = 214.831055
current_received_ts = 214.830719
current_seq = 912
count = 616
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.831055
last_received_ts = 214.830719
last_seq = 912
current_ts = 214.839401
current_received_ts = 214.839066
current_seq = 913
count = 617
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 30us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.839401
last_received_ts = 214.839066
last_seq = 913
current_ts = 214.847733
current_received_ts = 214.847458
current_seq = 914
count = 618
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 22us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.847733
last_received_ts = 214.847458
last_seq = 914
current_ts = 214.856079
current_received_ts = 214.855759
current_seq = 915
count = 619
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 29us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.856079
last_received_ts = 214.855759
last_seq = 915
current_ts = 214.864410
current_received_ts = 214.864151
current_seq = 916
count = 620
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.864410
last_received_ts = 214.864151
last_seq = 916
current_ts = 214.872742
current_received_ts = 214.872406
current_seq = 917
count = 621
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.872742
last_received_ts = 214.872406
last_seq = 917
current_ts = 214.881088
current_received_ts = 214.880859
current_seq = 918
count = 622
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 24us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.881088
last_received_ts = 214.880859
last_seq = 918
current_ts = 214.889420
current_received_ts = 214.889069
current_seq = 919
count = 623
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 34us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.889420
last_received_ts = 214.889069
last_seq = 919
current_ts = 214.897766
current_received_ts = 214.897476
current_seq = 920
count = 624
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 22us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.897766
last_received_ts = 214.897476
last_seq = 920
current_ts = 214.906097
current_received_ts = 214.905731
current_seq = 921
count = 625
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.906097
last_received_ts = 214.905731
last_seq = 921
current_ts = 214.914444
current_received_ts = 214.914078
current_seq = 922
count = 626
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.914444
last_received_ts = 214.914078
last_seq = 922
current_ts = 214.922775
current_received_ts = 214.922455
current_seq = 923
count = 627
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.922775
last_received_ts = 214.922455
last_seq = 923
current_ts = 214.931122
current_received_ts = 214.930786
current_seq = 924
count = 628
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 22us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.931122
last_received_ts = 214.930786
last_seq = 924
current_ts = 214.939453
current_received_ts = 214.939148
current_seq = 925
count = 629
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.939453
last_received_ts = 214.939148
last_seq = 925
current_ts = 214.947784
current_received_ts = 214.947495
current_seq = 926
count = 630
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 24us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.947784
last_received_ts = 214.947495
last_seq = 926
current_ts = 214.956131
current_received_ts = 214.955795
current_seq = 927
count = 631
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.956131
last_received_ts = 214.955795
last_seq = 927
current_ts = 214.964462
current_received_ts = 214.964218
current_seq = 928
count = 632
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.964462
last_received_ts = 214.964218
last_seq = 928
current_ts = 214.972809
current_received_ts = 214.972580
current_seq = 929
count = 633
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 35us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.972809
last_received_ts = 214.972580
last_seq = 929
current_ts = 214.981140
current_received_ts = 214.980881
current_seq = 930
count = 634
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 30us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.981140
last_received_ts = 214.980881
last_seq = 930
current_ts = 214.989487
current_received_ts = 214.989212
current_seq = 931
count = 635
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 34us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.989487
last_received_ts = 214.989212
last_seq = 931
current_ts = 214.997818
current_received_ts = 214.997528
current_seq = 932
count = 636
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 214.997818
last_received_ts = 214.997528
last_seq = 932
current_ts = 215.006165
current_received_ts = 215.005844
current_seq = 933
count = 637
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 35us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.006165
last_received_ts = 215.005844
last_seq = 933
current_ts = 215.014496
current_received_ts = 215.014221
current_seq = 934
count = 638
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 27us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.014496
last_received_ts = 215.014221
last_seq = 934
current_ts = 215.022827
current_received_ts = 215.022522
current_seq = 935
count = 639
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 38us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.022827
last_received_ts = 215.022522
last_seq = 935
current_ts = 215.031174
current_received_ts = 215.030899
current_seq = 936
count = 640
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.031174
last_received_ts = 215.030899
last_seq = 936
current_ts = 215.039505
current_received_ts = 215.039185
current_seq = 937
count = 641
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 34us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.039505
last_received_ts = 215.039185
last_seq = 937
current_ts = 215.047852
current_received_ts = 215.047562
current_seq = 938
count = 642
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.047852
last_received_ts = 215.047562
last_seq = 938
current_ts = 215.056183
current_received_ts = 215.055801
current_seq = 939
count = 643
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.056183
last_received_ts = 215.055801
last_seq = 939
current_ts = 215.064529
current_received_ts = 215.064178
current_seq = 940
count = 644
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.064529
last_received_ts = 215.064178
last_seq = 940
current_ts = 215.072861
current_received_ts = 215.072601
current_seq = 941
count = 645
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 24us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.072861
last_received_ts = 215.072601
last_seq = 941
current_ts = 215.081207
current_received_ts = 215.080856
current_seq = 942
count = 646
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 20us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.081207
last_received_ts = 215.080856
last_seq = 942
current_ts = 215.089539
current_received_ts = 215.089249
current_seq = 943
count = 647
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 22us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.089539
last_received_ts = 215.089249
last_seq = 943
current_ts = 215.097885
current_received_ts = 215.097565
current_seq = 944
count = 648
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 29us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.097885
last_received_ts = 215.097565
last_seq = 944
current_ts = 215.106216
current_received_ts = 215.105881
current_seq = 945
count = 649
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.106216
last_received_ts = 215.105881
last_seq = 945
current_ts = 215.114563
current_received_ts = 215.114212
current_seq = 946
count = 650
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.114563
last_received_ts = 215.114212
last_seq = 946
current_ts = 215.122894
current_received_ts = 215.122559
current_seq = 947
count = 651
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 31us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.122894
last_received_ts = 215.122559
last_seq = 947
current_ts = 215.131241
current_received_ts = 215.130890
current_seq = 948
count = 652
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 50us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.131241
last_received_ts = 215.130890
last_seq = 948
current_ts = 215.139572
current_received_ts = 215.139282
current_seq = 949
count = 653
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 24us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.139572
last_received_ts = 215.139282
last_seq = 949
current_ts = 215.147903
current_received_ts = 215.147629
current_seq = 950
count = 654
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.147903
last_received_ts = 215.147629
last_seq = 950
current_ts = 215.156235
current_received_ts = 215.155884
current_seq = 951
count = 655
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 22us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.156235
last_received_ts = 215.155884
last_seq = 951
current_ts = 215.164581
current_received_ts = 215.164261
current_seq = 952
count = 656
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.164581
last_received_ts = 215.164261
last_seq = 952
current_ts = 215.172928
current_received_ts = 215.172577
current_seq = 953
count = 657
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 28us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.172928
last_received_ts = 215.172577
last_seq = 953
current_ts = 215.181259
current_received_ts = 215.180954
current_seq = 954
count = 658
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 46us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.181259
last_received_ts = 215.180954
last_seq = 954
current_ts = 215.189590
current_received_ts = 215.189255
current_seq = 955
count = 659
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.189590
last_received_ts = 215.189255
last_seq = 955
current_ts = 215.197937
current_received_ts = 215.197586
current_seq = 956
count = 660
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.197937
last_received_ts = 215.197586
last_seq = 956
current_ts = 215.206268
current_received_ts = 215.205917
current_seq = 957
count = 661
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 24us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.206268
last_received_ts = 215.205917
last_seq = 957
current_ts = 215.214615
current_received_ts = 215.214279
current_seq = 958
count = 662
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 24us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.214615
last_received_ts = 215.214279
last_seq = 958
current_ts = 215.222946
current_received_ts = 215.222717
current_seq = 959
count = 663
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.222946
last_received_ts = 215.222717
last_seq = 959
current_ts = 215.231293
current_received_ts = 215.230988
current_seq = 960
count = 664
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 32us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.231293
last_received_ts = 215.230988
last_seq = 960
current_ts = 215.239624
current_received_ts = 215.239334
current_seq = 961
count = 665
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.239624
last_received_ts = 215.239334
last_seq = 961
current_ts = 215.247955
current_received_ts = 215.247650
current_seq = 962
count = 666
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 34us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.247955
last_received_ts = 215.247650
last_seq = 962
current_ts = 215.256302
current_received_ts = 215.256012
current_seq = 963
count = 667
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 36us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.256302
last_received_ts = 215.256012
last_seq = 963
current_ts = 215.264633
current_received_ts = 215.264328
current_seq = 964
count = 668
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.264633
last_received_ts = 215.264328
last_seq = 964
current_ts = 215.272980
current_received_ts = 215.272659
current_seq = 965
count = 669
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.272980
last_received_ts = 215.272659
last_seq = 965
current_ts = 215.281311
current_received_ts = 215.281158
current_seq = 966
count = 670
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.281311
last_received_ts = 215.281158
last_seq = 966
current_ts = 215.289658
current_received_ts = 215.289322
current_seq = 967
count = 671
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.289658
last_received_ts = 215.289322
last_seq = 967
current_ts = 215.298004
current_received_ts = 215.297653
current_seq = 968
count = 672
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.298004
last_received_ts = 215.297653
last_seq = 968
current_ts = 215.306335
current_received_ts = 215.305984
current_seq = 969
count = 673
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 36us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.306335
last_received_ts = 215.305984
last_seq = 969
current_ts = 215.314667
current_received_ts = 215.314331
current_seq = 970
count = 674
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.314667
last_received_ts = 215.314331
last_seq = 970
current_ts = 215.323013
current_received_ts = 215.322662
current_seq = 971
count = 675
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 24us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.323013
last_received_ts = 215.322662
last_seq = 971
current_ts = 215.331345
current_received_ts = 215.331024
current_seq = 972
count = 676
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.331345
last_received_ts = 215.331024
last_seq = 972
current_ts = 215.339691
current_received_ts = 215.339325
current_seq = 973
count = 677
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 22us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.339691
last_received_ts = 215.339325
last_seq = 973
current_ts = 215.348022
current_received_ts = 215.347809
current_seq = 974
count = 678
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.348022
last_received_ts = 215.347809
last_seq = 974
current_ts = 215.356369
current_received_ts = 215.356049
current_seq = 975
count = 679
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.356369
last_received_ts = 215.356049
last_seq = 975
current_ts = 215.364700
current_received_ts = 215.364471
current_seq = 976
count = 680
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 22us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.364700
last_received_ts = 215.364471
last_seq = 976
current_ts = 215.373032
current_received_ts = 215.372711
current_seq = 977
count = 681
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.373032
last_received_ts = 215.372711
last_seq = 977
current_ts = 215.381378
current_received_ts = 215.381058
current_seq = 978
count = 682
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.381378
last_received_ts = 215.381058
last_seq = 978
current_ts = 215.389709
current_received_ts = 215.389389
current_seq = 979
count = 683
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.389709
last_received_ts = 215.389389
last_seq = 979
current_ts = 215.398056
current_received_ts = 215.397720
current_seq = 980
count = 684
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 29us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.398056
last_received_ts = 215.397720
last_seq = 980
current_ts = 215.406387
current_received_ts = 215.406097
current_seq = 981
count = 685
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.406387
last_received_ts = 215.406097
last_seq = 981
current_ts = 215.414734
current_received_ts = 215.414413
current_seq = 982
count = 686
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 27us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.414734
last_received_ts = 215.414413
last_seq = 982
current_ts = 215.423065
current_received_ts = 215.422729
current_seq = 983
count = 687
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.423065
last_received_ts = 215.422729
last_seq = 983
current_ts = 215.431412
current_received_ts = 215.431046
current_seq = 984
count = 688
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 22us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.431412
last_received_ts = 215.431046
last_seq = 984
current_ts = 215.439743
current_received_ts = 215.439468
current_seq = 985
count = 689
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.439743
last_received_ts = 215.439468
last_seq = 985
current_ts = 215.448090
current_received_ts = 215.447723
current_seq = 986
count = 690
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 20us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.448090
last_received_ts = 215.447723
last_seq = 986
current_ts = 215.456421
current_received_ts = 215.456116
current_seq = 987
count = 691
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 22us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.456421
last_received_ts = 215.456116
last_seq = 987
current_ts = 215.464752
current_received_ts = 215.464493
current_seq = 988
count = 692
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 27us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.464752
last_received_ts = 215.464493
last_seq = 988
current_ts = 215.473099
current_received_ts = 215.472748
current_seq = 989
count = 693
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.473099
last_received_ts = 215.472748
last_seq = 989
current_ts = 215.481430
current_received_ts = 215.481110
current_seq = 990
count = 694
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.481430
last_received_ts = 215.481110
last_seq = 990
current_ts = 215.489761
current_received_ts = 215.489410
current_seq = 991
count = 695
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.489761
last_received_ts = 215.489410
last_seq = 991
current_ts = 215.498108
current_received_ts = 215.497955
current_seq = 992
count = 696
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 45us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.498108
last_received_ts = 215.497955
last_seq = 992
current_ts = 215.506454
current_received_ts = 215.506134
current_seq = 993
count = 697
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 24us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.506454
last_received_ts = 215.506134
last_seq = 993
current_ts = 215.514786
current_received_ts = 215.514557
current_seq = 994
count = 698
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.514786
last_received_ts = 215.514557
last_seq = 994
current_ts = 215.523132
current_received_ts = 215.522797
current_seq = 995
count = 699
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 28us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.523132
last_received_ts = 215.522797
last_seq = 995
current_ts = 215.531464
current_received_ts = 215.531189
current_seq = 996
count = 700
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.531464
last_received_ts = 215.531189
last_seq = 996
current_ts = 215.539810
current_received_ts = 215.539459
current_seq = 997
count = 701
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 24us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.539810
last_received_ts = 215.539459
last_seq = 997
current_ts = 215.548141
current_received_ts = 215.547729
current_seq = 998
count = 702
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 22us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.548141
last_received_ts = 215.547729
last_seq = 998
current_ts = 215.556473
current_received_ts = 215.556183
current_seq = 999
count = 703
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 27us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.556473
last_received_ts = 215.556183
last_seq = 999
current_ts = 215.564819
current_received_ts = 215.564590
current_seq = 1000
count = 704
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 27us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.564819
last_received_ts = 215.564590
last_seq = 1000
current_ts = 215.573151
current_received_ts = 215.572830
current_seq = 1001
count = 705
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 24us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.573151
last_received_ts = 215.572830
last_seq = 1001
current_ts = 215.581482
current_received_ts = 215.581207
current_seq = 1002
count = 706
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 47us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.581482
last_received_ts = 215.581207
last_seq = 1002
current_ts = 215.589828
current_received_ts = 215.589554
current_seq = 1003
count = 707
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.589828
last_received_ts = 215.589554
last_seq = 1003
current_ts = 215.598175
current_received_ts = 215.597916
current_seq = 1004
count = 708
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.598175
last_received_ts = 215.597916
last_seq = 1004
current_ts = 215.606506
current_received_ts = 215.606186
current_seq = 1005
count = 709
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 26us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.606506
last_received_ts = 215.606186
last_seq = 1005
current_ts = 215.614838
current_received_ts = 215.614563
current_seq = 1006
count = 710
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.614838
last_received_ts = 215.614563
last_seq = 1006
current_ts = 215.623184
current_received_ts = 215.622818
current_seq = 1007
count = 711
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 20us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.623184
last_received_ts = 215.622818
last_seq = 1007
current_ts = 215.631516
current_received_ts = 215.631226
current_seq = 1008
count = 712
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 25us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.631516
last_received_ts = 215.631226
last_seq = 1008
current_ts = 215.639862
current_received_ts = 215.639496
current_seq = 1009
count = 713
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 23us
(kms_flip:18182) DEBUG: name = flip
last_ts = 215.639862
last_received_ts = 215.639496
last_seq = 1009
current_ts = 215.648193
current_received_ts = 215.647964
current_seq = 1010
count = 714
seq_step = 1
(kms_flip:18182) DEBUG: Vblank took 746us
(kms_flip:18182) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:18182) CRITICAL: Failed assertion: end - start < 500
(kms_flip:18182) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:18182) igt_core-INFO: Stack trace:
(kms_flip:18182) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:18182) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:18182) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:18182) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:18182) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:18182) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:18182) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:18182) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (6.181s)

Dmesg

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

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

<7> [287.462984] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:650]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [287.541371] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 8, 8, 8, 8, 11, 16, 16, 0, 0, 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [287.546416] 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> [287.546575] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5

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

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

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

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

<7> [287.547400] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 285500, pixel rate 285500, min cdclk 192000, min voltage level 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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