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

Detail	Value
Duration	5.70 seconds
Hostname	shard-mtlp-3
Igt-Version	IGT-Version: 2.3-g4987fcaab (x86_64) (Linux: 6.19.0-CI_DRM_18010-g84d640df1ee7+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c: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 (5.699s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:2981) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2981) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:2981) DEBUG: name = flip last_ts = 698.645813 last_received_ts = 698.645691 last_seq = 937 current_ts = 698.656921 current_received_ts = 698.656860 current_seq = 938 count = 245 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 14us (kms_flip:2981) DEBUG: name = flip last_ts = 698.656921 last_received_ts = 698.656860 last_seq = 938 current_ts = 698.668030 current_received_ts = 698.667969 current_seq = 939 count = 246 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 698.668030 last_received_ts = 698.667969 last_seq = 939 current_ts = 698.679138 current_received_ts = 698.679077 current_seq = 940 count = 247 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 698.679138 last_received_ts = 698.679077 last_seq = 940 current_ts = 698.690247 current_received_ts = 698.690125 current_seq = 941 count = 248 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.690247 last_received_ts = 698.690125 last_seq = 941 current_ts = 698.701355 current_received_ts = 698.701233 current_seq = 942 count = 249 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.701355 last_received_ts = 698.701233 last_seq = 942 current_ts = 698.712463 current_received_ts = 698.712402 current_seq = 943 count = 250 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 698.712463 last_received_ts = 698.712402 last_seq = 943 current_ts = 698.723572 current_received_ts = 698.723450 current_seq = 944 count = 251 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 698.723572 last_received_ts = 698.723450 last_seq = 944 current_ts = 698.734680 current_received_ts = 698.734497 current_seq = 945 count = 252 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 10us (kms_flip:2981) DEBUG: name = flip last_ts = 698.734680 last_received_ts = 698.734497 last_seq = 945 current_ts = 698.745789 current_received_ts = 698.745728 current_seq = 946 count = 253 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 12us (kms_flip:2981) DEBUG: name = flip last_ts = 698.745789 last_received_ts = 698.745728 last_seq = 946 current_ts = 698.756897 current_received_ts = 698.756836 current_seq = 947 count = 254 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 698.756897 last_received_ts = 698.756836 last_seq = 947 current_ts = 698.768005 current_received_ts = 698.767944 current_seq = 948 count = 255 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 698.768005 last_received_ts = 698.767944 last_seq = 948 current_ts = 698.779114 current_received_ts = 698.779053 current_seq = 949 count = 256 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.779114 last_received_ts = 698.779053 last_seq = 949 current_ts = 698.790222 current_received_ts = 698.790161 current_seq = 950 count = 257 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.790222 last_received_ts = 698.790161 last_seq = 950 current_ts = 698.801331 current_received_ts = 698.801208 current_seq = 951 count = 258 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.801331 last_received_ts = 698.801208 last_seq = 951 current_ts = 698.812439 current_received_ts = 698.812378 current_seq = 952 count = 259 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.812439 last_received_ts = 698.812378 last_seq = 952 current_ts = 698.823547 current_received_ts = 698.823364 current_seq = 953 count = 260 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.823547 last_received_ts = 698.823364 last_seq = 953 current_ts = 698.834656 current_received_ts = 698.834473 current_seq = 954 count = 261 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.834656 last_received_ts = 698.834473 last_seq = 954 current_ts = 698.845764 current_received_ts = 698.845642 current_seq = 955 count = 262 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 698.845764 last_received_ts = 698.845642 last_seq = 955 current_ts = 698.856873 current_received_ts = 698.856812 current_seq = 956 count = 263 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 698.856873 last_received_ts = 698.856812 last_seq = 956 current_ts = 698.867981 current_received_ts = 698.867859 current_seq = 957 count = 264 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 698.867981 last_received_ts = 698.867859 last_seq = 957 current_ts = 698.879089 current_received_ts = 698.879089 current_seq = 958 count = 265 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.879089 last_received_ts = 698.879089 last_seq = 958 current_ts = 698.890198 current_received_ts = 698.890076 current_seq = 959 count = 266 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.890198 last_received_ts = 698.890076 last_seq = 959 current_ts = 698.901306 current_received_ts = 698.901184 current_seq = 960 count = 267 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 698.901306 last_received_ts = 698.901184 last_seq = 960 current_ts = 698.912415 current_received_ts = 698.912231 current_seq = 961 count = 268 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.912415 last_received_ts = 698.912231 last_seq = 961 current_ts = 698.923523 current_received_ts = 698.923401 current_seq = 962 count = 269 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 698.923523 last_received_ts = 698.923401 last_seq = 962 current_ts = 698.934631 current_received_ts = 698.934509 current_seq = 963 count = 270 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.934631 last_received_ts = 698.934509 last_seq = 963 current_ts = 698.945740 current_received_ts = 698.945618 current_seq = 964 count = 271 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 698.945740 last_received_ts = 698.945618 last_seq = 964 current_ts = 698.956848 current_received_ts = 698.956665 current_seq = 965 count = 272 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 11us (kms_flip:2981) DEBUG: name = flip last_ts = 698.956848 last_received_ts = 698.956665 last_seq = 965 current_ts = 698.967957 current_received_ts = 698.967896 current_seq = 966 count = 273 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 698.967957 last_received_ts = 698.967896 last_seq = 966 current_ts = 698.979065 current_received_ts = 698.979065 current_seq = 967 count = 274 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 698.979065 last_received_ts = 698.979065 last_seq = 967 current_ts = 698.990173 current_received_ts = 698.990112 current_seq = 968 count = 275 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 698.990173 last_received_ts = 698.990112 last_seq = 968 current_ts = 699.001282 current_received_ts = 699.001160 current_seq = 969 count = 276 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.001282 last_received_ts = 699.001160 last_seq = 969 current_ts = 699.012390 current_received_ts = 699.012207 current_seq = 970 count = 277 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.012390 last_received_ts = 699.012207 last_seq = 970 current_ts = 699.023499 current_received_ts = 699.023376 current_seq = 971 count = 278 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 10us (kms_flip:2981) DEBUG: name = flip last_ts = 699.023499 last_received_ts = 699.023376 last_seq = 971 current_ts = 699.034607 current_received_ts = 699.034424 current_seq = 972 count = 279 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.034607 last_received_ts = 699.034424 last_seq = 972 current_ts = 699.045715 current_received_ts = 699.045654 current_seq = 973 count = 280 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 699.045715 last_received_ts = 699.045654 last_seq = 973 current_ts = 699.056824 current_received_ts = 699.056702 current_seq = 974 count = 281 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 699.056824 last_received_ts = 699.056702 last_seq = 974 current_ts = 699.067932 current_received_ts = 699.067871 current_seq = 975 count = 282 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.067932 last_received_ts = 699.067871 last_seq = 975 current_ts = 699.079041 current_received_ts = 699.078979 current_seq = 976 count = 283 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.079041 last_received_ts = 699.078979 last_seq = 976 current_ts = 699.090149 current_received_ts = 699.090088 current_seq = 977 count = 284 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.090149 last_received_ts = 699.090088 last_seq = 977 current_ts = 699.101257 current_received_ts = 699.101135 current_seq = 978 count = 285 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.101257 last_received_ts = 699.101135 last_seq = 978 current_ts = 699.112366 current_received_ts = 699.112244 current_seq = 979 count = 286 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.112366 last_received_ts = 699.112244 last_seq = 979 current_ts = 699.123474 current_received_ts = 699.123291 current_seq = 980 count = 287 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 699.123474 last_received_ts = 699.123291 last_seq = 980 current_ts = 699.134583 current_received_ts = 699.134460 current_seq = 981 count = 288 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.134583 last_received_ts = 699.134460 last_seq = 981 current_ts = 699.145691 current_received_ts = 699.145508 current_seq = 982 count = 289 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.145691 last_received_ts = 699.145508 last_seq = 982 current_ts = 699.156799 current_received_ts = 699.156738 current_seq = 983 count = 290 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.156799 last_received_ts = 699.156738 last_seq = 983 current_ts = 699.167908 current_received_ts = 699.167664 current_seq = 984 count = 291 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.167908 last_received_ts = 699.167664 last_seq = 984 current_ts = 699.179016 current_received_ts = 699.178894 current_seq = 985 count = 292 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.179016 last_received_ts = 699.178894 last_seq = 985 current_ts = 699.190125 current_received_ts = 699.190063 current_seq = 986 count = 293 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.190125 last_received_ts = 699.190063 last_seq = 986 current_ts = 699.201233 current_received_ts = 699.201172 current_seq = 987 count = 294 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.201233 last_received_ts = 699.201172 last_seq = 987 current_ts = 699.212341 current_received_ts = 699.212219 current_seq = 988 count = 295 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.212341 last_received_ts = 699.212219 last_seq = 988 current_ts = 699.223450 current_received_ts = 699.223328 current_seq = 989 count = 296 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.223450 last_received_ts = 699.223328 last_seq = 989 current_ts = 699.234558 current_received_ts = 699.234375 current_seq = 990 count = 297 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 13us (kms_flip:2981) DEBUG: name = flip last_ts = 699.234558 last_received_ts = 699.234375 last_seq = 990 current_ts = 699.245667 current_received_ts = 699.245483 current_seq = 991 count = 298 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.245667 last_received_ts = 699.245483 last_seq = 991 current_ts = 699.256775 current_received_ts = 699.256592 current_seq = 992 count = 299 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 699.256775 last_received_ts = 699.256592 last_seq = 992 current_ts = 699.267883 current_received_ts = 699.267822 current_seq = 993 count = 300 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 699.267883 last_received_ts = 699.267822 last_seq = 993 current_ts = 699.278992 current_received_ts = 699.278931 current_seq = 994 count = 301 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.278992 last_received_ts = 699.278931 last_seq = 994 current_ts = 699.290100 current_received_ts = 699.290039 current_seq = 995 count = 302 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 699.290100 last_received_ts = 699.290039 last_seq = 995 current_ts = 699.301208 current_received_ts = 699.301086 current_seq = 996 count = 303 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.301208 last_received_ts = 699.301086 last_seq = 996 current_ts = 699.312317 current_received_ts = 699.312195 current_seq = 997 count = 304 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.312317 last_received_ts = 699.312195 last_seq = 997 current_ts = 699.323425 current_received_ts = 699.323181 current_seq = 998 count = 305 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.323425 last_received_ts = 699.323181 last_seq = 998 current_ts = 699.334534 current_received_ts = 699.334412 current_seq = 999 count = 306 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.334534 last_received_ts = 699.334412 last_seq = 999 current_ts = 699.345642 current_received_ts = 699.345459 current_seq = 1000 count = 307 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.345642 last_received_ts = 699.345459 last_seq = 1000 current_ts = 699.356750 current_received_ts = 699.356628 current_seq = 1001 count = 308 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 699.356750 last_received_ts = 699.356628 last_seq = 1001 current_ts = 699.367859 current_received_ts = 699.367798 current_seq = 1002 count = 309 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 699.367859 last_received_ts = 699.367798 last_seq = 1002 current_ts = 699.378967 current_received_ts = 699.378906 current_seq = 1003 count = 310 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.378967 last_received_ts = 699.378906 last_seq = 1003 current_ts = 699.390076 current_received_ts = 699.389893 current_seq = 1004 count = 311 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 699.390076 last_received_ts = 699.389893 last_seq = 1004 current_ts = 699.401184 current_received_ts = 699.401062 current_seq = 1005 count = 312 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.401184 last_received_ts = 699.401062 last_seq = 1005 current_ts = 699.412292 current_received_ts = 699.412170 current_seq = 1006 count = 313 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.412292 last_received_ts = 699.412170 last_seq = 1006 current_ts = 699.423401 current_received_ts = 699.423218 current_seq = 1007 count = 314 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.423401 last_received_ts = 699.423218 last_seq = 1007 current_ts = 699.434509 current_received_ts = 699.434387 current_seq = 1008 count = 315 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 11us (kms_flip:2981) DEBUG: name = flip last_ts = 699.434509 last_received_ts = 699.434387 last_seq = 1008 current_ts = 699.445618 current_received_ts = 699.445496 current_seq = 1009 count = 316 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.445618 last_received_ts = 699.445496 last_seq = 1009 current_ts = 699.456726 current_received_ts = 699.456543 current_seq = 1010 count = 317 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.456726 last_received_ts = 699.456543 last_seq = 1010 current_ts = 699.467834 current_received_ts = 699.467773 current_seq = 1011 count = 318 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.467834 last_received_ts = 699.467773 last_seq = 1011 current_ts = 699.478943 current_received_ts = 699.478882 current_seq = 1012 count = 319 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.478943 last_received_ts = 699.478882 last_seq = 1012 current_ts = 699.490051 current_received_ts = 699.490051 current_seq = 1013 count = 320 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.490051 last_received_ts = 699.490051 last_seq = 1013 current_ts = 699.501160 current_received_ts = 699.501099 current_seq = 1014 count = 321 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.501160 last_received_ts = 699.501099 last_seq = 1014 current_ts = 699.512268 current_received_ts = 699.512146 current_seq = 1015 count = 322 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.512268 last_received_ts = 699.512146 last_seq = 1015 current_ts = 699.523376 current_received_ts = 699.523254 current_seq = 1016 count = 323 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.523376 last_received_ts = 699.523254 last_seq = 1016 current_ts = 699.534485 current_received_ts = 699.534363 current_seq = 1017 count = 324 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.534485 last_received_ts = 699.534363 last_seq = 1017 current_ts = 699.545593 current_received_ts = 699.545410 current_seq = 1018 count = 325 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.545593 last_received_ts = 699.545410 last_seq = 1018 current_ts = 699.556702 current_received_ts = 699.556519 current_seq = 1019 count = 326 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.556702 last_received_ts = 699.556519 last_seq = 1019 current_ts = 699.567810 current_received_ts = 699.567627 current_seq = 1020 count = 327 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 14us (kms_flip:2981) DEBUG: name = flip last_ts = 699.567810 last_received_ts = 699.567627 last_seq = 1020 current_ts = 699.578918 current_received_ts = 699.578857 current_seq = 1021 count = 328 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.578918 last_received_ts = 699.578857 last_seq = 1021 current_ts = 699.590027 current_received_ts = 699.589966 current_seq = 1022 count = 329 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.590027 last_received_ts = 699.589966 last_seq = 1022 current_ts = 699.601135 current_received_ts = 699.601074 current_seq = 1023 count = 330 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.601135 last_received_ts = 699.601074 last_seq = 1023 current_ts = 699.612244 current_received_ts = 699.612183 current_seq = 1024 count = 331 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.612244 last_received_ts = 699.612183 last_seq = 1024 current_ts = 699.623352 current_received_ts = 699.623230 current_seq = 1025 count = 332 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.623352 last_received_ts = 699.623230 last_seq = 1025 current_ts = 699.634460 current_received_ts = 699.634399 current_seq = 1026 count = 333 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.634460 last_received_ts = 699.634399 last_seq = 1026 current_ts = 699.645569 current_received_ts = 699.645386 current_seq = 1027 count = 334 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 10us (kms_flip:2981) DEBUG: name = flip last_ts = 699.645569 last_received_ts = 699.645386 last_seq = 1027 current_ts = 699.656677 current_received_ts = 699.656494 current_seq = 1028 count = 335 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.656677 last_received_ts = 699.656494 last_seq = 1028 current_ts = 699.667786 current_received_ts = 699.667664 current_seq = 1029 count = 336 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 9us (kms_flip:2981) DEBUG: name = flip last_ts = 699.667786 last_received_ts = 699.667664 last_seq = 1029 current_ts = 699.678894 current_received_ts = 699.678833 current_seq = 1030 count = 337 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.678894 last_received_ts = 699.678833 last_seq = 1030 current_ts = 699.690002 current_received_ts = 699.689941 current_seq = 1031 count = 338 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.690002 last_received_ts = 699.689941 last_seq = 1031 current_ts = 699.701111 current_received_ts = 699.701050 current_seq = 1032 count = 339 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 11us (kms_flip:2981) DEBUG: name = flip last_ts = 699.701111 last_received_ts = 699.701050 last_seq = 1032 current_ts = 699.712219 current_received_ts = 699.712158 current_seq = 1033 count = 340 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.712219 last_received_ts = 699.712158 last_seq = 1033 current_ts = 699.723328 current_received_ts = 699.723206 current_seq = 1034 count = 341 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.723328 last_received_ts = 699.723206 last_seq = 1034 current_ts = 699.734436 current_received_ts = 699.734192 current_seq = 1035 count = 342 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.734436 last_received_ts = 699.734192 last_seq = 1035 current_ts = 699.745544 current_received_ts = 699.745422 current_seq = 1036 count = 343 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 15us (kms_flip:2981) DEBUG: name = flip last_ts = 699.745544 last_received_ts = 699.745422 last_seq = 1036 current_ts = 699.756653 current_received_ts = 699.756470 current_seq = 1037 count = 344 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.756653 last_received_ts = 699.756470 last_seq = 1037 current_ts = 699.767761 current_received_ts = 699.767578 current_seq = 1038 count = 345 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.767761 last_received_ts = 699.767578 last_seq = 1038 current_ts = 699.778870 current_received_ts = 699.778809 current_seq = 1039 count = 346 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.778870 last_received_ts = 699.778809 last_seq = 1039 current_ts = 699.789978 current_received_ts = 699.789917 current_seq = 1040 count = 347 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 12us (kms_flip:2981) DEBUG: name = flip last_ts = 699.789978 last_received_ts = 699.789917 last_seq = 1040 current_ts = 699.801086 current_received_ts = 699.801025 current_seq = 1041 count = 348 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.801086 last_received_ts = 699.801025 last_seq = 1041 current_ts = 699.812195 current_received_ts = 699.812134 current_seq = 1042 count = 349 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.812195 last_received_ts = 699.812134 last_seq = 1042 current_ts = 699.823303 current_received_ts = 699.823181 current_seq = 1043 count = 350 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.823303 last_received_ts = 699.823181 last_seq = 1043 current_ts = 699.834412 current_received_ts = 699.834229 current_seq = 1044 count = 351 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.834412 last_received_ts = 699.834229 last_seq = 1044 current_ts = 699.845520 current_received_ts = 699.845398 current_seq = 1045 count = 352 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.845520 last_received_ts = 699.845398 last_seq = 1045 current_ts = 699.856628 current_received_ts = 699.856384 current_seq = 1046 count = 353 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.856628 last_received_ts = 699.856384 last_seq = 1046 current_ts = 699.867737 current_received_ts = 699.867554 current_seq = 1047 count = 354 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.867737 last_received_ts = 699.867554 last_seq = 1047 current_ts = 699.878845 current_received_ts = 699.878784 current_seq = 1048 count = 355 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.878845 last_received_ts = 699.878784 last_seq = 1048 current_ts = 699.889954 current_received_ts = 699.889893 current_seq = 1049 count = 356 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.889954 last_received_ts = 699.889893 last_seq = 1049 current_ts = 699.901062 current_received_ts = 699.901001 current_seq = 1050 count = 357 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.901062 last_received_ts = 699.901001 last_seq = 1050 current_ts = 699.912170 current_received_ts = 699.912048 current_seq = 1051 count = 358 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.912170 last_received_ts = 699.912048 last_seq = 1051 current_ts = 699.923279 current_received_ts = 699.923157 current_seq = 1052 count = 359 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.923279 last_received_ts = 699.923157 last_seq = 1052 current_ts = 699.934387 current_received_ts = 699.934265 current_seq = 1053 count = 360 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.934387 last_received_ts = 699.934265 last_seq = 1053 current_ts = 699.945496 current_received_ts = 699.945374 current_seq = 1054 count = 361 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.945496 last_received_ts = 699.945374 last_seq = 1054 current_ts = 699.956604 current_received_ts = 699.956482 current_seq = 1055 count = 362 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.956604 last_received_ts = 699.956482 last_seq = 1055 current_ts = 699.967712 current_received_ts = 699.967468 current_seq = 1056 count = 363 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.967712 last_received_ts = 699.967468 last_seq = 1056 current_ts = 699.978821 current_received_ts = 699.978760 current_seq = 1057 count = 364 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 7us (kms_flip:2981) DEBUG: name = flip last_ts = 699.978821 last_received_ts = 699.978760 last_seq = 1057 current_ts = 699.989929 current_received_ts = 699.989868 current_seq = 1058 count = 365 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 8us (kms_flip:2981) DEBUG: name = flip last_ts = 699.989929 last_received_ts = 699.989868 last_seq = 1058 current_ts = 700.001038 current_received_ts = 700.000977 current_seq = 1059 count = 366 seq_step = 1 (kms_flip:2981) DEBUG: Vblank took 640us (kms_flip:2981) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2981) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2981) igt_core-INFO: Stack trace: (kms_flip:2981) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2981) igt_core-INFO: #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0() (kms_flip:2981) igt_core-INFO: #2 ../tests/kms_flip.c:1887 run_test() (kms_flip:2981) igt_core-INFO: #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043() (kms_flip:2981) igt_core-INFO: #4 ../tests/kms_flip.c:2043 main() (kms_flip:2981) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2981) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2981) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (5.699s)
Dmesg	<6> [725.959981] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [725.960252] i915 0000:00:02.0: [drm:intel_dpt_create [i915]] Allocating dpt from smem <7> [725.960437] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:564] <7> [725.960514] i915 0000:00:02.0: [drm:intel_dpt_create [i915]] Allocating dpt from smem <7> [725.960712] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:567] <7> [725.963499] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [725.963835] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [725.981541] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [725.981825] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [725.991088] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [725.991354] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [726.008028] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [726.008280] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [726.034452] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:150:pipe A] <7> [726.034588] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [726.034790] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [726.034924] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [726.035053] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [726.035180] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 7483046/8388608 link 623587/524288, found tu 0, data 0/0 link 0/0) <7> [726.035309] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [726.035434] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [726.035559] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [726.035753] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [726.035878] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [726.036002] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [726.036123] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [726.036243] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [726.036361] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [726.036482] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1801, found 0) <7> [726.036611] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [726.036738] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [726.036859] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1878, found 0) <7> [726.036980] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1878, found 0) <7> [726.037101] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [726.037225] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [726.037349] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [726.037471] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [726.037592] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [726.037724] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [726.037841] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [726.037963] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1801, found 0) <7> [726.038085] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [726.038208] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [726.038333] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1878, found 0) <7> [726.038452] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1878, found 0) <7> [726.038577] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [726.038711] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [726.038837] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [726.038962] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [726.039085] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [726.039209] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 513820, found 0) <7> [726.039331] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 513820, found 0) <7> [726.039454] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [726.039580] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in set_context_latency (expected 1, found 0) <7> [726.039718] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:150:pipe A] fastset requirement not met, forcing full modeset <7> [726.039841] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:150:pipe A] releasing DPLL 0 <7> [726.039999] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [726.040121] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:150:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [726.040260] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:144:cursor A] ddb (4001 - 4096) -> ( 0 - 0), size 95 -> 0 <7> [726.040394] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:150:pipe A] min cdclk: 256910 kHz -> 0 kHz <7> [726.040523] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Can change cdclk via squashing <7> [726.040656] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz <7> [726.040780] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [726.040922] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:150:pipe A] enable: no [modeset] <7> [726.041045] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:34:plane 1A] fb: [NOFB], visible: no <7> [726.041169] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:64:plane 2A] fb: [NOFB], visible: no <7> [726.041292] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:94:plane 3A] fb: [NOFB], visible: no <7> [726.041413] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:124:plane 4A] fb: [NOFB], visible: no <7> [726.041533] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:134:plane 5A] fb: [NOFB], visible: no <7> [726.041659] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:144:cursor A] fb: [NOFB], visible: no <7> [726.042083] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]] <7> [726.247982] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:507:eDP-1] set backlight PWM = 0 <7> [726.248993] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [726.259305] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 turn panel power off <7> [726.259626] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x00000089, pins 0x00000010, long 0x00000000 <7> [726.259852] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 wait for panel power off time <7> [726.260183] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:506:DDI A/PHY A] - short <7> [726.260386] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [726.312415] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010 <7> [726.313001] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:506:DDI A/PHY A] - long <7> [726.313515] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [726.315757] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [726.316355] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring short hpd on eDP [ENCODER:506:DDI A/PHY A] <7> [726.316345] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:150:pipe A] <7> [726.317121] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:506:DDI A/PHY A] <7> [726.318204] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0 <7> [726.318878] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A <7> [726.319373] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:506:DDI A/PHY A] <7> [726.319688] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:515:DDI B/PHY B] <7> [726.319916] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:517:DP-MST A] <7> [726.320135] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DP-MST B] <7> [726.320348] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:519:DP-MST C] <7> [726.320568] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST D] <7> [726.320864] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:533:DDI TC1/PHY TC1] <7> [726.321155] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DP-MST A] <7> [726.321390] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST B] <7> [726.321595] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST C] <7> [726.321777] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST D] <7> [726.321984] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:542:DDI TC2/PHY TC2] <7> [726.322124] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:546:DDI TC3/PHY TC3] <7> [726.322261] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST A] <7> [726.322524] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST B] <7> [726.322772] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST C] <7> [726.323041] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST D] <7> [726.323196] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:555:DDI TC4/PHY TC4] <7> [726.323316] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:557:DP-MST A] <7> [726.323437] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:558:DP-MST B] <7> [726.323578] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:559:DP-MST C] <7> [726.323716] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:560:DP-MST D] <7> [726.323842] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:507:eDP-1] <7> [726.324032] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no) <7> [726.324175] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: yes -> no (pipe: ) <7> [726.324298] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [726.324519] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_A <7> [726.324656] i915 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [i915]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [726.324857] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:150:pipe A] <7> [726.325032] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Post changing CDCLK to 172800 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [726.325196] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=432 <7> [726.325486] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B] <7> [726.325610] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:386:pipe C] <7> [726.325709] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:504:pipe D] <7> [726.325803] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B] <7> [726.325827] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:507:eDP-1] <7> [726.325877] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:507:eDP-1] Limiting target display pipe bpp to 24 (EDID bpp 30, max requested bpp 24, max platform bpp 36) <7> [726.326032] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:506:DDI A/PHY A][CRTC:268:pipe B] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 24 min link_bpp 18.0000 max link_bpp 24.0000 <7> [726.326150] i915 0000:00:02.0: [drm:intel_dp_compute_link_config [i915]] DP lane count 4 clock 432000 bpp input 24 compressed 0.0000 HDR no link rate required 1541460 available 1728000 <7> [726.326270] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:268:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [726.326398] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:506:DDI A/PHY A] [CRTC:268:pipe B] <7> [726.326636] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [726.326940] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [726.327133] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [726.327263] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [726.327390] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7483046/8388608 link 623587/524288) <7> [726.327515] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [726.327635] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [726.327780] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [726.327905] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [726.328026] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [726.328146] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [726.328266] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [726.328386] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [726.328507] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [726.328628] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1801) <7> [726.328764] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [726.328886] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [726.329008] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1878) <7> [726.329125] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1878) <7> [726.329242] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [726.329363] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [726.329488] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [726.329611] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [726.329741] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [726.329866] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [726.329990] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [726.330111] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1801) <7> [726.330231] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [726.330355] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [726.330478] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1878) <7> [726.330598] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1878) <7> [726.330748] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [726.330871] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [726.330993] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [726.331116] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [726.331241] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [726.331363] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 513820) <7> [726.331485] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 513820) <7> [726.331610] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [726.331768] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in set_context_latency (expected 0, found 1) <7> [726.331899] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:268:pipe B] fastset requirement not met, forcing full modeset <7> [726.332073] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [726.332195] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:268:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [726.332338] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:152:plane 1B] ddb ( 0 - 0) -> ( 0 - 4001), size 0 -> 4001 <7> [726.332458] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:262:cursor B] ddb ( 0 - 0) -> (4001 - 4096), size 0 -> 95 <7> [726.332579] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:152: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> [726.332719] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:152:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 16, 16, 19, 19, 28, 0, 0, 0, 4, 0 <7> [726.332842] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:152:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 365, 365, 434, 434, 638, 0, 0, 197, 92, 197 <7> [726.332964] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:152:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 547, 547, 729, 0, 0, 198, 183, 198 <7> [726.333111] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:268:pipe B] data rate 2055280 num active planes 1 <7> [726.333243] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200 <7> [726.333368] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [726.333489] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [726.333612] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [726.333751] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159 <7> [726.333879] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:268:pipe B] min cdclk: 0 kHz -> 256910 kHz <7> [726.334038] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Can change cdclk via squashing <7> [726.334163] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 307200 kHz, actual 307200 kHz <7> [726.334288] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [726.334438] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:268:pipe B] allocated DPLL 0 <7> [726.334566] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:268:pipe B] reserving DPLL 0 <7> [726.334703] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:268:pipe B] enable: yes [modeset] <7> [726.334831] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [726.334955] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [726.335076] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [726.335195] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [726.335316] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [726.335437] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [726.335558] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m_n: lanes: 4; data_m: 7483046, data_n: 8388608, link_m: 623587, link_n: 524288, tu: 64 <7> [726.335689] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [726.335813] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled <7> [726.335935] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled <7> [726.336056] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [726.336180] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum HBlank: 0 <7> [726.336302] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [726.336422] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] DP SDP: VSC, revision 4, length 14 <7> [726.336541] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB <7> [726.336662] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB <7> [726.336801] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0 <7> [726.336922] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range <7> [726.337040] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined <7> [726.337160] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1 <7> [726.337277] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 1 <7> [726.337394] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1878, vmax: 1878, flipline: 1878, pipeline full: 0, guardband: 76 vsync start: 75, vsync end: 69 <7> [726.337515] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1878, vmax vtotal: 1878 <7> [726.337637] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [726.337787] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa <7> [726.337911] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa <7> [726.338038] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1801-1878 vs=1803-1809 vt=1878, flags=0xa <7> [726.338163] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x40 0xa <7> [726.338287] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1801-1878 vs=1803-1809 vt=1878, flags=0xa <7> [726.338411] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 513820, min cdclk 256910 <7> [726.338533] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 48, ips linetime: 0 <7> [726.338653] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [726.338798] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [726.338921] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [726.339047] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [726.339169] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] c10pll_hw_state: fracen: no, <7> [726.339289] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] multiplier: 225, tx_clk_div: 1. <7> [726.339409] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] c10pll_rawhw_state: <7> [726.339527] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] tx: 0x10, cmn: 0x21 <7> [726.339646] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [726.339808] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [726.339932] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [726.340057] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [726.340177] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [726.340300] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [726.340421] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [726.340543] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [726.340666] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [726.340814] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [726.340936] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [726.341060] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [726.341180] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [726.341300] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [726.341420] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [726.341539] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [726.341665] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [726.341816] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [726.341939] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:152:plane 1B] fb: [FB:564] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [726.342063] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [726.342183] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [726.342302] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:182:plane 2B] fb: [NOFB], visible: no <7> [726.342421] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:212:plane 3B] fb: [NOFB], visible: no <7> [726.342543] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:242:plane 4B] fb: [NOFB], visible: no <7> [726.342670] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:252:plane 5B] fb: [NOFB], visible: no <7> [726.342812] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:262:cursor B] fb: [NOFB], visible: no <7> [726.343781] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off <7> [726.344392] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6 <7> [726.344924] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02 <7> [726.345469] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off <7> [726.345643] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00 <7> [726.346023] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [726.346195] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_B <7> [726.346387] i915 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [i915]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [726.346533] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 307200 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [726.346710] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=768 <7> [726.346837] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:506:DDI A/PHY A] <7> [726.346965] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:515:DDI B/PHY B] <7> [726.347085] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:517:DP-MST A] <7> [726.347211] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DP-MST B] <7> [726.347338] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:519:DP-MST C] <7> [726.347458] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST D] <7> [726.347576] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:533:DDI TC1/PHY TC1] <7> [726.347833] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DP-MST A] <7> [726.347950] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST B] <7> [726.348066] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST C] <7> [726.348182] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST D] <7> [726.348296] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:542:DDI TC2/PHY TC2] <7> [726.348418] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:546:DDI TC3/PHY TC3] <7> [726.348540] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST A] <7> [726.348662] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST B] <7> [726.348803] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST C] <7> [726.348925] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST D] <7> [726.349044] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:555:DDI TC4/PHY TC4] <7> [726.349163] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:557:DP-MST A] <7> [726.349279] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:558:DP-MST B] <7> [726.349394] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:559:DP-MST C] <7> [726.349511] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:560:DP-MST D] <7> [726.349657] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0xf <7> [726.349898] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: no -> yes (pipe: *) <7> [726.350028] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 4 (mbus joined: yes) <7> [726.350218] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A <7> [726.351597] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:268:pipe B] <7> [726.351756] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0 <7> [726.353365] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 turn panel power on <7> [726.353531] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 wait for panel power cycle (463 ms remaining) <7> [726.824233] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [726.890255] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [726.890960] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 wait for panel power on <7> [726.891583] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [726.923239] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010 <7> [726.923822] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:506:DDI A/PHY A] - long <7> [726.924331] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [726.924977] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:506:DDI A/PHY A] <7> [727.093578] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [727.094362] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 turning VDD on <7> [727.094997] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [727.098132] i915 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c4 41 00 00 01 c0 02 00 00 00 00 0b 80 <7> [727.099274] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:507:eDP-1][ENCODER:506:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [727.099921] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:507:eDP-1][ENCODER:506:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 06 <7> [727.101047] i915 0000:00:02.0: [drm:intel_dp_set_signal_levels [i915]] [CONNECTOR:507:eDP-1][ENCODER:506:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [727.101928] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:507:eDP-1][ENCODER:506:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [727.102958] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:507:eDP-1][ENCODER:506:DDI A/PHY A][DPRX] Clock recovery OK <7> [727.103080] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:507:eDP-1][ENCODER:506:DDI A/PHY A][DPRX] Using DP training pattern TPS3 <7> [727.104385] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:507:eDP-1][ENCODER:506:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [727.104495] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:507:eDP-1][ENCODER:506:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [727.105170] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [727.105433] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]] <7> [727.105547] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe B <7> [727.105711] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:507:eDP-1] set backlight PWM = 13892 <7> [727.116828] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR2 <7> [727.118355] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:507:eDP-1] <7> [727.118556] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:268:pipe B] <7> [729.680759] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 turning VDD off <7> [729.681325] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:506:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [731.223930] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off <7> [731.224464] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6 <7> [731.224960] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02 <6> [731.659862] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

