igt@kms_flip@flip-vs-expired-vblank@b-edp1 on shard-lnl@xe-4702-4f823cb4f9faf6611f35c6a8a71ab696e3a734d6 Test details

Detail	Value
Duration	8.70 seconds
Hostname	shard-lnl-2
Igt-Version	IGT-Version: 2.3-gd91dcaa22 (x86_64) (Linux: 7.0.0-rc3-lgci-xe-xe-4702-4f823cb4f9faf6611-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:921 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1887 run_test() #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043() #4 ../tests/kms_flip.c:2043 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (8.699s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:2562) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2562) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:2562) DEBUG: name = flip last_ts = 127.831413 last_received_ts = 127.830872 last_seq = 945 current_ts = 127.848076 current_received_ts = 127.847519 current_seq = 946 count = 320 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 98us (kms_flip:2562) DEBUG: name = flip last_ts = 127.848076 last_received_ts = 127.847519 last_seq = 946 current_ts = 127.864738 current_received_ts = 127.864189 current_seq = 947 count = 321 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 85us (kms_flip:2562) DEBUG: name = flip last_ts = 127.864738 last_received_ts = 127.864189 last_seq = 947 current_ts = 127.881409 current_received_ts = 127.880852 current_seq = 948 count = 322 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 184us (kms_flip:2562) DEBUG: name = flip last_ts = 127.881409 last_received_ts = 127.880852 last_seq = 948 current_ts = 127.898071 current_received_ts = 127.897499 current_seq = 949 count = 323 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 98us (kms_flip:2562) DEBUG: name = flip last_ts = 127.898071 last_received_ts = 127.897499 last_seq = 949 current_ts = 127.914734 current_received_ts = 127.914192 current_seq = 950 count = 324 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 98us (kms_flip:2562) DEBUG: name = flip last_ts = 127.914734 last_received_ts = 127.914192 last_seq = 950 current_ts = 127.931396 current_received_ts = 127.930878 current_seq = 951 count = 325 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 95us (kms_flip:2562) DEBUG: name = flip last_ts = 127.931396 last_received_ts = 127.930878 last_seq = 951 current_ts = 127.948067 current_received_ts = 127.947517 current_seq = 952 count = 326 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 127.948067 last_received_ts = 127.947517 last_seq = 952 current_ts = 127.964729 current_received_ts = 127.964211 current_seq = 953 count = 327 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 98us (kms_flip:2562) DEBUG: name = flip last_ts = 127.964729 last_received_ts = 127.964211 last_seq = 953 current_ts = 127.981392 current_received_ts = 127.980865 current_seq = 954 count = 328 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 85us (kms_flip:2562) DEBUG: name = flip last_ts = 127.981392 last_received_ts = 127.980865 last_seq = 954 current_ts = 127.998055 current_received_ts = 127.997520 current_seq = 955 count = 329 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 95us (kms_flip:2562) DEBUG: name = flip last_ts = 127.998055 last_received_ts = 127.997520 last_seq = 955 current_ts = 128.014725 current_received_ts = 128.014191 current_seq = 956 count = 330 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 86us (kms_flip:2562) DEBUG: name = flip last_ts = 128.014725 last_received_ts = 128.014191 last_seq = 956 current_ts = 128.031387 current_received_ts = 128.030853 current_seq = 957 count = 331 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 128.031387 last_received_ts = 128.030853 last_seq = 957 current_ts = 128.048050 current_received_ts = 128.047501 current_seq = 958 count = 332 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 131us (kms_flip:2562) DEBUG: name = flip last_ts = 128.048050 last_received_ts = 128.047501 last_seq = 958 current_ts = 128.064713 current_received_ts = 128.064178 current_seq = 959 count = 333 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 93us (kms_flip:2562) DEBUG: name = flip last_ts = 128.064713 last_received_ts = 128.064178 last_seq = 959 current_ts = 128.081390 current_received_ts = 128.080841 current_seq = 960 count = 334 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 96us (kms_flip:2562) DEBUG: name = flip last_ts = 128.081390 last_received_ts = 128.080841 last_seq = 960 current_ts = 128.098053 current_received_ts = 128.097504 current_seq = 961 count = 335 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 86us (kms_flip:2562) DEBUG: name = flip last_ts = 128.098053 last_received_ts = 128.097504 last_seq = 961 current_ts = 128.114716 current_received_ts = 128.114182 current_seq = 962 count = 336 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 128.114716 last_received_ts = 128.114182 last_seq = 962 current_ts = 128.131378 current_received_ts = 128.130844 current_seq = 963 count = 337 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 98us (kms_flip:2562) DEBUG: name = flip last_ts = 128.131378 last_received_ts = 128.130844 last_seq = 963 current_ts = 128.148041 current_received_ts = 128.147507 current_seq = 964 count = 338 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 128.148041 last_received_ts = 128.147507 last_seq = 964 current_ts = 128.164703 current_received_ts = 128.164185 current_seq = 965 count = 339 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 99us (kms_flip:2562) DEBUG: name = flip last_ts = 128.164703 last_received_ts = 128.164185 last_seq = 965 current_ts = 128.181381 current_received_ts = 128.180832 current_seq = 966 count = 340 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 86us (kms_flip:2562) DEBUG: name = flip last_ts = 128.181381 last_received_ts = 128.180832 last_seq = 966 current_ts = 128.198029 current_received_ts = 128.197510 current_seq = 967 count = 341 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 150us (kms_flip:2562) DEBUG: name = flip last_ts = 128.198029 last_received_ts = 128.197510 last_seq = 967 current_ts = 128.214706 current_received_ts = 128.214172 current_seq = 968 count = 342 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 74us (kms_flip:2562) DEBUG: name = flip last_ts = 128.214706 last_received_ts = 128.214172 last_seq = 968 current_ts = 128.231369 current_received_ts = 128.230820 current_seq = 969 count = 343 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 99us (kms_flip:2562) DEBUG: name = flip last_ts = 128.231369 last_received_ts = 128.230820 last_seq = 969 current_ts = 128.248032 current_received_ts = 128.247498 current_seq = 970 count = 344 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 131us (kms_flip:2562) DEBUG: name = flip last_ts = 128.248032 last_received_ts = 128.247498 last_seq = 970 current_ts = 128.264694 current_received_ts = 128.264175 current_seq = 971 count = 345 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 128.264694 last_received_ts = 128.264175 last_seq = 971 current_ts = 128.281357 current_received_ts = 128.280853 current_seq = 972 count = 346 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 108us (kms_flip:2562) DEBUG: name = flip last_ts = 128.281357 last_received_ts = 128.280853 last_seq = 972 current_ts = 128.298019 current_received_ts = 128.297516 current_seq = 973 count = 347 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 128.298019 last_received_ts = 128.297516 last_seq = 973 current_ts = 128.314682 current_received_ts = 128.314163 current_seq = 974 count = 348 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 87us (kms_flip:2562) DEBUG: name = flip last_ts = 128.314682 last_received_ts = 128.314163 last_seq = 974 current_ts = 128.331360 current_received_ts = 128.330826 current_seq = 975 count = 349 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 85us (kms_flip:2562) DEBUG: name = flip last_ts = 128.331360 last_received_ts = 128.330826 last_seq = 975 current_ts = 128.348022 current_received_ts = 128.347473 current_seq = 976 count = 350 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 128.348022 last_received_ts = 128.347473 last_seq = 976 current_ts = 128.364685 current_received_ts = 128.364166 current_seq = 977 count = 351 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 128.364685 last_received_ts = 128.364166 last_seq = 977 current_ts = 128.381348 current_received_ts = 128.380814 current_seq = 978 count = 352 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 128.381348 last_received_ts = 128.380814 last_seq = 978 current_ts = 128.398010 current_received_ts = 128.397491 current_seq = 979 count = 353 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 148us (kms_flip:2562) DEBUG: name = flip last_ts = 128.398010 last_received_ts = 128.397491 last_seq = 979 current_ts = 128.414688 current_received_ts = 128.414169 current_seq = 980 count = 354 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 86us (kms_flip:2562) DEBUG: name = flip last_ts = 128.414688 last_received_ts = 128.414169 last_seq = 980 current_ts = 128.431335 current_received_ts = 128.430817 current_seq = 981 count = 355 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 86us (kms_flip:2562) DEBUG: name = flip last_ts = 128.431335 last_received_ts = 128.430817 last_seq = 981 current_ts = 128.448013 current_received_ts = 128.447479 current_seq = 982 count = 356 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 85us (kms_flip:2562) DEBUG: name = flip last_ts = 128.448013 last_received_ts = 128.447479 last_seq = 982 current_ts = 128.464676 current_received_ts = 128.464157 current_seq = 983 count = 357 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 98us (kms_flip:2562) DEBUG: name = flip last_ts = 128.464676 last_received_ts = 128.464157 last_seq = 983 current_ts = 128.481339 current_received_ts = 128.480804 current_seq = 984 count = 358 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 128.481339 last_received_ts = 128.480804 last_seq = 984 current_ts = 128.498001 current_received_ts = 128.497482 current_seq = 985 count = 359 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 151us (kms_flip:2562) DEBUG: name = flip last_ts = 128.498001 last_received_ts = 128.497482 last_seq = 985 current_ts = 128.514664 current_received_ts = 128.514145 current_seq = 986 count = 360 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 96us (kms_flip:2562) DEBUG: name = flip last_ts = 128.514664 last_received_ts = 128.514145 last_seq = 986 current_ts = 128.531342 current_received_ts = 128.530807 current_seq = 987 count = 361 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 92us (kms_flip:2562) DEBUG: name = flip last_ts = 128.531342 last_received_ts = 128.530807 last_seq = 987 current_ts = 128.547989 current_received_ts = 128.547424 current_seq = 988 count = 362 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 93us (kms_flip:2562) DEBUG: name = flip last_ts = 128.547989 last_received_ts = 128.547424 last_seq = 988 current_ts = 128.564667 current_received_ts = 128.564133 current_seq = 989 count = 363 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 93us (kms_flip:2562) DEBUG: name = flip last_ts = 128.564667 last_received_ts = 128.564133 last_seq = 989 current_ts = 128.581329 current_received_ts = 128.580780 current_seq = 990 count = 364 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 90us (kms_flip:2562) DEBUG: name = flip last_ts = 128.581329 last_received_ts = 128.580780 last_seq = 990 current_ts = 128.597992 current_received_ts = 128.597412 current_seq = 991 count = 365 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 46us (kms_flip:2562) DEBUG: name = flip last_ts = 128.597992 last_received_ts = 128.597412 last_seq = 991 current_ts = 128.614655 current_received_ts = 128.614029 current_seq = 992 count = 366 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 43us (kms_flip:2562) DEBUG: name = flip last_ts = 128.614655 last_received_ts = 128.614029 last_seq = 992 current_ts = 128.631317 current_received_ts = 128.630539 current_seq = 993 count = 367 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 49us (kms_flip:2562) DEBUG: name = flip last_ts = 128.631317 last_received_ts = 128.630539 last_seq = 993 current_ts = 128.647980 current_received_ts = 128.647156 current_seq = 994 count = 368 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 48us (kms_flip:2562) DEBUG: name = flip last_ts = 128.647980 last_received_ts = 128.647156 last_seq = 994 current_ts = 128.664642 current_received_ts = 128.663879 current_seq = 995 count = 369 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 70us (kms_flip:2562) DEBUG: name = flip last_ts = 128.664642 last_received_ts = 128.663879 last_seq = 995 current_ts = 128.681320 current_received_ts = 128.680618 current_seq = 996 count = 370 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 156us (kms_flip:2562) DEBUG: name = flip last_ts = 128.681320 last_received_ts = 128.680618 last_seq = 996 current_ts = 128.697983 current_received_ts = 128.697220 current_seq = 997 count = 371 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 69us (kms_flip:2562) DEBUG: name = flip last_ts = 128.697983 last_received_ts = 128.697220 last_seq = 997 current_ts = 128.714645 current_received_ts = 128.713913 current_seq = 998 count = 372 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 60us (kms_flip:2562) DEBUG: name = flip last_ts = 128.714645 last_received_ts = 128.713913 last_seq = 998 current_ts = 128.731308 current_received_ts = 128.730682 current_seq = 999 count = 373 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 115us (kms_flip:2562) DEBUG: name = flip last_ts = 128.731308 last_received_ts = 128.730682 last_seq = 999 current_ts = 128.747971 current_received_ts = 128.747299 current_seq = 1000 count = 374 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 117us (kms_flip:2562) DEBUG: name = flip last_ts = 128.747971 last_received_ts = 128.747299 last_seq = 1000 current_ts = 128.764633 current_received_ts = 128.764069 current_seq = 1001 count = 375 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 81us (kms_flip:2562) DEBUG: name = flip last_ts = 128.764633 last_received_ts = 128.764069 last_seq = 1001 current_ts = 128.781311 current_received_ts = 128.780670 current_seq = 1002 count = 376 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 89us (kms_flip:2562) DEBUG: name = flip last_ts = 128.781311 last_received_ts = 128.780670 last_seq = 1002 current_ts = 128.797974 current_received_ts = 128.797287 current_seq = 1003 count = 377 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 114us (kms_flip:2562) DEBUG: name = flip last_ts = 128.797974 last_received_ts = 128.797287 last_seq = 1003 current_ts = 128.814636 current_received_ts = 128.814087 current_seq = 1004 count = 378 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 80us (kms_flip:2562) DEBUG: name = flip last_ts = 128.814636 last_received_ts = 128.814087 last_seq = 1004 current_ts = 128.831299 current_received_ts = 128.830658 current_seq = 1005 count = 379 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 101us (kms_flip:2562) DEBUG: name = flip last_ts = 128.831299 last_received_ts = 128.830658 last_seq = 1005 current_ts = 128.847961 current_received_ts = 128.847366 current_seq = 1006 count = 380 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 86us (kms_flip:2562) DEBUG: name = flip last_ts = 128.847961 last_received_ts = 128.847366 last_seq = 1006 current_ts = 128.864624 current_received_ts = 128.863953 current_seq = 1007 count = 381 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 131us (kms_flip:2562) DEBUG: name = flip last_ts = 128.864624 last_received_ts = 128.863953 last_seq = 1007 current_ts = 128.881302 current_received_ts = 128.880753 current_seq = 1008 count = 382 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 91us (kms_flip:2562) DEBUG: name = flip last_ts = 128.881302 last_received_ts = 128.880753 last_seq = 1008 current_ts = 128.897964 current_received_ts = 128.897293 current_seq = 1009 count = 383 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 101us (kms_flip:2562) DEBUG: name = flip last_ts = 128.897964 last_received_ts = 128.897293 last_seq = 1009 current_ts = 128.914627 current_received_ts = 128.913971 current_seq = 1010 count = 384 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 95us (kms_flip:2562) DEBUG: name = flip last_ts = 128.914627 last_received_ts = 128.913971 last_seq = 1010 current_ts = 128.931290 current_received_ts = 128.930618 current_seq = 1011 count = 385 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 61us (kms_flip:2562) DEBUG: name = flip last_ts = 128.931290 last_received_ts = 128.930618 last_seq = 1011 current_ts = 128.947952 current_received_ts = 128.947266 current_seq = 1012 count = 386 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 57us (kms_flip:2562) DEBUG: name = flip last_ts = 128.947952 last_received_ts = 128.947266 last_seq = 1012 current_ts = 128.964615 current_received_ts = 128.964066 current_seq = 1013 count = 387 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 82us (kms_flip:2562) DEBUG: name = flip last_ts = 128.964615 last_received_ts = 128.964066 last_seq = 1013 current_ts = 128.981293 current_received_ts = 128.980621 current_seq = 1014 count = 388 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 106us (kms_flip:2562) DEBUG: name = flip last_ts = 128.981293 last_received_ts = 128.980621 last_seq = 1014 current_ts = 128.997940 current_received_ts = 128.997253 current_seq = 1015 count = 389 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 55us (kms_flip:2562) DEBUG: name = flip last_ts = 128.997940 last_received_ts = 128.997253 last_seq = 1015 current_ts = 129.014618 current_received_ts = 129.013962 current_seq = 1016 count = 390 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 116us (kms_flip:2562) DEBUG: name = flip last_ts = 129.014618 last_received_ts = 129.013962 last_seq = 1016 current_ts = 129.031281 current_received_ts = 129.030609 current_seq = 1017 count = 391 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 120us (kms_flip:2562) DEBUG: name = flip last_ts = 129.031281 last_received_ts = 129.030609 last_seq = 1017 current_ts = 129.047943 current_received_ts = 129.047424 current_seq = 1018 count = 392 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 72us (kms_flip:2562) DEBUG: name = flip last_ts = 129.047943 last_received_ts = 129.047424 last_seq = 1018 current_ts = 129.064606 current_received_ts = 129.063980 current_seq = 1019 count = 393 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 133us (kms_flip:2562) DEBUG: name = flip last_ts = 129.064606 last_received_ts = 129.063980 last_seq = 1019 current_ts = 129.081268 current_received_ts = 129.080612 current_seq = 1020 count = 394 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 59us (kms_flip:2562) DEBUG: name = flip last_ts = 129.081268 last_received_ts = 129.080612 last_seq = 1020 current_ts = 129.097946 current_received_ts = 129.097260 current_seq = 1021 count = 395 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 54us (kms_flip:2562) DEBUG: name = flip last_ts = 129.097946 last_received_ts = 129.097260 last_seq = 1021 current_ts = 129.114594 current_received_ts = 129.114044 current_seq = 1022 count = 396 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 79us (kms_flip:2562) DEBUG: name = flip last_ts = 129.114594 last_received_ts = 129.114044 last_seq = 1022 current_ts = 129.131271 current_received_ts = 129.130630 current_seq = 1023 count = 397 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 91us (kms_flip:2562) DEBUG: name = flip last_ts = 129.131271 last_received_ts = 129.130630 last_seq = 1023 current_ts = 129.147934 current_received_ts = 129.147278 current_seq = 1024 count = 398 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 114us (kms_flip:2562) DEBUG: name = flip last_ts = 129.147934 last_received_ts = 129.147278 last_seq = 1024 current_ts = 129.164597 current_received_ts = 129.164062 current_seq = 1025 count = 399 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 70us (kms_flip:2562) DEBUG: name = flip last_ts = 129.164597 last_received_ts = 129.164062 last_seq = 1025 current_ts = 129.181259 current_received_ts = 129.180618 current_seq = 1026 count = 400 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 94us (kms_flip:2562) DEBUG: name = flip last_ts = 129.181259 last_received_ts = 129.180618 last_seq = 1026 current_ts = 129.197922 current_received_ts = 129.197174 current_seq = 1027 count = 401 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 112us (kms_flip:2562) DEBUG: name = flip last_ts = 129.197922 last_received_ts = 129.197174 last_seq = 1027 current_ts = 129.214600 current_received_ts = 129.214066 current_seq = 1028 count = 402 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 81us (kms_flip:2562) DEBUG: name = flip last_ts = 129.214600 last_received_ts = 129.214066 last_seq = 1028 current_ts = 129.231247 current_received_ts = 129.230606 current_seq = 1029 count = 403 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 60us (kms_flip:2562) DEBUG: name = flip last_ts = 129.231247 last_received_ts = 129.230606 last_seq = 1029 current_ts = 129.247925 current_received_ts = 129.247223 current_seq = 1030 count = 404 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 50us (kms_flip:2562) DEBUG: name = flip last_ts = 129.247925 last_received_ts = 129.247223 last_seq = 1030 current_ts = 129.264587 current_received_ts = 129.263901 current_seq = 1031 count = 405 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 51us (kms_flip:2562) DEBUG: name = flip last_ts = 129.264587 last_received_ts = 129.263901 last_seq = 1031 current_ts = 129.281250 current_received_ts = 129.280624 current_seq = 1032 count = 406 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 98us (kms_flip:2562) DEBUG: name = flip last_ts = 129.281250 last_received_ts = 129.280624 last_seq = 1032 current_ts = 129.297913 current_received_ts = 129.297226 current_seq = 1033 count = 407 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 61us (kms_flip:2562) DEBUG: name = flip last_ts = 129.297913 last_received_ts = 129.297226 last_seq = 1033 current_ts = 129.314575 current_received_ts = 129.313919 current_seq = 1034 count = 408 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 51us (kms_flip:2562) DEBUG: name = flip last_ts = 129.314575 last_received_ts = 129.313919 last_seq = 1034 current_ts = 129.331238 current_received_ts = 129.330566 current_seq = 1035 count = 409 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 89us (kms_flip:2562) DEBUG: name = flip last_ts = 129.331238 last_received_ts = 129.330566 last_seq = 1035 current_ts = 129.347916 current_received_ts = 129.347229 current_seq = 1036 count = 410 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 114us (kms_flip:2562) DEBUG: name = flip last_ts = 129.347916 last_received_ts = 129.347229 last_seq = 1036 current_ts = 129.364563 current_received_ts = 129.363892 current_seq = 1037 count = 411 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 45us (kms_flip:2562) DEBUG: name = flip last_ts = 129.364563 last_received_ts = 129.363892 last_seq = 1037 current_ts = 129.381241 current_received_ts = 129.380569 current_seq = 1038 count = 412 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 45us (kms_flip:2562) DEBUG: name = flip last_ts = 129.381241 last_received_ts = 129.380569 last_seq = 1038 current_ts = 129.397903 current_received_ts = 129.397308 current_seq = 1039 count = 413 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 91us (kms_flip:2562) DEBUG: name = flip last_ts = 129.397903 last_received_ts = 129.397308 last_seq = 1039 current_ts = 129.414566 current_received_ts = 129.414001 current_seq = 1040 count = 414 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 63us (kms_flip:2562) DEBUG: name = flip last_ts = 129.414566 last_received_ts = 129.414001 last_seq = 1040 current_ts = 129.431229 current_received_ts = 129.430573 current_seq = 1041 count = 415 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 103us (kms_flip:2562) DEBUG: name = flip last_ts = 129.431229 last_received_ts = 129.430573 last_seq = 1041 current_ts = 129.447906 current_received_ts = 129.447205 current_seq = 1042 count = 416 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 110us (kms_flip:2562) DEBUG: name = flip last_ts = 129.447906 last_received_ts = 129.447205 last_seq = 1042 current_ts = 129.464554 current_received_ts = 129.463989 current_seq = 1043 count = 417 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 74us (kms_flip:2562) DEBUG: name = flip last_ts = 129.464554 last_received_ts = 129.463989 last_seq = 1043 current_ts = 129.481232 current_received_ts = 129.480621 current_seq = 1044 count = 418 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 105us (kms_flip:2562) DEBUG: name = flip last_ts = 129.481232 last_received_ts = 129.480621 last_seq = 1044 current_ts = 129.497894 current_received_ts = 129.497223 current_seq = 1045 count = 419 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 122us (kms_flip:2562) DEBUG: name = flip last_ts = 129.497894 last_received_ts = 129.497223 last_seq = 1045 current_ts = 129.514557 current_received_ts = 129.513992 current_seq = 1046 count = 420 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 80us (kms_flip:2562) DEBUG: name = flip last_ts = 129.514557 last_received_ts = 129.513992 last_seq = 1046 current_ts = 129.531219 current_received_ts = 129.530594 current_seq = 1047 count = 421 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 129.531219 last_received_ts = 129.530594 last_seq = 1047 current_ts = 129.547897 current_received_ts = 129.547241 current_seq = 1048 count = 422 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 61us (kms_flip:2562) DEBUG: name = flip last_ts = 129.547897 last_received_ts = 129.547241 last_seq = 1048 current_ts = 129.564545 current_received_ts = 129.563873 current_seq = 1049 count = 423 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 53us (kms_flip:2562) DEBUG: name = flip last_ts = 129.564545 last_received_ts = 129.563873 last_seq = 1049 current_ts = 129.581207 current_received_ts = 129.580582 current_seq = 1050 count = 424 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 100us (kms_flip:2562) DEBUG: name = flip last_ts = 129.581207 last_received_ts = 129.580582 last_seq = 1050 current_ts = 129.597885 current_received_ts = 129.597198 current_seq = 1051 count = 425 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 121us (kms_flip:2562) DEBUG: name = flip last_ts = 129.597885 last_received_ts = 129.597198 last_seq = 1051 current_ts = 129.614548 current_received_ts = 129.613892 current_seq = 1052 count = 426 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 147us (kms_flip:2562) DEBUG: name = flip last_ts = 129.614548 last_received_ts = 129.613892 last_seq = 1052 current_ts = 129.631210 current_received_ts = 129.630569 current_seq = 1053 count = 427 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 95us (kms_flip:2562) DEBUG: name = flip last_ts = 129.631210 last_received_ts = 129.630569 last_seq = 1053 current_ts = 129.647873 current_received_ts = 129.647217 current_seq = 1054 count = 428 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 105us (kms_flip:2562) DEBUG: name = flip last_ts = 129.647873 last_received_ts = 129.647217 last_seq = 1054 current_ts = 129.664536 current_received_ts = 129.663925 current_seq = 1055 count = 429 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 140us (kms_flip:2562) DEBUG: name = flip last_ts = 129.664536 last_received_ts = 129.663925 last_seq = 1055 current_ts = 129.681198 current_received_ts = 129.680557 current_seq = 1056 count = 430 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 79us (kms_flip:2562) DEBUG: name = flip last_ts = 129.681198 last_received_ts = 129.680557 last_seq = 1056 current_ts = 129.697861 current_received_ts = 129.697250 current_seq = 1057 count = 431 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 91us (kms_flip:2562) DEBUG: name = flip last_ts = 129.697861 last_received_ts = 129.697250 last_seq = 1057 current_ts = 129.714539 current_received_ts = 129.713898 current_seq = 1058 count = 432 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 106us (kms_flip:2562) DEBUG: name = flip last_ts = 129.714539 last_received_ts = 129.713898 last_seq = 1058 current_ts = 129.731201 current_received_ts = 129.730576 current_seq = 1059 count = 433 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 91us (kms_flip:2562) DEBUG: name = flip last_ts = 129.731201 last_received_ts = 129.730576 last_seq = 1059 current_ts = 129.747864 current_received_ts = 129.747208 current_seq = 1060 count = 434 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 46us (kms_flip:2562) DEBUG: name = flip last_ts = 129.747864 last_received_ts = 129.747208 last_seq = 1060 current_ts = 129.764526 current_received_ts = 129.763901 current_seq = 1061 count = 435 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 77us (kms_flip:2562) DEBUG: name = flip last_ts = 129.764526 last_received_ts = 129.763901 last_seq = 1061 current_ts = 129.781189 current_received_ts = 129.780655 current_seq = 1062 count = 436 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 83us (kms_flip:2562) DEBUG: name = flip last_ts = 129.781189 last_received_ts = 129.780655 last_seq = 1062 current_ts = 129.797867 current_received_ts = 129.797150 current_seq = 1063 count = 437 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 119us (kms_flip:2562) DEBUG: name = flip last_ts = 129.797867 last_received_ts = 129.797150 last_seq = 1063 current_ts = 129.814529 current_received_ts = 129.813965 current_seq = 1064 count = 438 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 102us (kms_flip:2562) DEBUG: name = flip last_ts = 129.814529 last_received_ts = 129.813965 last_seq = 1064 current_ts = 129.831192 current_received_ts = 129.830566 current_seq = 1065 count = 439 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 97us (kms_flip:2562) DEBUG: name = flip last_ts = 129.831192 last_received_ts = 129.830566 last_seq = 1065 current_ts = 129.847855 current_received_ts = 129.847198 current_seq = 1066 count = 440 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 105us (kms_flip:2562) DEBUG: name = flip last_ts = 129.847855 last_received_ts = 129.847198 last_seq = 1066 current_ts = 129.864517 current_received_ts = 129.863922 current_seq = 1067 count = 441 seq_step = 1 (kms_flip:2562) DEBUG: Vblank took 1116us (kms_flip:2562) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2562) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2562) igt_core-INFO: Stack trace: (kms_flip:2562) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2562) igt_core-INFO: #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0() (kms_flip:2562) igt_core-INFO: #2 ../tests/kms_flip.c:1887 run_test() (kms_flip:2562) igt_core-INFO: #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043() (kms_flip:2562) igt_core-INFO: #4 ../tests/kms_flip.c:2043 main() (kms_flip:2562) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2562) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2562) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (8.699s)
Dmesg	<6> [121.738399] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [121.762110] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [121.762249] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [121.762324] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430] <7> [121.762341] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [121.762677] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431] <7> [121.833530] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:150:pipe A] <7> [121.833778] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [121.834111] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [121.834366] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [121.834635] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [121.834857] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150: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> [121.835077] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [121.835284] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [121.835500] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [121.835697] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [121.835888] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [121.836099] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [121.836289] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [121.836473] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [121.836670] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [121.836850] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [121.837016] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [121.837172] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [121.837327] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [121.837536] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [121.837687] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [121.837833] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [121.837988] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [121.838159] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [121.838312] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [121.838498] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [121.838649] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [121.838788] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [121.838928] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [121.839062] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [121.839193] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [121.839323] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [121.839462] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [121.839587] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [121.839713] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [121.839840] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [121.839961] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [121.840080] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [121.840195] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [121.840311] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:150:pipe A] fastset requirement not met, forcing full modeset <7> [121.840433] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:150:pipe A] releasing DPLL 0 <7> [121.840612] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [121.840727] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:150:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [121.840871] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:144:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [121.840988] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:150:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [121.841138] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [121.841267] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [121.841384] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [121.841551] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:150:pipe A] enable: no [modeset] <7> [121.841666] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:34:plane 1A] fb: [NOFB], visible: no <7> [121.841779] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:64:plane 2A] fb: [NOFB], visible: no <7> [121.841891] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:94:plane 3A] fb: [NOFB], visible: no <7> [121.841999] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:124:plane 4A] fb: [NOFB], visible: no <7> [121.842102] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:134:plane 5A] fb: [NOFB], visible: no <7> [121.842206] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:144:cursor A] fb: [NOFB], visible: no <7> [121.842364] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [121.842504] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [121.842824] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [121.842975] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [122.046643] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:392:eDP-1] set backlight PWM = 0 <7> [122.047358] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [122.052988] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 turn panel power off <7> [122.053601] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 wait for panel power off time <7> [122.054110] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [122.105557] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [122.105950] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:150:pipe A] <7> [122.105970] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [122.106361] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:391:DDI A/PHY A] - short <7> [122.106816] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:391:DDI A/PHY A] <7> [122.107486] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [122.107995] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [122.108575] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:391:DDI A/PHY A] <7> [122.109025] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:400:DDI TC1/PHY TC1] <7> [122.109448] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:402:DP-MST A] <7> [122.109834] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST B] <7> [122.110208] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST C] <7> [122.110670] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:412:DDI TC2/PHY TC2] <7> [122.111037] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:414:DP-MST A] <7> [122.111483] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST B] <7> [122.111842] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST C] <7> [122.112195] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:420:DDI TC3/PHY TC3] <7> [122.112646] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:422:DP-MST A] <7> [122.113020] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST B] <7> [122.113360] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST C] <7> [122.113784] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:392:eDP-1] <7> [122.114236] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [122.114635] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [122.114997] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [122.115602] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [122.116127] 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> [122.116734] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:150:pipe A] <7> [122.117135] 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> [122.117643] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [122.117930] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [122.118753] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [122.119107] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:388:pipe C] <7> [122.119371] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [122.119461] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:392:eDP-1] <7> [122.119615] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:392:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [122.119955] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:391:DDI A/PHY A][CRTC:269: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> [122.120231] 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> [122.120565] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [122.120892] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:391:DDI A/PHY A] [CRTC:269:pipe B] <7> [122.121159] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [122.121417] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [122.121686] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [122.121923] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [122.122150] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [122.122372] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [122.122620] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [122.122861] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [122.123068] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [122.123255] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [122.123449] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [122.123664] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [122.123869] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [122.124054] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [122.124211] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [122.124366] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [122.124546] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [122.124696] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [122.124845] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [122.124989] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [122.125128] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [122.125262] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [122.125392] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [122.125568] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [122.125709] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [122.125842] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [122.125967] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [122.126085] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [122.126201] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [122.126315] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [122.126431] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [122.126552] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [122.126668] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [122.126784] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [122.126897] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [122.127004] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [122.127109] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [122.127211] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [122.127320] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe B] fastset requirement not met, forcing full modeset <7> [122.127471] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [122.127563] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:269:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [122.127669] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:153:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [122.127748] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:263:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [122.127822] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [122.127897] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [122.127969] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [122.128038] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [122.128125] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:269:pipe B] data rate 1390840 num active planes 1 <7> [122.128229] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [122.128326] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [122.128424] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [122.128517] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [122.128609] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [122.128708] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:269:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [122.128815] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [122.128916] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [122.129013] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [122.129122] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:269:pipe B] allocated DPLL 0 <7> [122.129203] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:269:pipe B] reserving DPLL 0 <7> [122.129287] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:269:pipe B] enable: yes [modeset] <7> [122.129371] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [122.129523] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [122.129641] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [122.129731] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [122.129815] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [122.129895] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [122.129975] 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> [122.130056] 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> [122.130135] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [122.130215] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [122.130294] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [122.130374] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [122.130466] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [122.130549] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [122.130632] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [122.130719] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [122.130807] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [122.130883] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [122.130958] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [122.131034] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [122.131110] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [122.131186] 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> [122.131265] 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> [122.131345] 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> [122.131454] 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> [122.131548] 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> [122.131617] 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> [122.131686] 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> [122.131762] 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> [122.131835] 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> [122.131903] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [122.131972] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [122.132041] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [122.132116] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [122.132193] 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> [122.132272] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [122.132349] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [122.132447] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [122.132522] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [122.132592] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [122.132666] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [122.132742] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [122.132816] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [122.132884] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [122.132955] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [122.133033] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [122.133108] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [122.133182] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [122.133252] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [122.133323] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [122.133422] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [122.133507] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [122.133585] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [122.133653] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [122.133721] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [122.133791] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [122.133860] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [122.133931] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:153:plane 1B] fb: [FB:430] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [122.134002] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [122.134071] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [122.134141] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:183:plane 2B] fb: [NOFB], visible: no <7> [122.134212] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:213:plane 3B] fb: [NOFB], visible: no <7> [122.134281] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:243:plane 4B] fb: [NOFB], visible: no <7> [122.134356] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:253:plane 5B] fb: [NOFB], visible: no <7> [122.134449] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:263:cursor B] fb: [NOFB], visible: no <7> [122.134841] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [122.134985] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [122.135120] 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> [122.135219] 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> [122.135311] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [122.135414] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [122.135511] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:391:DDI A/PHY A] <7> [122.135589] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:400:DDI TC1/PHY TC1] <7> [122.135661] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:402:DP-MST A] <7> [122.135743] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST B] <7> [122.135826] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST C] <7> [122.135907] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:412:DDI TC2/PHY TC2] <7> [122.135979] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:414:DP-MST A] <7> [122.136045] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST B] <7> [122.136109] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST C] <7> [122.136173] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:420:DDI TC3/PHY TC3] <7> [122.136238] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:422:DP-MST A] <7> [122.136304] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST B] <7> [122.136368] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST C] <7> [122.136483] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [122.136678] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [122.136757] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [122.136874] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [122.138317] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:269:pipe B] <7> [122.138487] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [122.140458] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 turn panel power on <7> [122.140549] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 wait for panel power cycle (466 ms remaining) <7> [122.141840] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [122.141941] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:391:DDI A/PHY A] - long <7> [122.142021] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [122.142109] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:391:DDI A/PHY A] <7> [122.614640] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [122.645588] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [122.646057] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 wait for panel power on <7> [122.646536] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [122.682272] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [122.682653] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:391:DDI A/PHY A] - long <7> [122.683017] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [122.683426] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:391:DDI A/PHY A] <7> [122.856795] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [122.857201] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 turning VDD on <7> [122.857594] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [122.859727] 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> [122.861324] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [122.862347] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [122.863827] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [122.865380] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [122.866678] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Clock recovery OK <7> [122.867133] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [122.868806] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [122.869237] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [122.870138] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [122.870771] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [122.871240] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [122.871787] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:392:eDP-1] set backlight PWM = 192000 <7> [122.887693] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [122.889660] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:392:eDP-1] <7> [122.890129] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe B] <7> [125.406438] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 turning VDD off <7> [125.406929] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [130.287035] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [130.287633] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [130.288139] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [130.438191] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

