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

Detail	Value
Duration	7.03 seconds
Hostname	shard-lnl-1
Igt-Version	IGT-Version: 2.3-ga7015a99f (x86_64) (Linux: 7.0.0-rc4-lgci-xe-xe-4757-166a38809296432cd-debug+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1891 run_test() #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047() #4 ../tests/kms_flip.c:2047 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (7.030s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:7897) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:7897) CRITICAL: Failed assertion: end - start < 500 (kms_flip:7897) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 506.722260 last_received_ts = 506.721649 last_seq = 926 current_ts = 506.738922 current_received_ts = 506.738464 current_seq = 927 count = 226 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 506.738922 last_received_ts = 506.738464 last_seq = 927 current_ts = 506.755585 current_received_ts = 506.755127 current_seq = 928 count = 227 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 506.755585 last_received_ts = 506.755127 last_seq = 928 current_ts = 506.772247 current_received_ts = 506.771790 current_seq = 929 count = 228 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 31us (kms_flip:7897) DEBUG: name = flip last_ts = 506.772247 last_received_ts = 506.771790 last_seq = 929 current_ts = 506.788910 current_received_ts = 506.788483 current_seq = 930 count = 229 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 30us (kms_flip:7897) DEBUG: name = flip last_ts = 506.788910 last_received_ts = 506.788483 last_seq = 930 current_ts = 506.805573 current_received_ts = 506.805115 current_seq = 931 count = 230 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 506.805573 last_received_ts = 506.805115 last_seq = 931 current_ts = 506.822235 current_received_ts = 506.821777 current_seq = 932 count = 231 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 506.822235 last_received_ts = 506.821777 last_seq = 932 current_ts = 506.838898 current_received_ts = 506.838470 current_seq = 933 count = 232 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 34us (kms_flip:7897) DEBUG: name = flip last_ts = 506.838898 last_received_ts = 506.838470 last_seq = 933 current_ts = 506.855591 current_received_ts = 506.855103 current_seq = 934 count = 233 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 30us (kms_flip:7897) DEBUG: name = flip last_ts = 506.855591 last_received_ts = 506.855103 last_seq = 934 current_ts = 506.872253 current_received_ts = 506.871643 current_seq = 935 count = 234 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 506.872253 last_received_ts = 506.871643 last_seq = 935 current_ts = 506.888916 current_received_ts = 506.888458 current_seq = 936 count = 235 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 506.888916 last_received_ts = 506.888458 last_seq = 936 current_ts = 506.905579 current_received_ts = 506.905121 current_seq = 937 count = 236 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 30us (kms_flip:7897) DEBUG: name = flip last_ts = 506.905579 last_received_ts = 506.905121 last_seq = 937 current_ts = 506.922241 current_received_ts = 506.921783 current_seq = 938 count = 237 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 506.922241 last_received_ts = 506.921783 last_seq = 938 current_ts = 506.938904 current_received_ts = 506.938477 current_seq = 939 count = 238 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 88us (kms_flip:7897) DEBUG: name = flip last_ts = 506.938904 last_received_ts = 506.938477 last_seq = 939 current_ts = 506.955566 current_received_ts = 506.955139 current_seq = 940 count = 239 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 506.955566 last_received_ts = 506.955139 last_seq = 940 current_ts = 506.972229 current_received_ts = 506.971680 current_seq = 941 count = 240 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 34us (kms_flip:7897) DEBUG: name = flip last_ts = 506.972229 last_received_ts = 506.971680 last_seq = 941 current_ts = 506.988892 current_received_ts = 506.988464 current_seq = 942 count = 241 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 506.988892 last_received_ts = 506.988464 last_seq = 942 current_ts = 507.005554 current_received_ts = 507.004944 current_seq = 943 count = 242 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 507.005554 last_received_ts = 507.004944 last_seq = 943 current_ts = 507.022217 current_received_ts = 507.021484 current_seq = 944 count = 243 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 108us (kms_flip:7897) DEBUG: name = flip last_ts = 507.022217 last_received_ts = 507.021484 last_seq = 944 current_ts = 507.038910 current_received_ts = 507.038116 current_seq = 945 count = 244 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 44us (kms_flip:7897) DEBUG: name = flip last_ts = 507.038910 last_received_ts = 507.038116 last_seq = 945 current_ts = 507.055573 current_received_ts = 507.055084 current_seq = 946 count = 245 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 30us (kms_flip:7897) DEBUG: name = flip last_ts = 507.055573 last_received_ts = 507.055084 last_seq = 946 current_ts = 507.072205 current_received_ts = 507.071808 current_seq = 947 count = 246 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 29us (kms_flip:7897) DEBUG: name = flip last_ts = 507.072205 last_received_ts = 507.071808 last_seq = 947 current_ts = 507.088898 current_received_ts = 507.088440 current_seq = 948 count = 247 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 507.088898 last_received_ts = 507.088440 last_seq = 948 current_ts = 507.105560 current_received_ts = 507.105072 current_seq = 949 count = 248 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 30us (kms_flip:7897) DEBUG: name = flip last_ts = 507.105560 last_received_ts = 507.105072 last_seq = 949 current_ts = 507.122223 current_received_ts = 507.121582 current_seq = 950 count = 249 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 507.122223 last_received_ts = 507.121582 last_seq = 950 current_ts = 507.138885 current_received_ts = 507.138458 current_seq = 951 count = 250 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 99us (kms_flip:7897) DEBUG: name = flip last_ts = 507.138885 last_received_ts = 507.138458 last_seq = 951 current_ts = 507.155548 current_received_ts = 507.155090 current_seq = 952 count = 251 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 31us (kms_flip:7897) DEBUG: name = flip last_ts = 507.155548 last_received_ts = 507.155090 last_seq = 952 current_ts = 507.172211 current_received_ts = 507.171783 current_seq = 953 count = 252 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 507.172211 last_received_ts = 507.171783 last_seq = 953 current_ts = 507.188873 current_received_ts = 507.188446 current_seq = 954 count = 253 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 35us (kms_flip:7897) DEBUG: name = flip last_ts = 507.188873 last_received_ts = 507.188446 last_seq = 954 current_ts = 507.205536 current_received_ts = 507.205078 current_seq = 955 count = 254 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 34us (kms_flip:7897) DEBUG: name = flip last_ts = 507.205536 last_received_ts = 507.205078 last_seq = 955 current_ts = 507.222198 current_received_ts = 507.221619 current_seq = 956 count = 255 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 507.222198 last_received_ts = 507.221619 last_seq = 956 current_ts = 507.238861 current_received_ts = 507.238403 current_seq = 957 count = 256 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 119us (kms_flip:7897) DEBUG: name = flip last_ts = 507.238861 last_received_ts = 507.238403 last_seq = 957 current_ts = 507.255524 current_received_ts = 507.254791 current_seq = 958 count = 257 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 148us (kms_flip:7897) DEBUG: name = flip last_ts = 507.255524 last_received_ts = 507.254791 last_seq = 958 current_ts = 507.272186 current_received_ts = 507.271423 current_seq = 959 count = 258 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 60us (kms_flip:7897) DEBUG: name = flip last_ts = 507.272186 last_received_ts = 507.271423 last_seq = 959 current_ts = 507.288879 current_received_ts = 507.288452 current_seq = 960 count = 259 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 35us (kms_flip:7897) DEBUG: name = flip last_ts = 507.288879 last_received_ts = 507.288452 last_seq = 960 current_ts = 507.305511 current_received_ts = 507.305084 current_seq = 961 count = 260 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 507.305511 last_received_ts = 507.305084 last_seq = 961 current_ts = 507.322205 current_received_ts = 507.321503 current_seq = 962 count = 261 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 36us (kms_flip:7897) DEBUG: name = flip last_ts = 507.322205 last_received_ts = 507.321503 last_seq = 962 current_ts = 507.338867 current_received_ts = 507.338440 current_seq = 963 count = 262 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 35us (kms_flip:7897) DEBUG: name = flip last_ts = 507.338867 last_received_ts = 507.338440 last_seq = 963 current_ts = 507.355530 current_received_ts = 507.355072 current_seq = 964 count = 263 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 507.355530 last_received_ts = 507.355072 last_seq = 964 current_ts = 507.372192 current_received_ts = 507.371735 current_seq = 965 count = 264 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 35us (kms_flip:7897) DEBUG: name = flip last_ts = 507.372192 last_received_ts = 507.371735 last_seq = 965 current_ts = 507.388855 current_received_ts = 507.388458 current_seq = 966 count = 265 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 35us (kms_flip:7897) DEBUG: name = flip last_ts = 507.388855 last_received_ts = 507.388458 last_seq = 966 current_ts = 507.405518 current_received_ts = 507.405060 current_seq = 967 count = 266 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 507.405518 last_received_ts = 507.405060 last_seq = 967 current_ts = 507.422180 current_received_ts = 507.421509 current_seq = 968 count = 267 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 31us (kms_flip:7897) DEBUG: name = flip last_ts = 507.422180 last_received_ts = 507.421509 last_seq = 968 current_ts = 507.438843 current_received_ts = 507.438416 current_seq = 969 count = 268 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 507.438843 last_received_ts = 507.438416 last_seq = 969 current_ts = 507.455505 current_received_ts = 507.455078 current_seq = 970 count = 269 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 507.455505 last_received_ts = 507.455078 last_seq = 970 current_ts = 507.472168 current_received_ts = 507.471771 current_seq = 971 count = 270 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 507.472168 last_received_ts = 507.471771 last_seq = 971 current_ts = 507.488861 current_received_ts = 507.488434 current_seq = 972 count = 271 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 507.488861 last_received_ts = 507.488434 last_seq = 972 current_ts = 507.505524 current_received_ts = 507.504913 current_seq = 973 count = 272 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 90us (kms_flip:7897) DEBUG: name = flip last_ts = 507.505524 last_received_ts = 507.504913 last_seq = 973 current_ts = 507.522186 current_received_ts = 507.521667 current_seq = 974 count = 273 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 88us (kms_flip:7897) DEBUG: name = flip last_ts = 507.522186 last_received_ts = 507.521667 last_seq = 974 current_ts = 507.538849 current_received_ts = 507.538391 current_seq = 975 count = 274 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 29us (kms_flip:7897) DEBUG: name = flip last_ts = 507.538849 last_received_ts = 507.538391 last_seq = 975 current_ts = 507.555511 current_received_ts = 507.555054 current_seq = 976 count = 275 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 507.555511 last_received_ts = 507.555054 last_seq = 976 current_ts = 507.572174 current_received_ts = 507.571747 current_seq = 977 count = 276 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 507.572174 last_received_ts = 507.571747 last_seq = 977 current_ts = 507.588837 current_received_ts = 507.588409 current_seq = 978 count = 277 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 91us (kms_flip:7897) DEBUG: name = flip last_ts = 507.588837 last_received_ts = 507.588409 last_seq = 978 current_ts = 507.605499 current_received_ts = 507.605042 current_seq = 979 count = 278 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 507.605499 last_received_ts = 507.605042 last_seq = 979 current_ts = 507.622162 current_received_ts = 507.621521 current_seq = 980 count = 279 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 507.622162 last_received_ts = 507.621521 last_seq = 980 current_ts = 507.638824 current_received_ts = 507.638397 current_seq = 981 count = 280 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 34us (kms_flip:7897) DEBUG: name = flip last_ts = 507.638824 last_received_ts = 507.638397 last_seq = 981 current_ts = 507.655487 current_received_ts = 507.655060 current_seq = 982 count = 281 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 507.655487 last_received_ts = 507.655060 last_seq = 982 current_ts = 507.672150 current_received_ts = 507.671478 current_seq = 983 count = 282 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 86us (kms_flip:7897) DEBUG: name = flip last_ts = 507.672150 last_received_ts = 507.671478 last_seq = 983 current_ts = 507.688843 current_received_ts = 507.688385 current_seq = 984 count = 283 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 29us (kms_flip:7897) DEBUG: name = flip last_ts = 507.688843 last_received_ts = 507.688385 last_seq = 984 current_ts = 507.705505 current_received_ts = 507.705048 current_seq = 985 count = 284 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 30us (kms_flip:7897) DEBUG: name = flip last_ts = 507.705505 last_received_ts = 507.705048 last_seq = 985 current_ts = 507.722137 current_received_ts = 507.721497 current_seq = 986 count = 285 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 88us (kms_flip:7897) DEBUG: name = flip last_ts = 507.722137 last_received_ts = 507.721497 last_seq = 986 current_ts = 507.738831 current_received_ts = 507.738373 current_seq = 987 count = 286 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 30us (kms_flip:7897) DEBUG: name = flip last_ts = 507.738831 last_received_ts = 507.738373 last_seq = 987 current_ts = 507.755493 current_received_ts = 507.755066 current_seq = 988 count = 287 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 91us (kms_flip:7897) DEBUG: name = flip last_ts = 507.755493 last_received_ts = 507.755066 last_seq = 988 current_ts = 507.772156 current_received_ts = 507.771698 current_seq = 989 count = 288 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 87us (kms_flip:7897) DEBUG: name = flip last_ts = 507.772156 last_received_ts = 507.771698 last_seq = 989 current_ts = 507.788818 current_received_ts = 507.788361 current_seq = 990 count = 289 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 31us (kms_flip:7897) DEBUG: name = flip last_ts = 507.788818 last_received_ts = 507.788361 last_seq = 990 current_ts = 507.805481 current_received_ts = 507.805054 current_seq = 991 count = 290 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 34us (kms_flip:7897) DEBUG: name = flip last_ts = 507.805481 last_received_ts = 507.805054 last_seq = 991 current_ts = 507.822144 current_received_ts = 507.821533 current_seq = 992 count = 291 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 105us (kms_flip:7897) DEBUG: name = flip last_ts = 507.822144 last_received_ts = 507.821533 last_seq = 992 current_ts = 507.838806 current_received_ts = 507.838348 current_seq = 993 count = 292 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 36us (kms_flip:7897) DEBUG: name = flip last_ts = 507.838806 last_received_ts = 507.838348 last_seq = 993 current_ts = 507.855469 current_received_ts = 507.855042 current_seq = 994 count = 293 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 34us (kms_flip:7897) DEBUG: name = flip last_ts = 507.855469 last_received_ts = 507.855042 last_seq = 994 current_ts = 507.872131 current_received_ts = 507.871490 current_seq = 995 count = 294 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 37us (kms_flip:7897) DEBUG: name = flip last_ts = 507.872131 last_received_ts = 507.871490 last_seq = 995 current_ts = 507.888794 current_received_ts = 507.888367 current_seq = 996 count = 295 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 86us (kms_flip:7897) DEBUG: name = flip last_ts = 507.888794 last_received_ts = 507.888367 last_seq = 996 current_ts = 507.905487 current_received_ts = 507.904999 current_seq = 997 count = 296 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 48us (kms_flip:7897) DEBUG: name = flip last_ts = 507.905487 last_received_ts = 507.904999 last_seq = 997 current_ts = 507.922150 current_received_ts = 507.921722 current_seq = 998 count = 297 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 114us (kms_flip:7897) DEBUG: name = flip last_ts = 507.922150 last_received_ts = 507.921722 last_seq = 998 current_ts = 507.938812 current_received_ts = 507.938354 current_seq = 999 count = 298 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 31us (kms_flip:7897) DEBUG: name = flip last_ts = 507.938812 last_received_ts = 507.938354 last_seq = 999 current_ts = 507.955475 current_received_ts = 507.955048 current_seq = 1000 count = 299 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 507.955475 last_received_ts = 507.955048 last_seq = 1000 current_ts = 507.972137 current_received_ts = 507.971466 current_seq = 1001 count = 300 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 116us (kms_flip:7897) DEBUG: name = flip last_ts = 507.972137 last_received_ts = 507.971466 last_seq = 1001 current_ts = 507.988800 current_received_ts = 507.988373 current_seq = 1002 count = 301 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 110us (kms_flip:7897) DEBUG: name = flip last_ts = 507.988800 last_received_ts = 507.988373 last_seq = 1002 current_ts = 508.005463 current_received_ts = 508.005035 current_seq = 1003 count = 302 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 508.005463 last_received_ts = 508.005035 last_seq = 1003 current_ts = 508.022125 current_received_ts = 508.021698 current_seq = 1004 count = 303 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 92us (kms_flip:7897) DEBUG: name = flip last_ts = 508.022125 last_received_ts = 508.021698 last_seq = 1004 current_ts = 508.038788 current_received_ts = 508.038361 current_seq = 1005 count = 304 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 113us (kms_flip:7897) DEBUG: name = flip last_ts = 508.038788 last_received_ts = 508.038361 last_seq = 1005 current_ts = 508.055450 current_received_ts = 508.055054 current_seq = 1006 count = 305 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 508.055450 last_received_ts = 508.055054 last_seq = 1006 current_ts = 508.072113 current_received_ts = 508.071503 current_seq = 1007 count = 306 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 38us (kms_flip:7897) DEBUG: name = flip last_ts = 508.072113 last_received_ts = 508.071503 last_seq = 1007 current_ts = 508.088776 current_received_ts = 508.088226 current_seq = 1008 count = 307 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 508.088776 last_received_ts = 508.088226 last_seq = 1008 current_ts = 508.105438 current_received_ts = 508.105011 current_seq = 1009 count = 308 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 31us (kms_flip:7897) DEBUG: name = flip last_ts = 508.105438 last_received_ts = 508.105011 last_seq = 1009 current_ts = 508.122101 current_received_ts = 508.121338 current_seq = 1010 count = 309 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 43us (kms_flip:7897) DEBUG: name = flip last_ts = 508.122101 last_received_ts = 508.121338 last_seq = 1010 current_ts = 508.138794 current_received_ts = 508.138306 current_seq = 1011 count = 310 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 34us (kms_flip:7897) DEBUG: name = flip last_ts = 508.138794 last_received_ts = 508.138306 last_seq = 1011 current_ts = 508.155457 current_received_ts = 508.155060 current_seq = 1012 count = 311 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 31us (kms_flip:7897) DEBUG: name = flip last_ts = 508.155457 last_received_ts = 508.155060 last_seq = 1012 current_ts = 508.172119 current_received_ts = 508.171692 current_seq = 1013 count = 312 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 508.172119 last_received_ts = 508.171692 last_seq = 1013 current_ts = 508.188782 current_received_ts = 508.188324 current_seq = 1014 count = 313 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 114us (kms_flip:7897) DEBUG: name = flip last_ts = 508.188782 last_received_ts = 508.188324 last_seq = 1014 current_ts = 508.205444 current_received_ts = 508.205048 current_seq = 1015 count = 314 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 90us (kms_flip:7897) DEBUG: name = flip last_ts = 508.205444 last_received_ts = 508.205048 last_seq = 1015 current_ts = 508.222107 current_received_ts = 508.221710 current_seq = 1016 count = 315 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 86us (kms_flip:7897) DEBUG: name = flip last_ts = 508.222107 last_received_ts = 508.221710 last_seq = 1016 current_ts = 508.238770 current_received_ts = 508.238220 current_seq = 1017 count = 316 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 508.238770 last_received_ts = 508.238220 last_seq = 1017 current_ts = 508.255432 current_received_ts = 508.255005 current_seq = 1018 count = 317 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 88us (kms_flip:7897) DEBUG: name = flip last_ts = 508.255432 last_received_ts = 508.255005 last_seq = 1018 current_ts = 508.272095 current_received_ts = 508.271667 current_seq = 1019 count = 318 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 93us (kms_flip:7897) DEBUG: name = flip last_ts = 508.272095 last_received_ts = 508.271667 last_seq = 1019 current_ts = 508.288757 current_received_ts = 508.288147 current_seq = 1020 count = 319 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 30us (kms_flip:7897) DEBUG: name = flip last_ts = 508.288757 last_received_ts = 508.288147 last_seq = 1020 current_ts = 508.305420 current_received_ts = 508.305023 current_seq = 1021 count = 320 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 33us (kms_flip:7897) DEBUG: name = flip last_ts = 508.305420 last_received_ts = 508.305023 last_seq = 1021 current_ts = 508.322083 current_received_ts = 508.321533 current_seq = 1022 count = 321 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 87us (kms_flip:7897) DEBUG: name = flip last_ts = 508.322083 last_received_ts = 508.321533 last_seq = 1022 current_ts = 508.338745 current_received_ts = 508.338287 current_seq = 1023 count = 322 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 91us (kms_flip:7897) DEBUG: name = flip last_ts = 508.338745 last_received_ts = 508.338287 last_seq = 1023 current_ts = 508.355438 current_received_ts = 508.354980 current_seq = 1024 count = 323 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 42us (kms_flip:7897) DEBUG: name = flip last_ts = 508.355438 last_received_ts = 508.354980 last_seq = 1024 current_ts = 508.372101 current_received_ts = 508.371490 current_seq = 1025 count = 324 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 93us (kms_flip:7897) DEBUG: name = flip last_ts = 508.372101 last_received_ts = 508.371490 last_seq = 1025 current_ts = 508.388763 current_received_ts = 508.388214 current_seq = 1026 count = 325 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 31us (kms_flip:7897) DEBUG: name = flip last_ts = 508.388763 last_received_ts = 508.388214 last_seq = 1026 current_ts = 508.405426 current_received_ts = 508.404968 current_seq = 1027 count = 326 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 37us (kms_flip:7897) DEBUG: name = flip last_ts = 508.405426 last_received_ts = 508.404968 last_seq = 1027 current_ts = 508.422089 current_received_ts = 508.421661 current_seq = 1028 count = 327 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 104us (kms_flip:7897) DEBUG: name = flip last_ts = 508.422089 last_received_ts = 508.421661 last_seq = 1028 current_ts = 508.438751 current_received_ts = 508.438293 current_seq = 1029 count = 328 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 30us (kms_flip:7897) DEBUG: name = flip last_ts = 508.438751 last_received_ts = 508.438293 last_seq = 1029 current_ts = 508.455414 current_received_ts = 508.454956 current_seq = 1030 count = 329 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 43us (kms_flip:7897) DEBUG: name = flip last_ts = 508.455414 last_received_ts = 508.454956 last_seq = 1030 current_ts = 508.472076 current_received_ts = 508.471466 current_seq = 1031 count = 330 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 96us (kms_flip:7897) DEBUG: name = flip last_ts = 508.472076 last_received_ts = 508.471466 last_seq = 1031 current_ts = 508.488739 current_received_ts = 508.488190 current_seq = 1032 count = 331 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 30us (kms_flip:7897) DEBUG: name = flip last_ts = 508.488739 last_received_ts = 508.488190 last_seq = 1032 current_ts = 508.505402 current_received_ts = 508.504791 current_seq = 1033 count = 332 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 93us (kms_flip:7897) DEBUG: name = flip last_ts = 508.505402 last_received_ts = 508.504791 last_seq = 1033 current_ts = 508.522064 current_received_ts = 508.521301 current_seq = 1034 count = 333 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 44us (kms_flip:7897) DEBUG: name = flip last_ts = 508.522064 last_received_ts = 508.521301 last_seq = 1034 current_ts = 508.538727 current_received_ts = 508.537994 current_seq = 1035 count = 334 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 92us (kms_flip:7897) DEBUG: name = flip last_ts = 508.538727 last_received_ts = 508.537994 last_seq = 1035 current_ts = 508.555420 current_received_ts = 508.554962 current_seq = 1036 count = 335 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 54us (kms_flip:7897) DEBUG: name = flip last_ts = 508.555420 last_received_ts = 508.554962 last_seq = 1036 current_ts = 508.572083 current_received_ts = 508.571625 current_seq = 1037 count = 336 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 94us (kms_flip:7897) DEBUG: name = flip last_ts = 508.572083 last_received_ts = 508.571625 last_seq = 1037 current_ts = 508.588745 current_received_ts = 508.588287 current_seq = 1038 count = 337 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 32us (kms_flip:7897) DEBUG: name = flip last_ts = 508.588745 last_received_ts = 508.588287 last_seq = 1038 current_ts = 508.605408 current_received_ts = 508.604950 current_seq = 1039 count = 338 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 100us (kms_flip:7897) DEBUG: name = flip last_ts = 508.605408 last_received_ts = 508.604950 last_seq = 1039 current_ts = 508.622070 current_received_ts = 508.621613 current_seq = 1040 count = 339 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 91us (kms_flip:7897) DEBUG: name = flip last_ts = 508.622070 last_received_ts = 508.621613 last_seq = 1040 current_ts = 508.638733 current_received_ts = 508.638153 current_seq = 1041 count = 340 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 30us (kms_flip:7897) DEBUG: name = flip last_ts = 508.638733 last_received_ts = 508.638153 last_seq = 1041 current_ts = 508.655396 current_received_ts = 508.654785 current_seq = 1042 count = 341 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 89us (kms_flip:7897) DEBUG: name = flip last_ts = 508.655396 last_received_ts = 508.654785 last_seq = 1042 current_ts = 508.672058 current_received_ts = 508.671295 current_seq = 1043 count = 342 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 97us (kms_flip:7897) DEBUG: name = flip last_ts = 508.672058 last_received_ts = 508.671295 last_seq = 1043 current_ts = 508.688721 current_received_ts = 508.687927 current_seq = 1044 count = 343 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 124us (kms_flip:7897) DEBUG: name = flip last_ts = 508.688721 last_received_ts = 508.687927 last_seq = 1044 current_ts = 508.705383 current_received_ts = 508.704590 current_seq = 1045 count = 344 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 90us (kms_flip:7897) DEBUG: name = flip last_ts = 508.705383 last_received_ts = 508.704590 last_seq = 1045 current_ts = 508.722046 current_received_ts = 508.721222 current_seq = 1046 count = 345 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 39us (kms_flip:7897) DEBUG: name = flip last_ts = 508.722046 last_received_ts = 508.721222 last_seq = 1046 current_ts = 508.738708 current_received_ts = 508.737915 current_seq = 1047 count = 346 seq_step = 1 (kms_flip:7897) DEBUG: Vblank took 541us (kms_flip:7897) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:7897) CRITICAL: Failed assertion: end - start < 500 (kms_flip:7897) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:7897) igt_core-INFO: Stack trace: (kms_flip:7897) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:7897) igt_core-INFO: #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() (kms_flip:7897) igt_core-INFO: #2 ../tests/kms_flip.c:1891 run_test() (kms_flip:7897) igt_core-INFO: #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047() (kms_flip:7897) igt_core-INFO: #4 ../tests/kms_flip.c:2047 main() (kms_flip:7897) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:7897) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:7897) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (7.030s)
Dmesg	<6> [501.773294] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [501.777295] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431] <7> [501.779020] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [501.786209] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [501.786541] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [501.786737] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [501.856106] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [501.856254] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [501.856410] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [501.856537] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [501.856654] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [501.856766] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [501.856879] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [501.856987] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [501.857091] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [501.857209] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [501.857314] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [501.857420] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [501.857528] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [501.857636] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [501.857744] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [501.857854] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [501.857959] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [501.858064] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [501.858178] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [501.858285] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [501.858389] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [501.858491] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [501.858593] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [501.858696] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [501.858799] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [501.858903] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [501.859010] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [501.859118] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [501.859234] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [501.859347] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [501.859452] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [501.859555] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [501.859660] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [501.859763] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [501.859866] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [501.859970] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [501.860073] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [501.860547] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [501.860663] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [501.860771] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [501.860879] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [501.861043] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [501.861132] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [501.861247] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [501.861349] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [501.861469] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [501.861579] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [501.861688] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [501.861824] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [501.861941] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [501.862055] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [501.862178] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [501.862298] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [501.862409] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [501.862519] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [501.862693] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [501.862811] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [501.863063] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [501.863185] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [502.072265] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [502.073036] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [502.094038] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [502.094591] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [502.095049] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [502.147324] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [502.147952] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [502.155814] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [502.156301] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [502.156336] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [502.157938] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [502.158556] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [502.159260] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [502.159722] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [502.160187] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [502.160604] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [502.161021] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [502.161459] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [502.161874] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [502.162303] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [502.162717] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [502.163135] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [502.163564] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [502.163945] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [502.164319] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [502.164679] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [502.165164] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [502.165510] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [502.165842] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [502.166448] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [502.166933] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [502.167543] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [502.167945] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [502.168438] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [502.168749] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [502.169767] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [502.170310] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [502.170690] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [502.170774] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [502.171010] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [502.171422] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [502.171712] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [502.172012] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [502.172305] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [502.172580] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [502.172837] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [502.173074] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [502.173335] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [502.173572] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [502.173804] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [502.174022] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [502.174253] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [502.174471] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [502.174674] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [502.174862] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [502.175042] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [502.175234] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [502.175411] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [502.175577] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [502.175741] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [502.175903] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [502.176056] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [502.176216] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [502.176373] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [502.176526] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [502.176677] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [502.176825] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [502.176977] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [502.177127] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [502.177280] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [502.177448] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [502.177581] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [502.177704] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [502.177833] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [502.177954] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [502.178072] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [502.178189] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [502.178302] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [502.178413] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [502.178518] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [502.178625] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [502.178736] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [502.178857] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [502.179100] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [502.179310] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [502.179475] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [502.179576] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:264:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [502.179668] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [502.179740] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [502.179813] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [502.179883] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [502.179986] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [502.180108] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [502.180231] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [502.180346] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [502.180454] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [502.180561] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [502.180672] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [502.180813] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [502.180933] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [502.181048] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [502.181198] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [502.181316] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [502.181434] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [502.181553] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [502.181668] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [502.181781] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [502.181889] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [502.181997] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [502.182105] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [502.182220] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [502.182334] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [502.182451] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [502.182565] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [502.182679] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [502.182795] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [502.182914] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [502.183027] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [502.183139] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [502.183197] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [502.183264] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [502.183306] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [502.183372] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [502.183408] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [502.183480] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [502.183508] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [502.183589] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [502.183698] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [502.183806] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [502.183915] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [502.184025] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [502.184135] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [502.184282] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [502.184401] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [502.184517] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [502.184638] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [502.184755] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [502.184873] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855 <7> [502.184986] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [502.185094] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [502.185216] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [502.185335] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [502.185445] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [502.185555] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [502.185663] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [502.185771] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [502.185880] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [502.185992] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [502.186103] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [502.186223] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [502.186340] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [502.186453] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [502.186563] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [502.186673] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [502.186782] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [502.186890] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [502.186998] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [502.187107] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [502.187223] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [502.187337] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [502.187449] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [502.187560] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [502.187671] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [502.187784] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [502.187894] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [502.188005] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:431] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [502.188120] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [502.188246] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [502.188248] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [502.188361] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [502.188384] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [502.188469] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [502.188494] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [502.188578] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [502.188631] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [502.188689] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [502.188799] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [502.189307] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [502.189424] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [502.189682] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [502.189839] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [502.189985] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [502.190148] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [502.190275] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [502.190401] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [502.190513] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [502.190630] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [502.190724] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [502.190811] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [502.190895] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [502.190979] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [502.191062] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [502.191151] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [502.191234] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [502.191315] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [502.191396] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [502.191475] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [502.191553] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [502.191631] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [502.191733] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [502.191917] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [502.191998] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [502.192122] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [502.193196] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [502.193296] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [502.195222] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [502.195324] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (461 ms remaining) <7> [502.664268] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [502.685359] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [502.686200] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [502.686929] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [502.722628] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [502.723016] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [502.723329] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [502.723689] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [502.896086] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [502.897221] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [502.898036] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [502.901200] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [502.903144] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [502.904616] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [502.906542] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [502.908568] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [502.910367] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [502.911237] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [502.913328] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [502.913892] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [502.914984] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [502.915816] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [502.916401] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [502.916995] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 192000 <7> [502.932610] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [502.934797] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [502.935457] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <7> [505.472004] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off <7> [505.472324] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [508.748812] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [508.749128] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [508.749352] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [508.804424] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