5.70 seconds

Hostname

shard-mtlp-3

Igt-Version

IGT-Version: 2.3-g4987fcaab (x86_64) (Linux: 6.19.0-CI_DRM_18010-g84d640df1ee7+ x86_64)

Out

Starting dynamic subtest: B-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c: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 (5.699s)

Err

Starting dynamic subtest: B-eDP1
(kms_flip:2981) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2981) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.645813
last_received_ts = 698.645691
last_seq = 937
current_ts = 698.656921
current_received_ts = 698.656860
current_seq = 938
count = 245
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 14us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.656921
last_received_ts = 698.656860
last_seq = 938
current_ts = 698.668030
current_received_ts = 698.667969
current_seq = 939
count = 246
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.668030
last_received_ts = 698.667969
last_seq = 939
current_ts = 698.679138
current_received_ts = 698.679077
current_seq = 940
count = 247
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.679138
last_received_ts = 698.679077
last_seq = 940
current_ts = 698.690247
current_received_ts = 698.690125
current_seq = 941
count = 248
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.690247
last_received_ts = 698.690125
last_seq = 941
current_ts = 698.701355
current_received_ts = 698.701233
current_seq = 942
count = 249
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.701355
last_received_ts = 698.701233
last_seq = 942
current_ts = 698.712463
current_received_ts = 698.712402
current_seq = 943
count = 250
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.712463
last_received_ts = 698.712402
last_seq = 943
current_ts = 698.723572
current_received_ts = 698.723450
current_seq = 944
count = 251
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.723572
last_received_ts = 698.723450
last_seq = 944
current_ts = 698.734680
current_received_ts = 698.734497
current_seq = 945
count = 252
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 10us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.734680
last_received_ts = 698.734497
last_seq = 945
current_ts = 698.745789
current_received_ts = 698.745728
current_seq = 946
count = 253
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 12us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.745789
last_received_ts = 698.745728
last_seq = 946
current_ts = 698.756897
current_received_ts = 698.756836
current_seq = 947
count = 254
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.756897
last_received_ts = 698.756836
last_seq = 947
current_ts = 698.768005
current_received_ts = 698.767944
current_seq = 948
count = 255
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.768005
last_received_ts = 698.767944
last_seq = 948
current_ts = 698.779114
current_received_ts = 698.779053
current_seq = 949
count = 256
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.779114
last_received_ts = 698.779053
last_seq = 949
current_ts = 698.790222
current_received_ts = 698.790161
current_seq = 950
count = 257
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.790222
last_received_ts = 698.790161
last_seq = 950
current_ts = 698.801331
current_received_ts = 698.801208
current_seq = 951
count = 258
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.801331
last_received_ts = 698.801208
last_seq = 951
current_ts = 698.812439
current_received_ts = 698.812378
current_seq = 952
count = 259
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.812439
last_received_ts = 698.812378
last_seq = 952
current_ts = 698.823547
current_received_ts = 698.823364
current_seq = 953
count = 260
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.823547
last_received_ts = 698.823364
last_seq = 953
current_ts = 698.834656
current_received_ts = 698.834473
current_seq = 954
count = 261
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.834656
last_received_ts = 698.834473
last_seq = 954
current_ts = 698.845764
current_received_ts = 698.845642
current_seq = 955
count = 262
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.845764
last_received_ts = 698.845642
last_seq = 955
current_ts = 698.856873
current_received_ts = 698.856812
current_seq = 956
count = 263
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.856873
last_received_ts = 698.856812
last_seq = 956
current_ts = 698.867981
current_received_ts = 698.867859
current_seq = 957
count = 264
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.867981
last_received_ts = 698.867859
last_seq = 957
current_ts = 698.879089
current_received_ts = 698.879089
current_seq = 958
count = 265
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.879089
last_received_ts = 698.879089
last_seq = 958
current_ts = 698.890198
current_received_ts = 698.890076
current_seq = 959
count = 266
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.890198
last_received_ts = 698.890076
last_seq = 959
current_ts = 698.901306
current_received_ts = 698.901184
current_seq = 960
count = 267
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.901306
last_received_ts = 698.901184
last_seq = 960
current_ts = 698.912415
current_received_ts = 698.912231
current_seq = 961
count = 268
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.912415
last_received_ts = 698.912231
last_seq = 961
current_ts = 698.923523
current_received_ts = 698.923401
current_seq = 962
count = 269
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.923523
last_received_ts = 698.923401
last_seq = 962
current_ts = 698.934631
current_received_ts = 698.934509
current_seq = 963
count = 270
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.934631
last_received_ts = 698.934509
last_seq = 963
current_ts = 698.945740
current_received_ts = 698.945618
current_seq = 964
count = 271
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.945740
last_received_ts = 698.945618
last_seq = 964
current_ts = 698.956848
current_received_ts = 698.956665
current_seq = 965
count = 272
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 11us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.956848
last_received_ts = 698.956665
last_seq = 965
current_ts = 698.967957
current_received_ts = 698.967896
current_seq = 966
count = 273
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.967957
last_received_ts = 698.967896
last_seq = 966
current_ts = 698.979065
current_received_ts = 698.979065
current_seq = 967
count = 274
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.979065
last_received_ts = 698.979065
last_seq = 967
current_ts = 698.990173
current_received_ts = 698.990112
current_seq = 968
count = 275
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 698.990173
last_received_ts = 698.990112
last_seq = 968
current_ts = 699.001282
current_received_ts = 699.001160
current_seq = 969
count = 276
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.001282
last_received_ts = 699.001160
last_seq = 969
current_ts = 699.012390
current_received_ts = 699.012207
current_seq = 970
count = 277
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.012390
last_received_ts = 699.012207
last_seq = 970
current_ts = 699.023499
current_received_ts = 699.023376
current_seq = 971
count = 278
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 10us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.023499
last_received_ts = 699.023376
last_seq = 971
current_ts = 699.034607
current_received_ts = 699.034424
current_seq = 972
count = 279
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.034607
last_received_ts = 699.034424
last_seq = 972
current_ts = 699.045715
current_received_ts = 699.045654
current_seq = 973
count = 280
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.045715
last_received_ts = 699.045654
last_seq = 973
current_ts = 699.056824
current_received_ts = 699.056702
current_seq = 974
count = 281
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.056824
last_received_ts = 699.056702
last_seq = 974
current_ts = 699.067932
current_received_ts = 699.067871
current_seq = 975
count = 282
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.067932
last_received_ts = 699.067871
last_seq = 975
current_ts = 699.079041
current_received_ts = 699.078979
current_seq = 976
count = 283
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.079041
last_received_ts = 699.078979
last_seq = 976
current_ts = 699.090149
current_received_ts = 699.090088
current_seq = 977
count = 284
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.090149
last_received_ts = 699.090088
last_seq = 977
current_ts = 699.101257
current_received_ts = 699.101135
current_seq = 978
count = 285
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.101257
last_received_ts = 699.101135
last_seq = 978
current_ts = 699.112366
current_received_ts = 699.112244
current_seq = 979
count = 286
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.112366
last_received_ts = 699.112244
last_seq = 979
current_ts = 699.123474
current_received_ts = 699.123291
current_seq = 980
count = 287
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.123474
last_received_ts = 699.123291
last_seq = 980
current_ts = 699.134583
current_received_ts = 699.134460
current_seq = 981
count = 288
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.134583
last_received_ts = 699.134460
last_seq = 981
current_ts = 699.145691
current_received_ts = 699.145508
current_seq = 982
count = 289
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.145691
last_received_ts = 699.145508
last_seq = 982
current_ts = 699.156799
current_received_ts = 699.156738
current_seq = 983
count = 290
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.156799
last_received_ts = 699.156738
last_seq = 983
current_ts = 699.167908
current_received_ts = 699.167664
current_seq = 984
count = 291
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.167908
last_received_ts = 699.167664
last_seq = 984
current_ts = 699.179016
current_received_ts = 699.178894
current_seq = 985
count = 292
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.179016
last_received_ts = 699.178894
last_seq = 985
current_ts = 699.190125
current_received_ts = 699.190063
current_seq = 986
count = 293
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.190125
last_received_ts = 699.190063
last_seq = 986
current_ts = 699.201233
current_received_ts = 699.201172
current_seq = 987
count = 294
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.201233
last_received_ts = 699.201172
last_seq = 987
current_ts = 699.212341
current_received_ts = 699.212219
current_seq = 988
count = 295
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.212341
last_received_ts = 699.212219
last_seq = 988
current_ts = 699.223450
current_received_ts = 699.223328
current_seq = 989
count = 296
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.223450
last_received_ts = 699.223328
last_seq = 989
current_ts = 699.234558
current_received_ts = 699.234375
current_seq = 990
count = 297
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 13us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.234558
last_received_ts = 699.234375
last_seq = 990
current_ts = 699.245667
current_received_ts = 699.245483
current_seq = 991
count = 298
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.245667
last_received_ts = 699.245483
last_seq = 991
current_ts = 699.256775
current_received_ts = 699.256592
current_seq = 992
count = 299
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.256775
last_received_ts = 699.256592
last_seq = 992
current_ts = 699.267883
current_received_ts = 699.267822
current_seq = 993
count = 300
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.267883
last_received_ts = 699.267822
last_seq = 993
current_ts = 699.278992
current_received_ts = 699.278931
current_seq = 994
count = 301
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.278992
last_received_ts = 699.278931
last_seq = 994
current_ts = 699.290100
current_received_ts = 699.290039
current_seq = 995
count = 302
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.290100
last_received_ts = 699.290039
last_seq = 995
current_ts = 699.301208
current_received_ts = 699.301086
current_seq = 996
count = 303
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.301208
last_received_ts = 699.301086
last_seq = 996
current_ts = 699.312317
current_received_ts = 699.312195
current_seq = 997
count = 304
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.312317
last_received_ts = 699.312195
last_seq = 997
current_ts = 699.323425
current_received_ts = 699.323181
current_seq = 998
count = 305
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.323425
last_received_ts = 699.323181
last_seq = 998
current_ts = 699.334534
current_received_ts = 699.334412
current_seq = 999
count = 306
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.334534
last_received_ts = 699.334412
last_seq = 999
current_ts = 699.345642
current_received_ts = 699.345459
current_seq = 1000
count = 307
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.345642
last_received_ts = 699.345459
last_seq = 1000
current_ts = 699.356750
current_received_ts = 699.356628
current_seq = 1001
count = 308
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.356750
last_received_ts = 699.356628
last_seq = 1001
current_ts = 699.367859
current_received_ts = 699.367798
current_seq = 1002
count = 309
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.367859
last_received_ts = 699.367798
last_seq = 1002
current_ts = 699.378967
current_received_ts = 699.378906
current_seq = 1003
count = 310
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.378967
last_received_ts = 699.378906
last_seq = 1003
current_ts = 699.390076
current_received_ts = 699.389893
current_seq = 1004
count = 311
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.390076
last_received_ts = 699.389893
last_seq = 1004
current_ts = 699.401184
current_received_ts = 699.401062
current_seq = 1005
count = 312
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.401184
last_received_ts = 699.401062
last_seq = 1005
current_ts = 699.412292
current_received_ts = 699.412170
current_seq = 1006
count = 313
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.412292
last_received_ts = 699.412170
last_seq = 1006
current_ts = 699.423401
current_received_ts = 699.423218
current_seq = 1007
count = 314
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.423401
last_received_ts = 699.423218
last_seq = 1007
current_ts = 699.434509
current_received_ts = 699.434387
current_seq = 1008
count = 315
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 11us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.434509
last_received_ts = 699.434387
last_seq = 1008
current_ts = 699.445618
current_received_ts = 699.445496
current_seq = 1009
count = 316
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.445618
last_received_ts = 699.445496
last_seq = 1009
current_ts = 699.456726
current_received_ts = 699.456543
current_seq = 1010
count = 317
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.456726
last_received_ts = 699.456543
last_seq = 1010
current_ts = 699.467834
current_received_ts = 699.467773
current_seq = 1011
count = 318
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.467834
last_received_ts = 699.467773
last_seq = 1011
current_ts = 699.478943
current_received_ts = 699.478882
current_seq = 1012
count = 319
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.478943
last_received_ts = 699.478882
last_seq = 1012
current_ts = 699.490051
current_received_ts = 699.490051
current_seq = 1013
count = 320
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.490051
last_received_ts = 699.490051
last_seq = 1013
current_ts = 699.501160
current_received_ts = 699.501099
current_seq = 1014
count = 321
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.501160
last_received_ts = 699.501099
last_seq = 1014
current_ts = 699.512268
current_received_ts = 699.512146
current_seq = 1015
count = 322
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.512268
last_received_ts = 699.512146
last_seq = 1015
current_ts = 699.523376
current_received_ts = 699.523254
current_seq = 1016
count = 323
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.523376
last_received_ts = 699.523254
last_seq = 1016
current_ts = 699.534485
current_received_ts = 699.534363
current_seq = 1017
count = 324
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.534485
last_received_ts = 699.534363
last_seq = 1017
current_ts = 699.545593
current_received_ts = 699.545410
current_seq = 1018
count = 325
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.545593
last_received_ts = 699.545410
last_seq = 1018
current_ts = 699.556702
current_received_ts = 699.556519
current_seq = 1019
count = 326
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.556702
last_received_ts = 699.556519
last_seq = 1019
current_ts = 699.567810
current_received_ts = 699.567627
current_seq = 1020
count = 327
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 14us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.567810
last_received_ts = 699.567627
last_seq = 1020
current_ts = 699.578918
current_received_ts = 699.578857
current_seq = 1021
count = 328
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.578918
last_received_ts = 699.578857
last_seq = 1021
current_ts = 699.590027
current_received_ts = 699.589966
current_seq = 1022
count = 329
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.590027
last_received_ts = 699.589966
last_seq = 1022
current_ts = 699.601135
current_received_ts = 699.601074
current_seq = 1023
count = 330
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.601135
last_received_ts = 699.601074
last_seq = 1023
current_ts = 699.612244
current_received_ts = 699.612183
current_seq = 1024
count = 331
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.612244
last_received_ts = 699.612183
last_seq = 1024
current_ts = 699.623352
current_received_ts = 699.623230
current_seq = 1025
count = 332
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.623352
last_received_ts = 699.623230
last_seq = 1025
current_ts = 699.634460
current_received_ts = 699.634399
current_seq = 1026
count = 333
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.634460
last_received_ts = 699.634399
last_seq = 1026
current_ts = 699.645569
current_received_ts = 699.645386
current_seq = 1027
count = 334
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 10us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.645569
last_received_ts = 699.645386
last_seq = 1027
current_ts = 699.656677
current_received_ts = 699.656494
current_seq = 1028
count = 335
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.656677
last_received_ts = 699.656494
last_seq = 1028
current_ts = 699.667786
current_received_ts = 699.667664
current_seq = 1029
count = 336
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 9us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.667786
last_received_ts = 699.667664
last_seq = 1029
current_ts = 699.678894
current_received_ts = 699.678833
current_seq = 1030
count = 337
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.678894
last_received_ts = 699.678833
last_seq = 1030
current_ts = 699.690002
current_received_ts = 699.689941
current_seq = 1031
count = 338
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.690002
last_received_ts = 699.689941
last_seq = 1031
current_ts = 699.701111
current_received_ts = 699.701050
current_seq = 1032
count = 339
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 11us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.701111
last_received_ts = 699.701050
last_seq = 1032
current_ts = 699.712219
current_received_ts = 699.712158
current_seq = 1033
count = 340
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.712219
last_received_ts = 699.712158
last_seq = 1033
current_ts = 699.723328
current_received_ts = 699.723206
current_seq = 1034
count = 341
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.723328
last_received_ts = 699.723206
last_seq = 1034
current_ts = 699.734436
current_received_ts = 699.734192
current_seq = 1035
count = 342
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.734436
last_received_ts = 699.734192
last_seq = 1035
current_ts = 699.745544
current_received_ts = 699.745422
current_seq = 1036
count = 343
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 15us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.745544
last_received_ts = 699.745422
last_seq = 1036
current_ts = 699.756653
current_received_ts = 699.756470
current_seq = 1037
count = 344
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.756653
last_received_ts = 699.756470
last_seq = 1037
current_ts = 699.767761
current_received_ts = 699.767578
current_seq = 1038
count = 345
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.767761
last_received_ts = 699.767578
last_seq = 1038
current_ts = 699.778870
current_received_ts = 699.778809
current_seq = 1039
count = 346
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.778870
last_received_ts = 699.778809
last_seq = 1039
current_ts = 699.789978
current_received_ts = 699.789917
current_seq = 1040
count = 347
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 12us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.789978
last_received_ts = 699.789917
last_seq = 1040
current_ts = 699.801086
current_received_ts = 699.801025
current_seq = 1041
count = 348
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.801086
last_received_ts = 699.801025
last_seq = 1041
current_ts = 699.812195
current_received_ts = 699.812134
current_seq = 1042
count = 349
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.812195
last_received_ts = 699.812134
last_seq = 1042
current_ts = 699.823303
current_received_ts = 699.823181
current_seq = 1043
count = 350
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.823303
last_received_ts = 699.823181
last_seq = 1043
current_ts = 699.834412
current_received_ts = 699.834229
current_seq = 1044
count = 351
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.834412
last_received_ts = 699.834229
last_seq = 1044
current_ts = 699.845520
current_received_ts = 699.845398
current_seq = 1045
count = 352
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.845520
last_received_ts = 699.845398
last_seq = 1045
current_ts = 699.856628
current_received_ts = 699.856384
current_seq = 1046
count = 353
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.856628
last_received_ts = 699.856384
last_seq = 1046
current_ts = 699.867737
current_received_ts = 699.867554
current_seq = 1047
count = 354
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.867737
last_received_ts = 699.867554
last_seq = 1047
current_ts = 699.878845
current_received_ts = 699.878784
current_seq = 1048
count = 355
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.878845
last_received_ts = 699.878784
last_seq = 1048
current_ts = 699.889954
current_received_ts = 699.889893
current_seq = 1049
count = 356
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.889954
last_received_ts = 699.889893
last_seq = 1049
current_ts = 699.901062
current_received_ts = 699.901001
current_seq = 1050
count = 357
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.901062
last_received_ts = 699.901001
last_seq = 1050
current_ts = 699.912170
current_received_ts = 699.912048
current_seq = 1051
count = 358
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.912170
last_received_ts = 699.912048
last_seq = 1051
current_ts = 699.923279
current_received_ts = 699.923157
current_seq = 1052
count = 359
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.923279
last_received_ts = 699.923157
last_seq = 1052
current_ts = 699.934387
current_received_ts = 699.934265
current_seq = 1053
count = 360
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.934387
last_received_ts = 699.934265
last_seq = 1053
current_ts = 699.945496
current_received_ts = 699.945374
current_seq = 1054
count = 361
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.945496
last_received_ts = 699.945374
last_seq = 1054
current_ts = 699.956604
current_received_ts = 699.956482
current_seq = 1055
count = 362
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.956604
last_received_ts = 699.956482
last_seq = 1055
current_ts = 699.967712
current_received_ts = 699.967468
current_seq = 1056
count = 363
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.967712
last_received_ts = 699.967468
last_seq = 1056
current_ts = 699.978821
current_received_ts = 699.978760
current_seq = 1057
count = 364
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 7us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.978821
last_received_ts = 699.978760
last_seq = 1057
current_ts = 699.989929
current_received_ts = 699.989868
current_seq = 1058
count = 365
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 8us
(kms_flip:2981) DEBUG: name = flip
last_ts = 699.989929
last_received_ts = 699.989868
last_seq = 1058
current_ts = 700.001038
current_received_ts = 700.000977
current_seq = 1059
count = 366
seq_step = 1
(kms_flip:2981) DEBUG: Vblank took 640us
(kms_flip:2981) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2981) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2981) igt_core-INFO: Stack trace:
(kms_flip:2981) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2981) igt_core-INFO:   #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0()
(kms_flip:2981) igt_core-INFO:   #2 ../tests/kms_flip.c:1887 run_test()
(kms_flip:2981) igt_core-INFO:   #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043()
(kms_flip:2981) igt_core-INFO:   #4 ../tests/kms_flip.c:2043 main()
(kms_flip:2981) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2981) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2981) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (5.699s)