8.70 seconds

Hostname

shard-lnl-2

Igt-Version

IGT-Version: 2.3-gd91dcaa22 (x86_64) (Linux: 7.0.0-rc3-lgci-xe-xe-4702-4f823cb4f9faf6611-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:921 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1887 run_test()
  #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043()
  #4 ../tests/kms_flip.c:2043 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (8.699s)

Err

Starting dynamic subtest: B-eDP1
(kms_flip:2562) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2562) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2562) DEBUG: name = flip
last_ts = 127.831413
last_received_ts = 127.830872
last_seq = 945
current_ts = 127.848076
current_received_ts = 127.847519
current_seq = 946
count = 320
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 98us
(kms_flip:2562) DEBUG: name = flip
last_ts = 127.848076
last_received_ts = 127.847519
last_seq = 946
current_ts = 127.864738
current_received_ts = 127.864189
current_seq = 947
count = 321
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 85us
(kms_flip:2562) DEBUG: name = flip
last_ts = 127.864738
last_received_ts = 127.864189
last_seq = 947
current_ts = 127.881409
current_received_ts = 127.880852
current_seq = 948
count = 322
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 184us
(kms_flip:2562) DEBUG: name = flip
last_ts = 127.881409
last_received_ts = 127.880852
last_seq = 948
current_ts = 127.898071
current_received_ts = 127.897499
current_seq = 949
count = 323
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 98us
(kms_flip:2562) DEBUG: name = flip
last_ts = 127.898071
last_received_ts = 127.897499
last_seq = 949
current_ts = 127.914734
current_received_ts = 127.914192
current_seq = 950
count = 324
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 98us
(kms_flip:2562) DEBUG: name = flip
last_ts = 127.914734
last_received_ts = 127.914192
last_seq = 950
current_ts = 127.931396
current_received_ts = 127.930878
current_seq = 951
count = 325
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 95us
(kms_flip:2562) DEBUG: name = flip
last_ts = 127.931396
last_received_ts = 127.930878
last_seq = 951
current_ts = 127.948067
current_received_ts = 127.947517
current_seq = 952
count = 326
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 127.948067
last_received_ts = 127.947517
last_seq = 952
current_ts = 127.964729
current_received_ts = 127.964211
current_seq = 953
count = 327
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 98us
(kms_flip:2562) DEBUG: name = flip
last_ts = 127.964729
last_received_ts = 127.964211
last_seq = 953
current_ts = 127.981392
current_received_ts = 127.980865
current_seq = 954
count = 328
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 85us
(kms_flip:2562) DEBUG: name = flip
last_ts = 127.981392
last_received_ts = 127.980865
last_seq = 954
current_ts = 127.998055
current_received_ts = 127.997520
current_seq = 955
count = 329
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 95us
(kms_flip:2562) DEBUG: name = flip
last_ts = 127.998055
last_received_ts = 127.997520
last_seq = 955
current_ts = 128.014725
current_received_ts = 128.014191
current_seq = 956
count = 330
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 86us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.014725
last_received_ts = 128.014191
last_seq = 956
current_ts = 128.031387
current_received_ts = 128.030853
current_seq = 957
count = 331
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.031387
last_received_ts = 128.030853
last_seq = 957
current_ts = 128.048050
current_received_ts = 128.047501
current_seq = 958
count = 332
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 131us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.048050
last_received_ts = 128.047501
last_seq = 958
current_ts = 128.064713
current_received_ts = 128.064178
current_seq = 959
count = 333
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 93us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.064713
last_received_ts = 128.064178
last_seq = 959
current_ts = 128.081390
current_received_ts = 128.080841
current_seq = 960
count = 334
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 96us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.081390
last_received_ts = 128.080841
last_seq = 960
current_ts = 128.098053
current_received_ts = 128.097504
current_seq = 961
count = 335
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 86us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.098053
last_received_ts = 128.097504
last_seq = 961
current_ts = 128.114716
current_received_ts = 128.114182
current_seq = 962
count = 336
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.114716
last_received_ts = 128.114182
last_seq = 962
current_ts = 128.131378
current_received_ts = 128.130844
current_seq = 963
count = 337
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 98us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.131378
last_received_ts = 128.130844
last_seq = 963
current_ts = 128.148041
current_received_ts = 128.147507
current_seq = 964
count = 338
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.148041
last_received_ts = 128.147507
last_seq = 964
current_ts = 128.164703
current_received_ts = 128.164185
current_seq = 965
count = 339
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 99us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.164703
last_received_ts = 128.164185
last_seq = 965
current_ts = 128.181381
current_received_ts = 128.180832
current_seq = 966
count = 340
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 86us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.181381
last_received_ts = 128.180832
last_seq = 966
current_ts = 128.198029
current_received_ts = 128.197510
current_seq = 967
count = 341
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 150us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.198029
last_received_ts = 128.197510
last_seq = 967
current_ts = 128.214706
current_received_ts = 128.214172
current_seq = 968
count = 342
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 74us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.214706
last_received_ts = 128.214172
last_seq = 968
current_ts = 128.231369
current_received_ts = 128.230820
current_seq = 969
count = 343
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 99us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.231369
last_received_ts = 128.230820
last_seq = 969
current_ts = 128.248032
current_received_ts = 128.247498
current_seq = 970
count = 344
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 131us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.248032
last_received_ts = 128.247498
last_seq = 970
current_ts = 128.264694
current_received_ts = 128.264175
current_seq = 971
count = 345
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.264694
last_received_ts = 128.264175
last_seq = 971
current_ts = 128.281357
current_received_ts = 128.280853
current_seq = 972
count = 346
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 108us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.281357
last_received_ts = 128.280853
last_seq = 972
current_ts = 128.298019
current_received_ts = 128.297516
current_seq = 973
count = 347
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.298019
last_received_ts = 128.297516
last_seq = 973
current_ts = 128.314682
current_received_ts = 128.314163
current_seq = 974
count = 348
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 87us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.314682
last_received_ts = 128.314163
last_seq = 974
current_ts = 128.331360
current_received_ts = 128.330826
current_seq = 975
count = 349
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 85us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.331360
last_received_ts = 128.330826
last_seq = 975
current_ts = 128.348022
current_received_ts = 128.347473
current_seq = 976
count = 350
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.348022
last_received_ts = 128.347473
last_seq = 976
current_ts = 128.364685
current_received_ts = 128.364166
current_seq = 977
count = 351
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.364685
last_received_ts = 128.364166
last_seq = 977
current_ts = 128.381348
current_received_ts = 128.380814
current_seq = 978
count = 352
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.381348
last_received_ts = 128.380814
last_seq = 978
current_ts = 128.398010
current_received_ts = 128.397491
current_seq = 979
count = 353
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 148us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.398010
last_received_ts = 128.397491
last_seq = 979
current_ts = 128.414688
current_received_ts = 128.414169
current_seq = 980
count = 354
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 86us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.414688
last_received_ts = 128.414169
last_seq = 980
current_ts = 128.431335
current_received_ts = 128.430817
current_seq = 981
count = 355
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 86us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.431335
last_received_ts = 128.430817
last_seq = 981
current_ts = 128.448013
current_received_ts = 128.447479
current_seq = 982
count = 356
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 85us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.448013
last_received_ts = 128.447479
last_seq = 982
current_ts = 128.464676
current_received_ts = 128.464157
current_seq = 983
count = 357
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 98us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.464676
last_received_ts = 128.464157
last_seq = 983
current_ts = 128.481339
current_received_ts = 128.480804
current_seq = 984
count = 358
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.481339
last_received_ts = 128.480804
last_seq = 984
current_ts = 128.498001
current_received_ts = 128.497482
current_seq = 985
count = 359
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 151us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.498001
last_received_ts = 128.497482
last_seq = 985
current_ts = 128.514664
current_received_ts = 128.514145
current_seq = 986
count = 360
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 96us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.514664
last_received_ts = 128.514145
last_seq = 986
current_ts = 128.531342
current_received_ts = 128.530807
current_seq = 987
count = 361
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 92us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.531342
last_received_ts = 128.530807
last_seq = 987
current_ts = 128.547989
current_received_ts = 128.547424
current_seq = 988
count = 362
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 93us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.547989
last_received_ts = 128.547424
last_seq = 988
current_ts = 128.564667
current_received_ts = 128.564133
current_seq = 989
count = 363
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 93us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.564667
last_received_ts = 128.564133
last_seq = 989
current_ts = 128.581329
current_received_ts = 128.580780
current_seq = 990
count = 364
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 90us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.581329
last_received_ts = 128.580780
last_seq = 990
current_ts = 128.597992
current_received_ts = 128.597412
current_seq = 991
count = 365
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 46us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.597992
last_received_ts = 128.597412
last_seq = 991
current_ts = 128.614655
current_received_ts = 128.614029
current_seq = 992
count = 366
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 43us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.614655
last_received_ts = 128.614029
last_seq = 992
current_ts = 128.631317
current_received_ts = 128.630539
current_seq = 993
count = 367
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 49us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.631317
last_received_ts = 128.630539
last_seq = 993
current_ts = 128.647980
current_received_ts = 128.647156
current_seq = 994
count = 368
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 48us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.647980
last_received_ts = 128.647156
last_seq = 994
current_ts = 128.664642
current_received_ts = 128.663879
current_seq = 995
count = 369
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 70us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.664642
last_received_ts = 128.663879
last_seq = 995
current_ts = 128.681320
current_received_ts = 128.680618
current_seq = 996
count = 370
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 156us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.681320
last_received_ts = 128.680618
last_seq = 996
current_ts = 128.697983
current_received_ts = 128.697220
current_seq = 997
count = 371
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 69us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.697983
last_received_ts = 128.697220
last_seq = 997
current_ts = 128.714645
current_received_ts = 128.713913
current_seq = 998
count = 372
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 60us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.714645
last_received_ts = 128.713913
last_seq = 998
current_ts = 128.731308
current_received_ts = 128.730682
current_seq = 999
count = 373
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 115us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.731308
last_received_ts = 128.730682
last_seq = 999
current_ts = 128.747971
current_received_ts = 128.747299
current_seq = 1000
count = 374
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 117us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.747971
last_received_ts = 128.747299
last_seq = 1000
current_ts = 128.764633
current_received_ts = 128.764069
current_seq = 1001
count = 375
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 81us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.764633
last_received_ts = 128.764069
last_seq = 1001
current_ts = 128.781311
current_received_ts = 128.780670
current_seq = 1002
count = 376
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 89us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.781311
last_received_ts = 128.780670
last_seq = 1002
current_ts = 128.797974
current_received_ts = 128.797287
current_seq = 1003
count = 377
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 114us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.797974
last_received_ts = 128.797287
last_seq = 1003
current_ts = 128.814636
current_received_ts = 128.814087
current_seq = 1004
count = 378
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 80us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.814636
last_received_ts = 128.814087
last_seq = 1004
current_ts = 128.831299
current_received_ts = 128.830658
current_seq = 1005
count = 379
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 101us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.831299
last_received_ts = 128.830658
last_seq = 1005
current_ts = 128.847961
current_received_ts = 128.847366
current_seq = 1006
count = 380
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 86us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.847961
last_received_ts = 128.847366
last_seq = 1006
current_ts = 128.864624
current_received_ts = 128.863953
current_seq = 1007
count = 381
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 131us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.864624
last_received_ts = 128.863953
last_seq = 1007
current_ts = 128.881302
current_received_ts = 128.880753
current_seq = 1008
count = 382
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 91us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.881302
last_received_ts = 128.880753
last_seq = 1008
current_ts = 128.897964
current_received_ts = 128.897293
current_seq = 1009
count = 383
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 101us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.897964
last_received_ts = 128.897293
last_seq = 1009
current_ts = 128.914627
current_received_ts = 128.913971
current_seq = 1010
count = 384
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 95us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.914627
last_received_ts = 128.913971
last_seq = 1010
current_ts = 128.931290
current_received_ts = 128.930618
current_seq = 1011
count = 385
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 61us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.931290
last_received_ts = 128.930618
last_seq = 1011
current_ts = 128.947952
current_received_ts = 128.947266
current_seq = 1012
count = 386
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 57us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.947952
last_received_ts = 128.947266
last_seq = 1012
current_ts = 128.964615
current_received_ts = 128.964066
current_seq = 1013
count = 387
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 82us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.964615
last_received_ts = 128.964066
last_seq = 1013
current_ts = 128.981293
current_received_ts = 128.980621
current_seq = 1014
count = 388
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 106us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.981293
last_received_ts = 128.980621
last_seq = 1014
current_ts = 128.997940
current_received_ts = 128.997253
current_seq = 1015
count = 389
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 55us
(kms_flip:2562) DEBUG: name = flip
last_ts = 128.997940
last_received_ts = 128.997253
last_seq = 1015
current_ts = 129.014618
current_received_ts = 129.013962
current_seq = 1016
count = 390
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 116us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.014618
last_received_ts = 129.013962
last_seq = 1016
current_ts = 129.031281
current_received_ts = 129.030609
current_seq = 1017
count = 391
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 120us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.031281
last_received_ts = 129.030609
last_seq = 1017
current_ts = 129.047943
current_received_ts = 129.047424
current_seq = 1018
count = 392
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 72us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.047943
last_received_ts = 129.047424
last_seq = 1018
current_ts = 129.064606
current_received_ts = 129.063980
current_seq = 1019
count = 393
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 133us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.064606
last_received_ts = 129.063980
last_seq = 1019
current_ts = 129.081268
current_received_ts = 129.080612
current_seq = 1020
count = 394
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 59us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.081268
last_received_ts = 129.080612
last_seq = 1020
current_ts = 129.097946
current_received_ts = 129.097260
current_seq = 1021
count = 395
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 54us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.097946
last_received_ts = 129.097260
last_seq = 1021
current_ts = 129.114594
current_received_ts = 129.114044
current_seq = 1022
count = 396
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 79us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.114594
last_received_ts = 129.114044
last_seq = 1022
current_ts = 129.131271
current_received_ts = 129.130630
current_seq = 1023
count = 397
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 91us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.131271
last_received_ts = 129.130630
last_seq = 1023
current_ts = 129.147934
current_received_ts = 129.147278
current_seq = 1024
count = 398
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 114us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.147934
last_received_ts = 129.147278
last_seq = 1024
current_ts = 129.164597
current_received_ts = 129.164062
current_seq = 1025
count = 399
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 70us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.164597
last_received_ts = 129.164062
last_seq = 1025
current_ts = 129.181259
current_received_ts = 129.180618
current_seq = 1026
count = 400
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 94us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.181259
last_received_ts = 129.180618
last_seq = 1026
current_ts = 129.197922
current_received_ts = 129.197174
current_seq = 1027
count = 401
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 112us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.197922
last_received_ts = 129.197174
last_seq = 1027
current_ts = 129.214600
current_received_ts = 129.214066
current_seq = 1028
count = 402
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 81us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.214600
last_received_ts = 129.214066
last_seq = 1028
current_ts = 129.231247
current_received_ts = 129.230606
current_seq = 1029
count = 403
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 60us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.231247
last_received_ts = 129.230606
last_seq = 1029
current_ts = 129.247925
current_received_ts = 129.247223
current_seq = 1030
count = 404
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 50us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.247925
last_received_ts = 129.247223
last_seq = 1030
current_ts = 129.264587
current_received_ts = 129.263901
current_seq = 1031
count = 405
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 51us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.264587
last_received_ts = 129.263901
last_seq = 1031
current_ts = 129.281250
current_received_ts = 129.280624
current_seq = 1032
count = 406
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 98us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.281250
last_received_ts = 129.280624
last_seq = 1032
current_ts = 129.297913
current_received_ts = 129.297226
current_seq = 1033
count = 407
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 61us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.297913
last_received_ts = 129.297226
last_seq = 1033
current_ts = 129.314575
current_received_ts = 129.313919
current_seq = 1034
count = 408
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 51us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.314575
last_received_ts = 129.313919
last_seq = 1034
current_ts = 129.331238
current_received_ts = 129.330566
current_seq = 1035
count = 409
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 89us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.331238
last_received_ts = 129.330566
last_seq = 1035
current_ts = 129.347916
current_received_ts = 129.347229
current_seq = 1036
count = 410
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 114us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.347916
last_received_ts = 129.347229
last_seq = 1036
current_ts = 129.364563
current_received_ts = 129.363892
current_seq = 1037
count = 411
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 45us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.364563
last_received_ts = 129.363892
last_seq = 1037
current_ts = 129.381241
current_received_ts = 129.380569
current_seq = 1038
count = 412
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 45us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.381241
last_received_ts = 129.380569
last_seq = 1038
current_ts = 129.397903
current_received_ts = 129.397308
current_seq = 1039
count = 413
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 91us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.397903
last_received_ts = 129.397308
last_seq = 1039
current_ts = 129.414566
current_received_ts = 129.414001
current_seq = 1040
count = 414
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 63us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.414566
last_received_ts = 129.414001
last_seq = 1040
current_ts = 129.431229
current_received_ts = 129.430573
current_seq = 1041
count = 415
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 103us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.431229
last_received_ts = 129.430573
last_seq = 1041
current_ts = 129.447906
current_received_ts = 129.447205
current_seq = 1042
count = 416
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 110us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.447906
last_received_ts = 129.447205
last_seq = 1042
current_ts = 129.464554
current_received_ts = 129.463989
current_seq = 1043
count = 417
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 74us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.464554
last_received_ts = 129.463989
last_seq = 1043
current_ts = 129.481232
current_received_ts = 129.480621
current_seq = 1044
count = 418
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 105us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.481232
last_received_ts = 129.480621
last_seq = 1044
current_ts = 129.497894
current_received_ts = 129.497223
current_seq = 1045
count = 419
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 122us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.497894
last_received_ts = 129.497223
last_seq = 1045
current_ts = 129.514557
current_received_ts = 129.513992
current_seq = 1046
count = 420
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 80us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.514557
last_received_ts = 129.513992
last_seq = 1046
current_ts = 129.531219
current_received_ts = 129.530594
current_seq = 1047
count = 421
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.531219
last_received_ts = 129.530594
last_seq = 1047
current_ts = 129.547897
current_received_ts = 129.547241
current_seq = 1048
count = 422
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 61us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.547897
last_received_ts = 129.547241
last_seq = 1048
current_ts = 129.564545
current_received_ts = 129.563873
current_seq = 1049
count = 423
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 53us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.564545
last_received_ts = 129.563873
last_seq = 1049
current_ts = 129.581207
current_received_ts = 129.580582
current_seq = 1050
count = 424
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 100us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.581207
last_received_ts = 129.580582
last_seq = 1050
current_ts = 129.597885
current_received_ts = 129.597198
current_seq = 1051
count = 425
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 121us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.597885
last_received_ts = 129.597198
last_seq = 1051
current_ts = 129.614548
current_received_ts = 129.613892
current_seq = 1052
count = 426
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 147us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.614548
last_received_ts = 129.613892
last_seq = 1052
current_ts = 129.631210
current_received_ts = 129.630569
current_seq = 1053
count = 427
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 95us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.631210
last_received_ts = 129.630569
last_seq = 1053
current_ts = 129.647873
current_received_ts = 129.647217
current_seq = 1054
count = 428
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 105us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.647873
last_received_ts = 129.647217
last_seq = 1054
current_ts = 129.664536
current_received_ts = 129.663925
current_seq = 1055
count = 429
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 140us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.664536
last_received_ts = 129.663925
last_seq = 1055
current_ts = 129.681198
current_received_ts = 129.680557
current_seq = 1056
count = 430
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 79us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.681198
last_received_ts = 129.680557
last_seq = 1056
current_ts = 129.697861
current_received_ts = 129.697250
current_seq = 1057
count = 431
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 91us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.697861
last_received_ts = 129.697250
last_seq = 1057
current_ts = 129.714539
current_received_ts = 129.713898
current_seq = 1058
count = 432
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 106us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.714539
last_received_ts = 129.713898
last_seq = 1058
current_ts = 129.731201
current_received_ts = 129.730576
current_seq = 1059
count = 433
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 91us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.731201
last_received_ts = 129.730576
last_seq = 1059
current_ts = 129.747864
current_received_ts = 129.747208
current_seq = 1060
count = 434
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 46us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.747864
last_received_ts = 129.747208
last_seq = 1060
current_ts = 129.764526
current_received_ts = 129.763901
current_seq = 1061
count = 435
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 77us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.764526
last_received_ts = 129.763901
last_seq = 1061
current_ts = 129.781189
current_received_ts = 129.780655
current_seq = 1062
count = 436
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 83us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.781189
last_received_ts = 129.780655
last_seq = 1062
current_ts = 129.797867
current_received_ts = 129.797150
current_seq = 1063
count = 437
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 119us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.797867
last_received_ts = 129.797150
last_seq = 1063
current_ts = 129.814529
current_received_ts = 129.813965
current_seq = 1064
count = 438
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 102us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.814529
last_received_ts = 129.813965
last_seq = 1064
current_ts = 129.831192
current_received_ts = 129.830566
current_seq = 1065
count = 439
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 97us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.831192
last_received_ts = 129.830566
last_seq = 1065
current_ts = 129.847855
current_received_ts = 129.847198
current_seq = 1066
count = 440
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 105us
(kms_flip:2562) DEBUG: name = flip
last_ts = 129.847855
last_received_ts = 129.847198
last_seq = 1066
current_ts = 129.864517
current_received_ts = 129.863922
current_seq = 1067
count = 441
seq_step = 1
(kms_flip:2562) DEBUG: Vblank took 1116us
(kms_flip:2562) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2562) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2562) igt_core-INFO: Stack trace:
(kms_flip:2562) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2562) igt_core-INFO:   #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0()
(kms_flip:2562) igt_core-INFO:   #2 ../tests/kms_flip.c:1887 run_test()
(kms_flip:2562) igt_core-INFO:   #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043()
(kms_flip:2562) igt_core-INFO:   #4 ../tests/kms_flip.c:2043 main()
(kms_flip:2562) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2562) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2562) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (8.699s)