7.03 seconds

Hostname

shard-lnl-1

Igt-Version

IGT-Version: 2.3-ga7015a99f (x86_64) (Linux: 7.0.0-rc4-lgci-xe-xe-4757-166a38809296432cd-debug+ x86_64)

Out

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

Err

Starting dynamic subtest: B-eDP1
(kms_flip:7897) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:7897) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7897) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.722260
last_received_ts = 506.721649
last_seq = 926
current_ts = 506.738922
current_received_ts = 506.738464
current_seq = 927
count = 226
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.738922
last_received_ts = 506.738464
last_seq = 927
current_ts = 506.755585
current_received_ts = 506.755127
current_seq = 928
count = 227
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.755585
last_received_ts = 506.755127
last_seq = 928
current_ts = 506.772247
current_received_ts = 506.771790
current_seq = 929
count = 228
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 31us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.772247
last_received_ts = 506.771790
last_seq = 929
current_ts = 506.788910
current_received_ts = 506.788483
current_seq = 930
count = 229
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 30us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.788910
last_received_ts = 506.788483
last_seq = 930
current_ts = 506.805573
current_received_ts = 506.805115
current_seq = 931
count = 230
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.805573
last_received_ts = 506.805115
last_seq = 931
current_ts = 506.822235
current_received_ts = 506.821777
current_seq = 932
count = 231
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.822235
last_received_ts = 506.821777
last_seq = 932
current_ts = 506.838898
current_received_ts = 506.838470
current_seq = 933
count = 232
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 34us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.838898
last_received_ts = 506.838470
last_seq = 933
current_ts = 506.855591
current_received_ts = 506.855103
current_seq = 934
count = 233
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 30us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.855591
last_received_ts = 506.855103
last_seq = 934
current_ts = 506.872253
current_received_ts = 506.871643
current_seq = 935
count = 234
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.872253
last_received_ts = 506.871643
last_seq = 935
current_ts = 506.888916
current_received_ts = 506.888458
current_seq = 936
count = 235
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.888916
last_received_ts = 506.888458
last_seq = 936
current_ts = 506.905579
current_received_ts = 506.905121
current_seq = 937
count = 236
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 30us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.905579
last_received_ts = 506.905121
last_seq = 937
current_ts = 506.922241
current_received_ts = 506.921783
current_seq = 938
count = 237
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.922241
last_received_ts = 506.921783
last_seq = 938
current_ts = 506.938904
current_received_ts = 506.938477
current_seq = 939
count = 238
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 88us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.938904
last_received_ts = 506.938477
last_seq = 939
current_ts = 506.955566
current_received_ts = 506.955139
current_seq = 940
count = 239
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.955566
last_received_ts = 506.955139
last_seq = 940
current_ts = 506.972229
current_received_ts = 506.971680
current_seq = 941
count = 240
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 34us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.972229
last_received_ts = 506.971680
last_seq = 941
current_ts = 506.988892
current_received_ts = 506.988464
current_seq = 942
count = 241
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 506.988892
last_received_ts = 506.988464
last_seq = 942
current_ts = 507.005554
current_received_ts = 507.004944
current_seq = 943
count = 242
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.005554
last_received_ts = 507.004944
last_seq = 943
current_ts = 507.022217
current_received_ts = 507.021484
current_seq = 944
count = 243
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 108us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.022217
last_received_ts = 507.021484
last_seq = 944
current_ts = 507.038910
current_received_ts = 507.038116
current_seq = 945
count = 244
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 44us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.038910
last_received_ts = 507.038116
last_seq = 945
current_ts = 507.055573
current_received_ts = 507.055084
current_seq = 946
count = 245
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 30us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.055573
last_received_ts = 507.055084
last_seq = 946
current_ts = 507.072205
current_received_ts = 507.071808
current_seq = 947
count = 246
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 29us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.072205
last_received_ts = 507.071808
last_seq = 947
current_ts = 507.088898
current_received_ts = 507.088440
current_seq = 948
count = 247
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.088898
last_received_ts = 507.088440
last_seq = 948
current_ts = 507.105560
current_received_ts = 507.105072
current_seq = 949
count = 248
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 30us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.105560
last_received_ts = 507.105072
last_seq = 949
current_ts = 507.122223
current_received_ts = 507.121582
current_seq = 950
count = 249
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.122223
last_received_ts = 507.121582
last_seq = 950
current_ts = 507.138885
current_received_ts = 507.138458
current_seq = 951
count = 250
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 99us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.138885
last_received_ts = 507.138458
last_seq = 951
current_ts = 507.155548
current_received_ts = 507.155090
current_seq = 952
count = 251
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 31us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.155548
last_received_ts = 507.155090
last_seq = 952
current_ts = 507.172211
current_received_ts = 507.171783
current_seq = 953
count = 252
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.172211
last_received_ts = 507.171783
last_seq = 953
current_ts = 507.188873
current_received_ts = 507.188446
current_seq = 954
count = 253
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 35us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.188873
last_received_ts = 507.188446
last_seq = 954
current_ts = 507.205536
current_received_ts = 507.205078
current_seq = 955
count = 254
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 34us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.205536
last_received_ts = 507.205078
last_seq = 955
current_ts = 507.222198
current_received_ts = 507.221619
current_seq = 956
count = 255
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.222198
last_received_ts = 507.221619
last_seq = 956
current_ts = 507.238861
current_received_ts = 507.238403
current_seq = 957
count = 256
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 119us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.238861
last_received_ts = 507.238403
last_seq = 957
current_ts = 507.255524
current_received_ts = 507.254791
current_seq = 958
count = 257
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 148us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.255524
last_received_ts = 507.254791
last_seq = 958
current_ts = 507.272186
current_received_ts = 507.271423
current_seq = 959
count = 258
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 60us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.272186
last_received_ts = 507.271423
last_seq = 959
current_ts = 507.288879
current_received_ts = 507.288452
current_seq = 960
count = 259
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 35us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.288879
last_received_ts = 507.288452
last_seq = 960
current_ts = 507.305511
current_received_ts = 507.305084
current_seq = 961
count = 260
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.305511
last_received_ts = 507.305084
last_seq = 961
current_ts = 507.322205
current_received_ts = 507.321503
current_seq = 962
count = 261
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 36us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.322205
last_received_ts = 507.321503
last_seq = 962
current_ts = 507.338867
current_received_ts = 507.338440
current_seq = 963
count = 262
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 35us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.338867
last_received_ts = 507.338440
last_seq = 963
current_ts = 507.355530
current_received_ts = 507.355072
current_seq = 964
count = 263
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.355530
last_received_ts = 507.355072
last_seq = 964
current_ts = 507.372192
current_received_ts = 507.371735
current_seq = 965
count = 264
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 35us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.372192
last_received_ts = 507.371735
last_seq = 965
current_ts = 507.388855
current_received_ts = 507.388458
current_seq = 966
count = 265
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 35us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.388855
last_received_ts = 507.388458
last_seq = 966
current_ts = 507.405518
current_received_ts = 507.405060
current_seq = 967
count = 266
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.405518
last_received_ts = 507.405060
last_seq = 967
current_ts = 507.422180
current_received_ts = 507.421509
current_seq = 968
count = 267
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 31us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.422180
last_received_ts = 507.421509
last_seq = 968
current_ts = 507.438843
current_received_ts = 507.438416
current_seq = 969
count = 268
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.438843
last_received_ts = 507.438416
last_seq = 969
current_ts = 507.455505
current_received_ts = 507.455078
current_seq = 970
count = 269
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.455505
last_received_ts = 507.455078
last_seq = 970
current_ts = 507.472168
current_received_ts = 507.471771
current_seq = 971
count = 270
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.472168
last_received_ts = 507.471771
last_seq = 971
current_ts = 507.488861
current_received_ts = 507.488434
current_seq = 972
count = 271
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.488861
last_received_ts = 507.488434
last_seq = 972
current_ts = 507.505524
current_received_ts = 507.504913
current_seq = 973
count = 272
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 90us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.505524
last_received_ts = 507.504913
last_seq = 973
current_ts = 507.522186
current_received_ts = 507.521667
current_seq = 974
count = 273
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 88us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.522186
last_received_ts = 507.521667
last_seq = 974
current_ts = 507.538849
current_received_ts = 507.538391
current_seq = 975
count = 274
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 29us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.538849
last_received_ts = 507.538391
last_seq = 975
current_ts = 507.555511
current_received_ts = 507.555054
current_seq = 976
count = 275
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.555511
last_received_ts = 507.555054
last_seq = 976
current_ts = 507.572174
current_received_ts = 507.571747
current_seq = 977
count = 276
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.572174
last_received_ts = 507.571747
last_seq = 977
current_ts = 507.588837
current_received_ts = 507.588409
current_seq = 978
count = 277
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 91us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.588837
last_received_ts = 507.588409
last_seq = 978
current_ts = 507.605499
current_received_ts = 507.605042
current_seq = 979
count = 278
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.605499
last_received_ts = 507.605042
last_seq = 979
current_ts = 507.622162
current_received_ts = 507.621521
current_seq = 980
count = 279
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.622162
last_received_ts = 507.621521
last_seq = 980
current_ts = 507.638824
current_received_ts = 507.638397
current_seq = 981
count = 280
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 34us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.638824
last_received_ts = 507.638397
last_seq = 981
current_ts = 507.655487
current_received_ts = 507.655060
current_seq = 982
count = 281
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.655487
last_received_ts = 507.655060
last_seq = 982
current_ts = 507.672150
current_received_ts = 507.671478
current_seq = 983
count = 282
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 86us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.672150
last_received_ts = 507.671478
last_seq = 983
current_ts = 507.688843
current_received_ts = 507.688385
current_seq = 984
count = 283
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 29us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.688843
last_received_ts = 507.688385
last_seq = 984
current_ts = 507.705505
current_received_ts = 507.705048
current_seq = 985
count = 284
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 30us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.705505
last_received_ts = 507.705048
last_seq = 985
current_ts = 507.722137
current_received_ts = 507.721497
current_seq = 986
count = 285
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 88us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.722137
last_received_ts = 507.721497
last_seq = 986
current_ts = 507.738831
current_received_ts = 507.738373
current_seq = 987
count = 286
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 30us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.738831
last_received_ts = 507.738373
last_seq = 987
current_ts = 507.755493
current_received_ts = 507.755066
current_seq = 988
count = 287
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 91us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.755493
last_received_ts = 507.755066
last_seq = 988
current_ts = 507.772156
current_received_ts = 507.771698
current_seq = 989
count = 288
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 87us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.772156
last_received_ts = 507.771698
last_seq = 989
current_ts = 507.788818
current_received_ts = 507.788361
current_seq = 990
count = 289
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 31us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.788818
last_received_ts = 507.788361
last_seq = 990
current_ts = 507.805481
current_received_ts = 507.805054
current_seq = 991
count = 290
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 34us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.805481
last_received_ts = 507.805054
last_seq = 991
current_ts = 507.822144
current_received_ts = 507.821533
current_seq = 992
count = 291
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 105us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.822144
last_received_ts = 507.821533
last_seq = 992
current_ts = 507.838806
current_received_ts = 507.838348
current_seq = 993
count = 292
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 36us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.838806
last_received_ts = 507.838348
last_seq = 993
current_ts = 507.855469
current_received_ts = 507.855042
current_seq = 994
count = 293
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 34us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.855469
last_received_ts = 507.855042
last_seq = 994
current_ts = 507.872131
current_received_ts = 507.871490
current_seq = 995
count = 294
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 37us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.872131
last_received_ts = 507.871490
last_seq = 995
current_ts = 507.888794
current_received_ts = 507.888367
current_seq = 996
count = 295
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 86us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.888794
last_received_ts = 507.888367
last_seq = 996
current_ts = 507.905487
current_received_ts = 507.904999
current_seq = 997
count = 296
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 48us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.905487
last_received_ts = 507.904999
last_seq = 997
current_ts = 507.922150
current_received_ts = 507.921722
current_seq = 998
count = 297
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 114us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.922150
last_received_ts = 507.921722
last_seq = 998
current_ts = 507.938812
current_received_ts = 507.938354
current_seq = 999
count = 298
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 31us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.938812
last_received_ts = 507.938354
last_seq = 999
current_ts = 507.955475
current_received_ts = 507.955048
current_seq = 1000
count = 299
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.955475
last_received_ts = 507.955048
last_seq = 1000
current_ts = 507.972137
current_received_ts = 507.971466
current_seq = 1001
count = 300
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 116us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.972137
last_received_ts = 507.971466
last_seq = 1001
current_ts = 507.988800
current_received_ts = 507.988373
current_seq = 1002
count = 301
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 110us
(kms_flip:7897) DEBUG: name = flip
last_ts = 507.988800
last_received_ts = 507.988373
last_seq = 1002
current_ts = 508.005463
current_received_ts = 508.005035
current_seq = 1003
count = 302
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.005463
last_received_ts = 508.005035
last_seq = 1003
current_ts = 508.022125
current_received_ts = 508.021698
current_seq = 1004
count = 303
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 92us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.022125
last_received_ts = 508.021698
last_seq = 1004
current_ts = 508.038788
current_received_ts = 508.038361
current_seq = 1005
count = 304
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 113us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.038788
last_received_ts = 508.038361
last_seq = 1005
current_ts = 508.055450
current_received_ts = 508.055054
current_seq = 1006
count = 305
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.055450
last_received_ts = 508.055054
last_seq = 1006
current_ts = 508.072113
current_received_ts = 508.071503
current_seq = 1007
count = 306
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 38us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.072113
last_received_ts = 508.071503
last_seq = 1007
current_ts = 508.088776
current_received_ts = 508.088226
current_seq = 1008
count = 307
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.088776
last_received_ts = 508.088226
last_seq = 1008
current_ts = 508.105438
current_received_ts = 508.105011
current_seq = 1009
count = 308
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 31us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.105438
last_received_ts = 508.105011
last_seq = 1009
current_ts = 508.122101
current_received_ts = 508.121338
current_seq = 1010
count = 309
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 43us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.122101
last_received_ts = 508.121338
last_seq = 1010
current_ts = 508.138794
current_received_ts = 508.138306
current_seq = 1011
count = 310
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 34us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.138794
last_received_ts = 508.138306
last_seq = 1011
current_ts = 508.155457
current_received_ts = 508.155060
current_seq = 1012
count = 311
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 31us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.155457
last_received_ts = 508.155060
last_seq = 1012
current_ts = 508.172119
current_received_ts = 508.171692
current_seq = 1013
count = 312
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.172119
last_received_ts = 508.171692
last_seq = 1013
current_ts = 508.188782
current_received_ts = 508.188324
current_seq = 1014
count = 313
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 114us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.188782
last_received_ts = 508.188324
last_seq = 1014
current_ts = 508.205444
current_received_ts = 508.205048
current_seq = 1015
count = 314
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 90us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.205444
last_received_ts = 508.205048
last_seq = 1015
current_ts = 508.222107
current_received_ts = 508.221710
current_seq = 1016
count = 315
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 86us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.222107
last_received_ts = 508.221710
last_seq = 1016
current_ts = 508.238770
current_received_ts = 508.238220
current_seq = 1017
count = 316
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.238770
last_received_ts = 508.238220
last_seq = 1017
current_ts = 508.255432
current_received_ts = 508.255005
current_seq = 1018
count = 317
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 88us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.255432
last_received_ts = 508.255005
last_seq = 1018
current_ts = 508.272095
current_received_ts = 508.271667
current_seq = 1019
count = 318
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 93us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.272095
last_received_ts = 508.271667
last_seq = 1019
current_ts = 508.288757
current_received_ts = 508.288147
current_seq = 1020
count = 319
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 30us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.288757
last_received_ts = 508.288147
last_seq = 1020
current_ts = 508.305420
current_received_ts = 508.305023
current_seq = 1021
count = 320
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 33us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.305420
last_received_ts = 508.305023
last_seq = 1021
current_ts = 508.322083
current_received_ts = 508.321533
current_seq = 1022
count = 321
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 87us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.322083
last_received_ts = 508.321533
last_seq = 1022
current_ts = 508.338745
current_received_ts = 508.338287
current_seq = 1023
count = 322
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 91us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.338745
last_received_ts = 508.338287
last_seq = 1023
current_ts = 508.355438
current_received_ts = 508.354980
current_seq = 1024
count = 323
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 42us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.355438
last_received_ts = 508.354980
last_seq = 1024
current_ts = 508.372101
current_received_ts = 508.371490
current_seq = 1025
count = 324
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 93us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.372101
last_received_ts = 508.371490
last_seq = 1025
current_ts = 508.388763
current_received_ts = 508.388214
current_seq = 1026
count = 325
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 31us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.388763
last_received_ts = 508.388214
last_seq = 1026
current_ts = 508.405426
current_received_ts = 508.404968
current_seq = 1027
count = 326
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 37us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.405426
last_received_ts = 508.404968
last_seq = 1027
current_ts = 508.422089
current_received_ts = 508.421661
current_seq = 1028
count = 327
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 104us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.422089
last_received_ts = 508.421661
last_seq = 1028
current_ts = 508.438751
current_received_ts = 508.438293
current_seq = 1029
count = 328
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 30us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.438751
last_received_ts = 508.438293
last_seq = 1029
current_ts = 508.455414
current_received_ts = 508.454956
current_seq = 1030
count = 329
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 43us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.455414
last_received_ts = 508.454956
last_seq = 1030
current_ts = 508.472076
current_received_ts = 508.471466
current_seq = 1031
count = 330
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 96us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.472076
last_received_ts = 508.471466
last_seq = 1031
current_ts = 508.488739
current_received_ts = 508.488190
current_seq = 1032
count = 331
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 30us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.488739
last_received_ts = 508.488190
last_seq = 1032
current_ts = 508.505402
current_received_ts = 508.504791
current_seq = 1033
count = 332
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 93us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.505402
last_received_ts = 508.504791
last_seq = 1033
current_ts = 508.522064
current_received_ts = 508.521301
current_seq = 1034
count = 333
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 44us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.522064
last_received_ts = 508.521301
last_seq = 1034
current_ts = 508.538727
current_received_ts = 508.537994
current_seq = 1035
count = 334
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 92us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.538727
last_received_ts = 508.537994
last_seq = 1035
current_ts = 508.555420
current_received_ts = 508.554962
current_seq = 1036
count = 335
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 54us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.555420
last_received_ts = 508.554962
last_seq = 1036
current_ts = 508.572083
current_received_ts = 508.571625
current_seq = 1037
count = 336
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 94us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.572083
last_received_ts = 508.571625
last_seq = 1037
current_ts = 508.588745
current_received_ts = 508.588287
current_seq = 1038
count = 337
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 32us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.588745
last_received_ts = 508.588287
last_seq = 1038
current_ts = 508.605408
current_received_ts = 508.604950
current_seq = 1039
count = 338
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 100us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.605408
last_received_ts = 508.604950
last_seq = 1039
current_ts = 508.622070
current_received_ts = 508.621613
current_seq = 1040
count = 339
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 91us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.622070
last_received_ts = 508.621613
last_seq = 1040
current_ts = 508.638733
current_received_ts = 508.638153
current_seq = 1041
count = 340
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 30us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.638733
last_received_ts = 508.638153
last_seq = 1041
current_ts = 508.655396
current_received_ts = 508.654785
current_seq = 1042
count = 341
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 89us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.655396
last_received_ts = 508.654785
last_seq = 1042
current_ts = 508.672058
current_received_ts = 508.671295
current_seq = 1043
count = 342
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 97us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.672058
last_received_ts = 508.671295
last_seq = 1043
current_ts = 508.688721
current_received_ts = 508.687927
current_seq = 1044
count = 343
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 124us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.688721
last_received_ts = 508.687927
last_seq = 1044
current_ts = 508.705383
current_received_ts = 508.704590
current_seq = 1045
count = 344
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 90us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.705383
last_received_ts = 508.704590
last_seq = 1045
current_ts = 508.722046
current_received_ts = 508.721222
current_seq = 1046
count = 345
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 39us
(kms_flip:7897) DEBUG: name = flip
last_ts = 508.722046
last_received_ts = 508.721222
last_seq = 1046
current_ts = 508.738708
current_received_ts = 508.737915
current_seq = 1047
count = 346
seq_step = 1
(kms_flip:7897) DEBUG: Vblank took 541us
(kms_flip:7897) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:7897) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7897) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:7897) igt_core-INFO: Stack trace:
(kms_flip:7897) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:7897) igt_core-INFO:   #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0()
(kms_flip:7897) igt_core-INFO:   #2 ../tests/kms_flip.c:1891 run_test()
(kms_flip:7897) igt_core-INFO:   #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047()
(kms_flip:7897) igt_core-INFO:   #4 ../tests/kms_flip.c:2047 main()
(kms_flip:7897) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7897) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7897) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (7.030s)

Dmesg

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [502.182795] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [502.184873] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [502.188631] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on

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

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

<7> [502.189307] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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