Dmesg

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

<7> [725.960252] i915 0000:00:02.0: [drm:intel_dpt_create [i915]] Allocating dpt from smem

<7> [725.960437] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:564]

<7> [725.960514] i915 0000:00:02.0: [drm:intel_dpt_create [i915]] Allocating dpt from smem

<7> [725.960712] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:567]

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

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

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

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

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

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

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

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

<7> [726.034452] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:150:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [726.324857] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:150:pipe A]

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

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

<7> [726.325486] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B]

<7> [726.325610] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:386:pipe C]

<7> [726.325709] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:504:pipe D]

<7> [726.325803] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B]

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

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

<7> [726.326032] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:506:DDI A/PHY A][CRTC:268:pipe B] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 24 min link_bpp 18.0000 max link_bpp 24.0000

<7> [726.326150] i915 0000:00:02.0: [drm:intel_dp_compute_link_config [i915]] DP lane count 4 clock 432000 bpp input 24 compressed 0.0000 HDR no link rate required 1541460 available 1728000

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

<7> [726.326398] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:506:DDI A/PHY A] [CRTC:268:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [726.332338] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:152:plane 1B] ddb ( 0 - 0) -> ( 0 - 4001), size 0 -> 4001

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

<7> [726.332579] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:152: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> [726.332719] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:152:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 16, 16, 19, 19, 28, 0, 0, 0, 4, 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [726.336180] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum HBlank: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [726.338411] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 513820, min cdclk 256910

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

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

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

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

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

<7> [726.339169] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] c10pll_hw_state: fracen: no,

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [727.118556] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:268:pipe B]

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

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

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

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

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

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

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