Dmesg

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

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

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

<7> [121.762324] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430]

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

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

<7> [121.833530] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:150:pipe A]

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

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

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

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

<7> [121.834857] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150: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> [121.835077] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [122.116127] 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> [122.116734] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:150:pipe A]

<7> [122.117135] 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> [122.117643] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

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

<7> [122.118753] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]

<7> [122.119107] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:388:pipe C]

<7> [122.119371] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]

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

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

<7> [122.119955] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:391:DDI A/PHY A][CRTC:269: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> [122.120231] 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> [122.120565] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0

<7> [122.120892] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:391:DDI A/PHY A] [CRTC:269:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [122.127669] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:153:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

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

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

<7> [122.127897] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [122.127969] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [122.128038] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [122.128125] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:269:pipe B] data rate 1390840 num active planes 1

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [122.129975] 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> [122.130056] 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> [122.130135] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

<7> [122.131186] 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> [122.131265] 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> [122.131345] 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> [122.131454] 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> [122.131548] 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> [122.131617] 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> [122.131686] 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> [122.131762] 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> [122.131835] 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> [122.131903] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

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

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

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

<7> [122.132193] 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> [122.132272] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [122.135120] 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> [122.135219] 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> [122.135311] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [122.859727] 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> [122.861324] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Reloading eDP link rates

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [122.890129] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe B]

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

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

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

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

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

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

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