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

Detail	Value
Duration	4.12 seconds
Hostname	shard-tglu-9
Igt-Version	IGT-Version: 2.3-g4987fcaab (x86_64) (Linux: 6.19.0-CI_DRM_18009-g5cea68971b03+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A1 1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c: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-HDMI-A1: FAIL (4.124s)
Err	Starting dynamic subtest: B-HDMI-A1 (kms_flip:2472) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2472) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-HDMI-A1 failed. ** DEBUG (kms_flip:2472) DEBUG: name = flip last_ts = 468.050110 last_received_ts = 468.049774 last_seq = 950 current_ts = 468.058441 current_received_ts = 468.058228 current_seq = 951 count = 336 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.058441 last_received_ts = 468.058228 last_seq = 951 current_ts = 468.066772 current_received_ts = 468.066559 current_seq = 952 count = 337 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 468.066772 last_received_ts = 468.066559 last_seq = 952 current_ts = 468.075104 current_received_ts = 468.074860 current_seq = 953 count = 338 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.075104 last_received_ts = 468.074860 last_seq = 953 current_ts = 468.083435 current_received_ts = 468.083130 current_seq = 954 count = 339 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.083435 last_received_ts = 468.083130 last_seq = 954 current_ts = 468.091766 current_received_ts = 468.091522 current_seq = 955 count = 340 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.091766 last_received_ts = 468.091522 last_seq = 955 current_ts = 468.100098 current_received_ts = 468.099792 current_seq = 956 count = 341 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.100098 last_received_ts = 468.099792 last_seq = 956 current_ts = 468.108459 current_received_ts = 468.108246 current_seq = 957 count = 342 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.108459 last_received_ts = 468.108246 last_seq = 957 current_ts = 468.116791 current_received_ts = 468.116486 current_seq = 958 count = 343 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.116791 last_received_ts = 468.116486 last_seq = 958 current_ts = 468.125122 current_received_ts = 468.124878 current_seq = 959 count = 344 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.125122 last_received_ts = 468.124878 last_seq = 959 current_ts = 468.133453 current_received_ts = 468.133148 current_seq = 960 count = 345 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.133453 last_received_ts = 468.133148 last_seq = 960 current_ts = 468.141785 current_received_ts = 468.141541 current_seq = 961 count = 346 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 30us (kms_flip:2472) DEBUG: name = flip last_ts = 468.141785 last_received_ts = 468.141541 last_seq = 961 current_ts = 468.150146 current_received_ts = 468.149811 current_seq = 962 count = 347 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.150146 last_received_ts = 468.149811 last_seq = 962 current_ts = 468.158478 current_received_ts = 468.158142 current_seq = 963 count = 348 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.158478 last_received_ts = 468.158142 last_seq = 963 current_ts = 468.166809 current_received_ts = 468.166473 current_seq = 964 count = 349 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 31us (kms_flip:2472) DEBUG: name = flip last_ts = 468.166809 last_received_ts = 468.166473 last_seq = 964 current_ts = 468.175140 current_received_ts = 468.174805 current_seq = 965 count = 350 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.175140 last_received_ts = 468.174805 last_seq = 965 current_ts = 468.183472 current_received_ts = 468.183167 current_seq = 966 count = 351 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.183472 last_received_ts = 468.183167 last_seq = 966 current_ts = 468.191833 current_received_ts = 468.191559 current_seq = 967 count = 352 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.191833 last_received_ts = 468.191559 last_seq = 967 current_ts = 468.200165 current_received_ts = 468.199829 current_seq = 968 count = 353 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.200165 last_received_ts = 468.199829 last_seq = 968 current_ts = 468.208496 current_received_ts = 468.208160 current_seq = 969 count = 354 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.208496 last_received_ts = 468.208160 last_seq = 969 current_ts = 468.216827 current_received_ts = 468.216583 current_seq = 970 count = 355 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.216827 last_received_ts = 468.216583 last_seq = 970 current_ts = 468.225159 current_received_ts = 468.224915 current_seq = 971 count = 356 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.225159 last_received_ts = 468.224915 last_seq = 971 current_ts = 468.233521 current_received_ts = 468.233215 current_seq = 972 count = 357 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 468.233521 last_received_ts = 468.233215 last_seq = 972 current_ts = 468.241852 current_received_ts = 468.241516 current_seq = 973 count = 358 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.241852 last_received_ts = 468.241516 last_seq = 973 current_ts = 468.250183 current_received_ts = 468.249878 current_seq = 974 count = 359 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 468.250183 last_received_ts = 468.249878 last_seq = 974 current_ts = 468.258514 current_received_ts = 468.258240 current_seq = 975 count = 360 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.258514 last_received_ts = 468.258240 last_seq = 975 current_ts = 468.266846 current_received_ts = 468.266602 current_seq = 976 count = 361 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.266846 last_received_ts = 468.266602 last_seq = 976 current_ts = 468.275177 current_received_ts = 468.275024 current_seq = 977 count = 362 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 37us (kms_flip:2472) DEBUG: name = flip last_ts = 468.275177 last_received_ts = 468.275024 last_seq = 977 current_ts = 468.283539 current_received_ts = 468.283264 current_seq = 978 count = 363 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.283539 last_received_ts = 468.283264 last_seq = 978 current_ts = 468.291870 current_received_ts = 468.291595 current_seq = 979 count = 364 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.291870 last_received_ts = 468.291595 last_seq = 979 current_ts = 468.300201 current_received_ts = 468.299988 current_seq = 980 count = 365 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 39us (kms_flip:2472) DEBUG: name = flip last_ts = 468.300201 last_received_ts = 468.299988 last_seq = 980 current_ts = 468.308533 current_received_ts = 468.308258 current_seq = 981 count = 366 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.308533 last_received_ts = 468.308258 last_seq = 981 current_ts = 468.316864 current_received_ts = 468.316528 current_seq = 982 count = 367 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.316864 last_received_ts = 468.316528 last_seq = 982 current_ts = 468.325226 current_received_ts = 468.324860 current_seq = 983 count = 368 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.325226 last_received_ts = 468.324860 last_seq = 983 current_ts = 468.333557 current_received_ts = 468.333191 current_seq = 984 count = 369 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 30us (kms_flip:2472) DEBUG: name = flip last_ts = 468.333557 last_received_ts = 468.333191 last_seq = 984 current_ts = 468.341888 current_received_ts = 468.341553 current_seq = 985 count = 370 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.341888 last_received_ts = 468.341553 last_seq = 985 current_ts = 468.350220 current_received_ts = 468.349884 current_seq = 986 count = 371 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.350220 last_received_ts = 468.349884 last_seq = 986 current_ts = 468.358551 current_received_ts = 468.358276 current_seq = 987 count = 372 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.358551 last_received_ts = 468.358276 last_seq = 987 current_ts = 468.366882 current_received_ts = 468.366638 current_seq = 988 count = 373 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.366882 last_received_ts = 468.366638 last_seq = 988 current_ts = 468.375244 current_received_ts = 468.374939 current_seq = 989 count = 374 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 89us (kms_flip:2472) DEBUG: name = flip last_ts = 468.375244 last_received_ts = 468.374939 last_seq = 989 current_ts = 468.383575 current_received_ts = 468.383301 current_seq = 990 count = 375 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.383575 last_received_ts = 468.383301 last_seq = 990 current_ts = 468.391907 current_received_ts = 468.391632 current_seq = 991 count = 376 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.391907 last_received_ts = 468.391632 last_seq = 991 current_ts = 468.400238 current_received_ts = 468.400055 current_seq = 992 count = 377 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.400238 last_received_ts = 468.400055 last_seq = 992 current_ts = 468.408569 current_received_ts = 468.408264 current_seq = 993 count = 378 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.408569 last_received_ts = 468.408264 last_seq = 993 current_ts = 468.416901 current_received_ts = 468.416656 current_seq = 994 count = 379 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 468.416901 last_received_ts = 468.416656 last_seq = 994 current_ts = 468.425262 current_received_ts = 468.425079 current_seq = 995 count = 380 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.425262 last_received_ts = 468.425079 last_seq = 995 current_ts = 468.433594 current_received_ts = 468.433319 current_seq = 996 count = 381 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.433594 last_received_ts = 468.433319 last_seq = 996 current_ts = 468.441925 current_received_ts = 468.441681 current_seq = 997 count = 382 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 468.441925 last_received_ts = 468.441681 last_seq = 997 current_ts = 468.450256 current_received_ts = 468.449921 current_seq = 998 count = 383 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 53us (kms_flip:2472) DEBUG: name = flip last_ts = 468.450256 last_received_ts = 468.449921 last_seq = 998 current_ts = 468.458588 current_received_ts = 468.458252 current_seq = 999 count = 384 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 29us (kms_flip:2472) DEBUG: name = flip last_ts = 468.458588 last_received_ts = 468.458252 last_seq = 999 current_ts = 468.466949 current_received_ts = 468.466583 current_seq = 1000 count = 385 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.466949 last_received_ts = 468.466583 last_seq = 1000 current_ts = 468.475281 current_received_ts = 468.475067 current_seq = 1001 count = 386 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.475281 last_received_ts = 468.475067 last_seq = 1001 current_ts = 468.483612 current_received_ts = 468.483337 current_seq = 1002 count = 387 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 39us (kms_flip:2472) DEBUG: name = flip last_ts = 468.483612 last_received_ts = 468.483337 last_seq = 1002 current_ts = 468.491943 current_received_ts = 468.491638 current_seq = 1003 count = 388 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.491943 last_received_ts = 468.491638 last_seq = 1003 current_ts = 468.500305 current_received_ts = 468.499969 current_seq = 1004 count = 389 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 58us (kms_flip:2472) DEBUG: name = flip last_ts = 468.500305 last_received_ts = 468.499969 last_seq = 1004 current_ts = 468.508636 current_received_ts = 468.508301 current_seq = 1005 count = 390 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.508636 last_received_ts = 468.508301 last_seq = 1005 current_ts = 468.516968 current_received_ts = 468.516724 current_seq = 1006 count = 391 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.516968 last_received_ts = 468.516724 last_seq = 1006 current_ts = 468.525299 current_received_ts = 468.525085 current_seq = 1007 count = 392 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.525299 last_received_ts = 468.525085 last_seq = 1007 current_ts = 468.533630 current_received_ts = 468.533356 current_seq = 1008 count = 393 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.533630 last_received_ts = 468.533356 last_seq = 1008 current_ts = 468.541962 current_received_ts = 468.541626 current_seq = 1009 count = 394 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.541962 last_received_ts = 468.541626 last_seq = 1009 current_ts = 468.550293 current_received_ts = 468.549988 current_seq = 1010 count = 395 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 37us (kms_flip:2472) DEBUG: name = flip last_ts = 468.550293 last_received_ts = 468.549988 last_seq = 1010 current_ts = 468.558655 current_received_ts = 468.558319 current_seq = 1011 count = 396 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.558655 last_received_ts = 468.558319 last_seq = 1011 current_ts = 468.566986 current_received_ts = 468.566711 current_seq = 1012 count = 397 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.566986 last_received_ts = 468.566711 last_seq = 1012 current_ts = 468.575317 current_received_ts = 468.575012 current_seq = 1013 count = 398 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.575317 last_received_ts = 468.575012 last_seq = 1013 current_ts = 468.583649 current_received_ts = 468.583374 current_seq = 1014 count = 399 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.583649 last_received_ts = 468.583374 last_seq = 1014 current_ts = 468.592010 current_received_ts = 468.591675 current_seq = 1015 count = 400 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.592010 last_received_ts = 468.591675 last_seq = 1015 current_ts = 468.600342 current_received_ts = 468.600098 current_seq = 1016 count = 401 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.600342 last_received_ts = 468.600098 last_seq = 1016 current_ts = 468.608673 current_received_ts = 468.608398 current_seq = 1017 count = 402 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.608673 last_received_ts = 468.608398 last_seq = 1017 current_ts = 468.617004 current_received_ts = 468.616791 current_seq = 1018 count = 403 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.617004 last_received_ts = 468.616791 last_seq = 1018 current_ts = 468.625336 current_received_ts = 468.625031 current_seq = 1019 count = 404 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.625336 last_received_ts = 468.625031 last_seq = 1019 current_ts = 468.633667 current_received_ts = 468.633331 current_seq = 1020 count = 405 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.633667 last_received_ts = 468.633331 last_seq = 1020 current_ts = 468.642029 current_received_ts = 468.641754 current_seq = 1021 count = 406 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.642029 last_received_ts = 468.641754 last_seq = 1021 current_ts = 468.650360 current_received_ts = 468.650177 current_seq = 1022 count = 407 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 468.650360 last_received_ts = 468.650177 last_seq = 1022 current_ts = 468.658691 current_received_ts = 468.658417 current_seq = 1023 count = 408 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.658691 last_received_ts = 468.658417 last_seq = 1023 current_ts = 468.667023 current_received_ts = 468.666687 current_seq = 1024 count = 409 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.667023 last_received_ts = 468.666687 last_seq = 1024 current_ts = 468.675354 current_received_ts = 468.675171 current_seq = 1025 count = 410 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.675354 last_received_ts = 468.675171 last_seq = 1025 current_ts = 468.683716 current_received_ts = 468.683411 current_seq = 1026 count = 411 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.683716 last_received_ts = 468.683411 last_seq = 1026 current_ts = 468.692047 current_received_ts = 468.691833 current_seq = 1027 count = 412 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.692047 last_received_ts = 468.691833 last_seq = 1027 current_ts = 468.700378 current_received_ts = 468.700073 current_seq = 1028 count = 413 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.700378 last_received_ts = 468.700073 last_seq = 1028 current_ts = 468.708710 current_received_ts = 468.708496 current_seq = 1029 count = 414 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.708710 last_received_ts = 468.708496 last_seq = 1029 current_ts = 468.717041 current_received_ts = 468.716705 current_seq = 1030 count = 415 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.717041 last_received_ts = 468.716705 last_seq = 1030 current_ts = 468.725372 current_received_ts = 468.725067 current_seq = 1031 count = 416 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.725372 last_received_ts = 468.725067 last_seq = 1031 current_ts = 468.733734 current_received_ts = 468.733459 current_seq = 1032 count = 417 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 468.733734 last_received_ts = 468.733459 last_seq = 1032 current_ts = 468.742065 current_received_ts = 468.741730 current_seq = 1033 count = 418 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.742065 last_received_ts = 468.741730 last_seq = 1033 current_ts = 468.750397 current_received_ts = 468.750092 current_seq = 1034 count = 419 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 468.750397 last_received_ts = 468.750092 last_seq = 1034 current_ts = 468.758728 current_received_ts = 468.758453 current_seq = 1035 count = 420 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.758728 last_received_ts = 468.758453 last_seq = 1035 current_ts = 468.767059 current_received_ts = 468.766846 current_seq = 1036 count = 421 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.767059 last_received_ts = 468.766846 last_seq = 1036 current_ts = 468.775391 current_received_ts = 468.775085 current_seq = 1037 count = 422 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.775391 last_received_ts = 468.775085 last_seq = 1037 current_ts = 468.783752 current_received_ts = 468.783417 current_seq = 1038 count = 423 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 468.783752 last_received_ts = 468.783417 last_seq = 1038 current_ts = 468.792084 current_received_ts = 468.791840 current_seq = 1039 count = 424 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.792084 last_received_ts = 468.791840 last_seq = 1039 current_ts = 468.800415 current_received_ts = 468.800110 current_seq = 1040 count = 425 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.800415 last_received_ts = 468.800110 last_seq = 1040 current_ts = 468.808746 current_received_ts = 468.808411 current_seq = 1041 count = 426 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.808746 last_received_ts = 468.808411 last_seq = 1041 current_ts = 468.817108 current_received_ts = 468.816772 current_seq = 1042 count = 427 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 468.817108 last_received_ts = 468.816772 last_seq = 1042 current_ts = 468.825439 current_received_ts = 468.825256 current_seq = 1043 count = 428 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.825439 last_received_ts = 468.825256 last_seq = 1043 current_ts = 468.833771 current_received_ts = 468.833527 current_seq = 1044 count = 429 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.833771 last_received_ts = 468.833527 last_seq = 1044 current_ts = 468.842102 current_received_ts = 468.841858 current_seq = 1045 count = 430 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.842102 last_received_ts = 468.841858 last_seq = 1045 current_ts = 468.850433 current_received_ts = 468.850128 current_seq = 1046 count = 431 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.850433 last_received_ts = 468.850128 last_seq = 1046 current_ts = 468.858765 current_received_ts = 468.858429 current_seq = 1047 count = 432 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.858765 last_received_ts = 468.858429 last_seq = 1047 current_ts = 468.867126 current_received_ts = 468.866791 current_seq = 1048 count = 433 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.867126 last_received_ts = 468.866791 last_seq = 1048 current_ts = 468.875458 current_received_ts = 468.875153 current_seq = 1049 count = 434 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.875458 last_received_ts = 468.875153 last_seq = 1049 current_ts = 468.883789 current_received_ts = 468.883453 current_seq = 1050 count = 435 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.883789 last_received_ts = 468.883453 last_seq = 1050 current_ts = 468.892120 current_received_ts = 468.891785 current_seq = 1051 count = 436 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.892120 last_received_ts = 468.891785 last_seq = 1051 current_ts = 468.900452 current_received_ts = 468.900238 current_seq = 1052 count = 437 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 31us (kms_flip:2472) DEBUG: name = flip last_ts = 468.900452 last_received_ts = 468.900238 last_seq = 1052 current_ts = 468.908783 current_received_ts = 468.908539 current_seq = 1053 count = 438 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.908783 last_received_ts = 468.908539 last_seq = 1053 current_ts = 468.917145 current_received_ts = 468.916870 current_seq = 1054 count = 439 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.917145 last_received_ts = 468.916870 last_seq = 1054 current_ts = 468.925476 current_received_ts = 468.925171 current_seq = 1055 count = 440 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 468.925476 last_received_ts = 468.925171 last_seq = 1055 current_ts = 468.933807 current_received_ts = 468.933472 current_seq = 1056 count = 441 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.933807 last_received_ts = 468.933472 last_seq = 1056 current_ts = 468.942139 current_received_ts = 468.941895 current_seq = 1057 count = 442 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.942139 last_received_ts = 468.941895 last_seq = 1057 current_ts = 468.950470 current_received_ts = 468.950165 current_seq = 1058 count = 443 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 468.950470 last_received_ts = 468.950165 last_seq = 1058 current_ts = 468.958801 current_received_ts = 468.958588 current_seq = 1059 count = 444 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 34us (kms_flip:2472) DEBUG: name = flip last_ts = 468.958801 last_received_ts = 468.958588 last_seq = 1059 current_ts = 468.967163 current_received_ts = 468.966919 current_seq = 1060 count = 445 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 70us (kms_flip:2472) DEBUG: name = flip last_ts = 468.967163 last_received_ts = 468.966919 last_seq = 1060 current_ts = 468.975494 current_received_ts = 468.975281 current_seq = 1061 count = 446 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.975494 last_received_ts = 468.975281 last_seq = 1061 current_ts = 468.983826 current_received_ts = 468.983521 current_seq = 1062 count = 447 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 32us (kms_flip:2472) DEBUG: name = flip last_ts = 468.983826 last_received_ts = 468.983521 last_seq = 1062 current_ts = 468.992157 current_received_ts = 468.991852 current_seq = 1063 count = 448 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 468.992157 last_received_ts = 468.991852 last_seq = 1063 current_ts = 469.000488 current_received_ts = 469.000244 current_seq = 1064 count = 449 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 469.000488 last_received_ts = 469.000244 last_seq = 1064 current_ts = 469.008850 current_received_ts = 469.008575 current_seq = 1065 count = 450 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 469.008850 last_received_ts = 469.008575 last_seq = 1065 current_ts = 469.017181 current_received_ts = 469.016968 current_seq = 1066 count = 451 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 469.017181 last_received_ts = 469.016968 last_seq = 1066 current_ts = 469.025513 current_received_ts = 469.025177 current_seq = 1067 count = 452 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 469.025513 last_received_ts = 469.025177 last_seq = 1067 current_ts = 469.033844 current_received_ts = 469.033600 current_seq = 1068 count = 453 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 35us (kms_flip:2472) DEBUG: name = flip last_ts = 469.033844 last_received_ts = 469.033600 last_seq = 1068 current_ts = 469.042206 current_received_ts = 469.041992 current_seq = 1069 count = 454 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 36us (kms_flip:2472) DEBUG: name = flip last_ts = 469.042206 last_received_ts = 469.041992 last_seq = 1069 current_ts = 469.050537 current_received_ts = 469.050201 current_seq = 1070 count = 455 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 29us (kms_flip:2472) DEBUG: name = flip last_ts = 469.050537 last_received_ts = 469.050201 last_seq = 1070 current_ts = 469.058868 current_received_ts = 469.058594 current_seq = 1071 count = 456 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 33us (kms_flip:2472) DEBUG: name = flip last_ts = 469.058868 last_received_ts = 469.058594 last_seq = 1071 current_ts = 469.067200 current_received_ts = 469.066956 current_seq = 1072 count = 457 seq_step = 1 (kms_flip:2472) DEBUG: Vblank took 524us (kms_flip:2472) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2472) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2472) igt_core-INFO: Stack trace: (kms_flip:2472) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2472) igt_core-INFO: #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0() (kms_flip:2472) igt_core-INFO: #2 ../tests/kms_flip.c:1887 run_test() (kms_flip:2472) igt_core-INFO: #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043() (kms_flip:2472) igt_core-INFO: #4 ../tests/kms_flip.c:2043 main() (kms_flip:2472) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2472) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2472) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A1: FAIL (4.124s)
Dmesg	<6> [479.418302] [IGT] kms_flip: starting dynamic subtest B-HDMI-A1 <7> [479.419049] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:636] <7> [479.419369] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:637] <7> [479.457263] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:170:pipe A] <7> [479.457381] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [479.457568] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [479.457722] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [479.457874] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [479.458023] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [479.458228] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [479.458466] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [479.458693] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2080, found 0) <7> [479.458915] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [479.459146] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2080, found 0) <7> [479.459328] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1968, found 0) <7> [479.459481] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2000, found 0) <7> [479.459635] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [479.459789] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [479.459968] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [479.460218] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [479.460450] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1144, found 0) <7> [479.460679] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1144, found 0) <7> [479.460897] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [479.461087] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2080, found 0) <7> [479.461263] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [479.461419] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2080, found 0) <7> [479.461573] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1968, found 0) <7> [479.461726] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2000, found 0) <7> [479.461938] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [479.462183] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [479.462410] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [479.462641] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [479.462825] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1144, found 0) <7> [479.462977] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1144, found 0) <7> [479.463147] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [479.463300] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [479.463520] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [479.463747] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [479.463976] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in has_infoframe (expected yes, found no) <7> [479.464218] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [479.464417] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 285500, found 0) <7> [479.464569] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 285500, found 0) <7> [479.464720] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in port_clock (expected 285500, found 0) <7> [479.464874] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [479.465034] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in avi infoframe <7> [479.465281] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [479.465505] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [479.465509] i915 0000:00:02.0: colorspace: RGB <7> [479.465512] i915 0000:00:02.0: scan mode: Underscan <7> [479.465514] i915 0000:00:02.0: colorimetry: No Data <7> [479.465517] i915 0000:00:02.0: picture aspect: No Data <7> [479.465520] i915 0000:00:02.0: active aspect: Same as Picture <7> [479.465523] i915 0000:00:02.0: itc: No Data <7> [479.465525] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [479.465528] i915 0000:00:02.0: quantization range: Full <7> [479.465530] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [479.465533] i915 0000:00:02.0: video code: 0 <7> [479.465535] i915 0000:00:02.0: ycc quantization range: Full <7> [479.465538] i915 0000:00:02.0: hdmi content type: Graphics <7> [479.465541] i915 0000:00:02.0: pixel repeat: 0 <7> [479.465543] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [479.465546] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [479.465776] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in spd infoframe <7> [479.466017] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [479.466258] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [479.466261] i915 0000:00:02.0: vendor: Intel <7> [479.466264] i915 0000:00:02.0: product: Integrated gfx <7> [479.466267] i915 0000:00:02.0: source device information: PC General (0x9) <7> [479.466270] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [479.466449] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:170:pipe A] fastset requirement not met in hdmi infoframe <7> [479.466605] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [479.466762] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [479.466764] i915 0000:00:02.0: empty frame <7> [479.466765] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [479.466921] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:170:pipe A] fastset requirement not met, forcing full modeset <7> [479.467136] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:170:pipe A] releasing DPLL 0 <7> [479.467407] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no <7> [479.467631] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:170:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [479.467910] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:164:cursor A] ddb (1993 - 2048) -> ( 0 - 0), size 55 -> 0 <7> [479.468153] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:170:pipe A] min cdclk: 192000 kHz -> 0 kHz <7> [479.468340] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [479.468497] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz <7> [479.468670] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [479.468905] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:170:pipe A] enable: no [modeset] <7> [479.469145] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:34:plane 1A] fb: [NOFB], visible: no <7> [479.469376] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:64:plane 2A] fb: [NOFB], visible: no <7> [479.469582] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:94:plane 3A] fb: [NOFB], visible: no <7> [479.469740] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:124:plane 4A] fb: [NOFB], visible: no <7> [479.469899] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:134:plane 5A] fb: [NOFB], visible: no <7> [479.470057] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:144:plane 6A] fb: [NOFB], visible: no <7> [479.470288] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:154:plane 7A] fb: [NOFB], visible: no <7> [479.470520] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:164:cursor A] fb: [NOFB], visible: no <7> [479.470873] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:587:HDMI-A-1][ENCODER:586:DDI B/PHY B] Disable audio codec on [CRTC:170:pipe A] <7> [479.480868] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [479.484121] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:587:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10 <7> [479.484679] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [479.484831] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [479.485336] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [479.485558] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:587:HDMI-A-1] Failed to read TMDS config: -6 <7> [479.485582] i915 0000:00:02.0: [drm:intel_ddi_disable [i915]] [CONNECTOR:587:HDMI-A-1] Failed to reset sink scrambling/TMDS bit clock ratio <7> [479.485832] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [479.491120] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [479.491314] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:170:pipe A] <7> [479.491504] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0 <7> [479.491680] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 172800 kHz, VCO 345600 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [479.491940] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:586:DDI B/PHY B] <7> [479.492147] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:596:DDI TC1/PHY TC1] <7> [479.492329] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:598:DP-MST A] <7> [479.492487] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST B] <7> [479.492643] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST C] <7> [479.492803] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST D] <7> [479.492959] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:606:DDI TC2/PHY TC2] <7> [479.493128] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:608:DP-MST A] <7> [479.493343] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST B] <7> [479.493556] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST C] <7> [479.493776] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST D] <7> [479.494000] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:615:DDI TC3/PHY TC3] <7> [479.494241] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:617:DP-MST A] <7> [479.494466] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST B] <7> [479.494691] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST C] <7> [479.494906] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST D] <7> [479.495125] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:624:DDI TC4/PHY TC4] <7> [479.495335] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:626:DP-MST A] <7> [479.495549] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST B] <7> [479.495765] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST C] <7> [479.495986] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST D] <7> [479.496234] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:587:HDMI-A-1] <7> [479.496737] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [479.497044] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_3 <7> [479.497325] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [479.497582] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:170:pipe A] <7> [479.498502] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:308:pipe B] <7> [479.498763] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:446:pipe C] <7> [479.499005] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:584:pipe D] <7> [479.499259] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:308:pipe B] <7> [479.499303] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:587:HDMI-A-1] <7> [479.499412] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:587:HDMI-A-1] Limiting target display pipe bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36) <7> [479.499676] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [479.499908] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:308:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [479.500145] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:586:DDI B/PHY B] [CRTC:308:pipe B] <7> [479.500355] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [479.500585] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [479.500812] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [479.501041] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [479.501277] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [479.501509] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [479.501737] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [479.501964] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2080) <7> [479.502206] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [479.502431] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2080) <7> [479.502643] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1968) <7> [479.502860] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2000) <7> [479.503081] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [479.503326] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [479.503553] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [479.503782] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [479.504010] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1144) <7> [479.504256] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1144) <7> [479.504484] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [479.504704] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2080) <7> [479.504920] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [479.505158] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2080) <7> [479.505381] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1968) <7> [479.505607] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2000) <7> [479.505842] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [479.506063] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [479.506295] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [479.506515] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [479.506731] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1144) <7> [479.506953] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1144) <7> [479.507179] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [479.507398] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [479.507615] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [479.507834] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [479.508060] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in has_infoframe (expected no, found yes) <7> [479.508315] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [479.508531] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 285500) <7> [479.508740] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 285500) <7> [479.508958] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in port_clock (expected 0, found 285500) <7> [479.509188] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [479.509402] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in avi infoframe <7> [479.509639] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [479.509851] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [479.510073] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [479.510077] i915 0000:00:02.0: colorspace: RGB <7> [479.510080] i915 0000:00:02.0: scan mode: Underscan <7> [479.510083] i915 0000:00:02.0: colorimetry: No Data <7> [479.510092] i915 0000:00:02.0: picture aspect: No Data <7> [479.510095] i915 0000:00:02.0: active aspect: Same as Picture <7> [479.510098] i915 0000:00:02.0: itc: No Data <7> [479.510101] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [479.510103] i915 0000:00:02.0: quantization range: Full <7> [479.510106] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [479.510109] i915 0000:00:02.0: video code: 0 <7> [479.510112] i915 0000:00:02.0: ycc quantization range: Full <7> [479.510115] i915 0000:00:02.0: hdmi content type: Graphics <7> [479.510118] i915 0000:00:02.0: pixel repeat: 0 <7> [479.510120] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [479.510123] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in spd infoframe <7> [479.510351] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [479.510573] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [479.510801] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [479.510804] i915 0000:00:02.0: vendor: Intel <7> [479.510807] i915 0000:00:02.0: product: Integrated gfx <7> [479.510810] i915 0000:00:02.0: source device information: PC General (0x9) <7> [479.510813] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:308:pipe B] fastset requirement not met in hdmi infoframe <7> [479.511042] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [479.511272] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [479.511483] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [479.511485] i915 0000:00:02.0: empty frame <7> [479.511489] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:308:pipe B] fastset requirement not met, forcing full modeset <7> [479.511755] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no <7> [479.511977] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:308:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2 <7> [479.512296] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:172:plane 1B] ddb ( 0 - 0) -> ( 0 - 1993), size 0 -> 1993 <7> [479.512507] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:302:cursor B] ddb ( 0 - 0) -> (1993 - 2048), size 0 -> 55 <7> [479.512723] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:172: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> [479.512935] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:172:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 8, 8, 8, 8, 11, 16, 16, 0, 0, 0 <7> [479.513167] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:172:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 129, 129, 129, 129, 177, 257, 257, 30, 0, 0 <7> [479.513390] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:172:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 143, 143, 143, 143, 196, 284, 284, 31, 0, 0 <7> [479.513644] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:308:pipe B] data rate 1142000 num active planes 1 <7> [479.513872] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 14993 required 1142 <7> [479.514094] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [479.514336] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:308:pipe B] min cdclk: 0 kHz -> 192000 kHz <7> [479.514628] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [479.514857] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [479.515072] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [479.515319] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:308:pipe B] allocated DPLL 0 <7> [479.515546] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:308:pipe B] reserving DPLL 0 <7> [479.515774] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:308:pipe B] enable: yes [modeset] <7> [479.516006] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [479.516254] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [479.516470] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [479.516685] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [479.516902] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [479.517132] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [479.517351] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [479.517569] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x0 <7> [479.517798] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [479.517801] i915 0000:00:02.0: colorspace: RGB <7> [479.517804] i915 0000:00:02.0: scan mode: Underscan <7> [479.517807] i915 0000:00:02.0: colorimetry: No Data <7> [479.517810] i915 0000:00:02.0: picture aspect: No Data <7> [479.517813] i915 0000:00:02.0: active aspect: Same as Picture <7> [479.517815] i915 0000:00:02.0: itc: No Data <7> [479.517818] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [479.517820] i915 0000:00:02.0: quantization range: Full <7> [479.517822] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [479.517824] i915 0000:00:02.0: video code: 0 <7> [479.517826] i915 0000:00:02.0: ycc quantization range: Full <7> [479.517828] i915 0000:00:02.0: hdmi content type: Graphics <7> [479.517830] i915 0000:00:02.0: pixel repeat: 0 <7> [479.517832] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [479.517835] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [479.517837] i915 0000:00:02.0: vendor: Intel <7> [479.517839] i915 0000:00:02.0: product: Integrated gfx <7> [479.517842] i915 0000:00:02.0: source device information: PC General (0x9) <7> [479.517844] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [479.517847] i915 0000:00:02.0: empty frame <7> [479.517850] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 0f 00 6d a2 00 7f 00 00 00 00 00 00 00 00 <7> [479.518080] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 0d 82 34 12 66 69 74 48 65 61 64 6c 65 73 73 47 <7> [479.518328] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 53 7f 7f 28 0f 7f 07 17 7f ff 3f 7f ff 47 7f ff <7> [479.518560] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 5f 7f 82 7f 7f 00 7f 7f 51 7f 7f 30 77 7f 03 00 <7> [479.518776] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [479.518990] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [479.519228] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1144, vmax: 1144, flipline: 1144, pipeline full: 61, guardband: 63 vsync start: 0, vsync end: 0 <7> [479.519451] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1081, vmax vblank: 1081, vmin vtotal: 1144, vmax vtotal: 1144 <7> [479.519678] 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> [479.519903] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 <7> [479.520132] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 <7> [479.520360] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5 <7> [479.520589] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x40 0x5 <7> [479.520809] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5 <7> [479.521020] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 285500, pipe src: 1920x1080+0+0, pixel rate 285500, min cdclk 192000 <7> [479.521265] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [479.521483] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [479.521698] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [479.521922] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [479.522156] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1801be, cfgcr1: 0x488, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0 <7> [479.522366] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [479.522576] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [479.522793] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [479.523012] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [479.523242] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [479.523456] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [479.523672] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [479.523895] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [479.524125] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [479.524350] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [479.524568] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [479.524779] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [479.524992] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [479.525226] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:172:plane 1B] fb: [FB:636] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [479.525444] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [479.525674] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [479.525893] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:202:plane 2B] fb: [NOFB], visible: no <7> [479.526121] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:232:plane 3B] fb: [NOFB], visible: no <7> [479.526346] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:262:plane 4B] fb: [NOFB], visible: no <7> [479.526571] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:272:plane 5B] fb: [NOFB], visible: no <7> [479.526797] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:282:plane 6B] fb: [NOFB], visible: no <7> [479.527024] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:292:plane 7B] fb: [NOFB], visible: no <7> [479.527254] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:302:cursor B] fb: [NOFB], visible: no <7> [479.528493] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [479.528702] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_3 <7> [479.528925] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 192000 kHz, VCO 384000 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [479.529202] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:586:DDI B/PHY B] <7> [479.529380] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:596:DDI TC1/PHY TC1] <7> [479.529551] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:598:DP-MST A] <7> [479.529725] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST B] <7> [479.529894] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST C] <7> [479.530060] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST D] <7> [479.530287] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:606:DDI TC2/PHY TC2] <7> [479.530455] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:608:DP-MST A] <7> [479.530622] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST B] <7> [479.530787] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST C] <7> [479.530954] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST D] <7> [479.531137] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:615:DDI TC3/PHY TC3] <7> [479.531302] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:617:DP-MST A] <7> [479.531466] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST B] <7> [479.531630] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST C] <7> [479.531795] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST D] <7> [479.531960] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:624:DDI TC4/PHY TC4] <7> [479.532151] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:626:DP-MST A] <7> [479.532316] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST B] <7> [479.532481] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST C] <7> [479.532645] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST D] <7> [479.532956] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x810 <7> [479.533057] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [479.533348] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:308:pipe B] <7> [479.533514] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0 <7> [479.533741] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B <7> [479.533980] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [479.534090] i915 0000:00:02.0: [drm:pxp_session_work [i915]] PXP: processing event-flags 0x0000000d <7> [479.534748] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:587:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10 <7> [479.535339] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [479.535494] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [479.536035] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [479.536223] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:587:HDMI-A-1] Failed to read TMDS config: -6 <7> [479.536245] i915 0000:00:02.0: [drm:intel_ddi_enable [i915]] [CONNECTOR:587:HDMI-A-1] Failed to configure sink scrambling/TMDS bit clock ratio <7> [479.537661] azx_init_pci: snd_hda_intel 0000:00:1f.3: Clearing TCSEL <7> [479.537698] azx_init_pci: snd_hda_intel 0000:00:1f.3: SCH snoop: Enabled <7> [479.544860] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:587:HDMI-A-1][ENCODER:586:DDI B/PHY B] Enable audio codec on [CRTC:308:pipe B], 64 bytes ELD <7> [479.553191] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] HDMI audio pixel clock setting for 285500 not found, falling back to defaults <7> [479.553383] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000) <7> [479.553540] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <6> [479.553703] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 5 not expected <6> [479.553706] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 0 not expected <6> [479.553708] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 10 not expected <6> [479.553709] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 6 not expected <7> [479.553840] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:587:HDMI-A-1] <7> [479.554112] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:308:pipe B] <7> [479.555960] i915 0000:00:02.0: [drm:pxp_session_work [i915]] PXP: processing event-flags 0x0000000a <7> [479.556143] i915 0000:00:02.0: [drm:pxp_session_work [i915]] PXP: creating arb_session after invalidation <7> [479.585599] i915 0000:00:02.0: [drm:pxp_session_work [i915]] PXP ARB session is alive <6> [483.542664] [IGT] kms_flip: finished subtest B-HDMI-A1, FAIL

Detail

Value

Duration

4.12 seconds

Hostname

shard-tglu-9

Igt-Version

IGT-Version: 2.3-g4987fcaab (x86_64) (Linux: 6.19.0-CI_DRM_18009-g5cea68971b03+ x86_64)

Out

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

Err

Starting dynamic subtest: B-HDMI-A1
(kms_flip:2472) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2472) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.050110
last_received_ts = 468.049774
last_seq = 950
current_ts = 468.058441
current_received_ts = 468.058228
current_seq = 951
count = 336
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.058441
last_received_ts = 468.058228
last_seq = 951
current_ts = 468.066772
current_received_ts = 468.066559
current_seq = 952
count = 337
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.066772
last_received_ts = 468.066559
last_seq = 952
current_ts = 468.075104
current_received_ts = 468.074860
current_seq = 953
count = 338
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.075104
last_received_ts = 468.074860
last_seq = 953
current_ts = 468.083435
current_received_ts = 468.083130
current_seq = 954
count = 339
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.083435
last_received_ts = 468.083130
last_seq = 954
current_ts = 468.091766
current_received_ts = 468.091522
current_seq = 955
count = 340
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.091766
last_received_ts = 468.091522
last_seq = 955
current_ts = 468.100098
current_received_ts = 468.099792
current_seq = 956
count = 341
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.100098
last_received_ts = 468.099792
last_seq = 956
current_ts = 468.108459
current_received_ts = 468.108246
current_seq = 957
count = 342
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.108459
last_received_ts = 468.108246
last_seq = 957
current_ts = 468.116791
current_received_ts = 468.116486
current_seq = 958
count = 343
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.116791
last_received_ts = 468.116486
last_seq = 958
current_ts = 468.125122
current_received_ts = 468.124878
current_seq = 959
count = 344
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.125122
last_received_ts = 468.124878
last_seq = 959
current_ts = 468.133453
current_received_ts = 468.133148
current_seq = 960
count = 345
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.133453
last_received_ts = 468.133148
last_seq = 960
current_ts = 468.141785
current_received_ts = 468.141541
current_seq = 961
count = 346
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 30us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.141785
last_received_ts = 468.141541
last_seq = 961
current_ts = 468.150146
current_received_ts = 468.149811
current_seq = 962
count = 347
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.150146
last_received_ts = 468.149811
last_seq = 962
current_ts = 468.158478
current_received_ts = 468.158142
current_seq = 963
count = 348
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.158478
last_received_ts = 468.158142
last_seq = 963
current_ts = 468.166809
current_received_ts = 468.166473
current_seq = 964
count = 349
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 31us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.166809
last_received_ts = 468.166473
last_seq = 964
current_ts = 468.175140
current_received_ts = 468.174805
current_seq = 965
count = 350
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.175140
last_received_ts = 468.174805
last_seq = 965
current_ts = 468.183472
current_received_ts = 468.183167
current_seq = 966
count = 351
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.183472
last_received_ts = 468.183167
last_seq = 966
current_ts = 468.191833
current_received_ts = 468.191559
current_seq = 967
count = 352
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.191833
last_received_ts = 468.191559
last_seq = 967
current_ts = 468.200165
current_received_ts = 468.199829
current_seq = 968
count = 353
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.200165
last_received_ts = 468.199829
last_seq = 968
current_ts = 468.208496
current_received_ts = 468.208160
current_seq = 969
count = 354
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.208496
last_received_ts = 468.208160
last_seq = 969
current_ts = 468.216827
current_received_ts = 468.216583
current_seq = 970
count = 355
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.216827
last_received_ts = 468.216583
last_seq = 970
current_ts = 468.225159
current_received_ts = 468.224915
current_seq = 971
count = 356
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.225159
last_received_ts = 468.224915
last_seq = 971
current_ts = 468.233521
current_received_ts = 468.233215
current_seq = 972
count = 357
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.233521
last_received_ts = 468.233215
last_seq = 972
current_ts = 468.241852
current_received_ts = 468.241516
current_seq = 973
count = 358
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.241852
last_received_ts = 468.241516
last_seq = 973
current_ts = 468.250183
current_received_ts = 468.249878
current_seq = 974
count = 359
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.250183
last_received_ts = 468.249878
last_seq = 974
current_ts = 468.258514
current_received_ts = 468.258240
current_seq = 975
count = 360
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.258514
last_received_ts = 468.258240
last_seq = 975
current_ts = 468.266846
current_received_ts = 468.266602
current_seq = 976
count = 361
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.266846
last_received_ts = 468.266602
last_seq = 976
current_ts = 468.275177
current_received_ts = 468.275024
current_seq = 977
count = 362
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 37us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.275177
last_received_ts = 468.275024
last_seq = 977
current_ts = 468.283539
current_received_ts = 468.283264
current_seq = 978
count = 363
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.283539
last_received_ts = 468.283264
last_seq = 978
current_ts = 468.291870
current_received_ts = 468.291595
current_seq = 979
count = 364
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.291870
last_received_ts = 468.291595
last_seq = 979
current_ts = 468.300201
current_received_ts = 468.299988
current_seq = 980
count = 365
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 39us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.300201
last_received_ts = 468.299988
last_seq = 980
current_ts = 468.308533
current_received_ts = 468.308258
current_seq = 981
count = 366
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.308533
last_received_ts = 468.308258
last_seq = 981
current_ts = 468.316864
current_received_ts = 468.316528
current_seq = 982
count = 367
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.316864
last_received_ts = 468.316528
last_seq = 982
current_ts = 468.325226
current_received_ts = 468.324860
current_seq = 983
count = 368
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.325226
last_received_ts = 468.324860
last_seq = 983
current_ts = 468.333557
current_received_ts = 468.333191
current_seq = 984
count = 369
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 30us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.333557
last_received_ts = 468.333191
last_seq = 984
current_ts = 468.341888
current_received_ts = 468.341553
current_seq = 985
count = 370
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.341888
last_received_ts = 468.341553
last_seq = 985
current_ts = 468.350220
current_received_ts = 468.349884
current_seq = 986
count = 371
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.350220
last_received_ts = 468.349884
last_seq = 986
current_ts = 468.358551
current_received_ts = 468.358276
current_seq = 987
count = 372
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.358551
last_received_ts = 468.358276
last_seq = 987
current_ts = 468.366882
current_received_ts = 468.366638
current_seq = 988
count = 373
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.366882
last_received_ts = 468.366638
last_seq = 988
current_ts = 468.375244
current_received_ts = 468.374939
current_seq = 989
count = 374
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 89us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.375244
last_received_ts = 468.374939
last_seq = 989
current_ts = 468.383575
current_received_ts = 468.383301
current_seq = 990
count = 375
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.383575
last_received_ts = 468.383301
last_seq = 990
current_ts = 468.391907
current_received_ts = 468.391632
current_seq = 991
count = 376
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.391907
last_received_ts = 468.391632
last_seq = 991
current_ts = 468.400238
current_received_ts = 468.400055
current_seq = 992
count = 377
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.400238
last_received_ts = 468.400055
last_seq = 992
current_ts = 468.408569
current_received_ts = 468.408264
current_seq = 993
count = 378
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.408569
last_received_ts = 468.408264
last_seq = 993
current_ts = 468.416901
current_received_ts = 468.416656
current_seq = 994
count = 379
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.416901
last_received_ts = 468.416656
last_seq = 994
current_ts = 468.425262
current_received_ts = 468.425079
current_seq = 995
count = 380
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.425262
last_received_ts = 468.425079
last_seq = 995
current_ts = 468.433594
current_received_ts = 468.433319
current_seq = 996
count = 381
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.433594
last_received_ts = 468.433319
last_seq = 996
current_ts = 468.441925
current_received_ts = 468.441681
current_seq = 997
count = 382
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.441925
last_received_ts = 468.441681
last_seq = 997
current_ts = 468.450256
current_received_ts = 468.449921
current_seq = 998
count = 383
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 53us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.450256
last_received_ts = 468.449921
last_seq = 998
current_ts = 468.458588
current_received_ts = 468.458252
current_seq = 999
count = 384
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 29us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.458588
last_received_ts = 468.458252
last_seq = 999
current_ts = 468.466949
current_received_ts = 468.466583
current_seq = 1000
count = 385
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.466949
last_received_ts = 468.466583
last_seq = 1000
current_ts = 468.475281
current_received_ts = 468.475067
current_seq = 1001
count = 386
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.475281
last_received_ts = 468.475067
last_seq = 1001
current_ts = 468.483612
current_received_ts = 468.483337
current_seq = 1002
count = 387
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 39us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.483612
last_received_ts = 468.483337
last_seq = 1002
current_ts = 468.491943
current_received_ts = 468.491638
current_seq = 1003
count = 388
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.491943
last_received_ts = 468.491638
last_seq = 1003
current_ts = 468.500305
current_received_ts = 468.499969
current_seq = 1004
count = 389
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 58us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.500305
last_received_ts = 468.499969
last_seq = 1004
current_ts = 468.508636
current_received_ts = 468.508301
current_seq = 1005
count = 390
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.508636
last_received_ts = 468.508301
last_seq = 1005
current_ts = 468.516968
current_received_ts = 468.516724
current_seq = 1006
count = 391
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.516968
last_received_ts = 468.516724
last_seq = 1006
current_ts = 468.525299
current_received_ts = 468.525085
current_seq = 1007
count = 392
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.525299
last_received_ts = 468.525085
last_seq = 1007
current_ts = 468.533630
current_received_ts = 468.533356
current_seq = 1008
count = 393
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.533630
last_received_ts = 468.533356
last_seq = 1008
current_ts = 468.541962
current_received_ts = 468.541626
current_seq = 1009
count = 394
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.541962
last_received_ts = 468.541626
last_seq = 1009
current_ts = 468.550293
current_received_ts = 468.549988
current_seq = 1010
count = 395
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 37us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.550293
last_received_ts = 468.549988
last_seq = 1010
current_ts = 468.558655
current_received_ts = 468.558319
current_seq = 1011
count = 396
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.558655
last_received_ts = 468.558319
last_seq = 1011
current_ts = 468.566986
current_received_ts = 468.566711
current_seq = 1012
count = 397
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.566986
last_received_ts = 468.566711
last_seq = 1012
current_ts = 468.575317
current_received_ts = 468.575012
current_seq = 1013
count = 398
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.575317
last_received_ts = 468.575012
last_seq = 1013
current_ts = 468.583649
current_received_ts = 468.583374
current_seq = 1014
count = 399
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.583649
last_received_ts = 468.583374
last_seq = 1014
current_ts = 468.592010
current_received_ts = 468.591675
current_seq = 1015
count = 400
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.592010
last_received_ts = 468.591675
last_seq = 1015
current_ts = 468.600342
current_received_ts = 468.600098
current_seq = 1016
count = 401
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.600342
last_received_ts = 468.600098
last_seq = 1016
current_ts = 468.608673
current_received_ts = 468.608398
current_seq = 1017
count = 402
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.608673
last_received_ts = 468.608398
last_seq = 1017
current_ts = 468.617004
current_received_ts = 468.616791
current_seq = 1018
count = 403
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.617004
last_received_ts = 468.616791
last_seq = 1018
current_ts = 468.625336
current_received_ts = 468.625031
current_seq = 1019
count = 404
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.625336
last_received_ts = 468.625031
last_seq = 1019
current_ts = 468.633667
current_received_ts = 468.633331
current_seq = 1020
count = 405
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.633667
last_received_ts = 468.633331
last_seq = 1020
current_ts = 468.642029
current_received_ts = 468.641754
current_seq = 1021
count = 406
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.642029
last_received_ts = 468.641754
last_seq = 1021
current_ts = 468.650360
current_received_ts = 468.650177
current_seq = 1022
count = 407
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.650360
last_received_ts = 468.650177
last_seq = 1022
current_ts = 468.658691
current_received_ts = 468.658417
current_seq = 1023
count = 408
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.658691
last_received_ts = 468.658417
last_seq = 1023
current_ts = 468.667023
current_received_ts = 468.666687
current_seq = 1024
count = 409
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.667023
last_received_ts = 468.666687
last_seq = 1024
current_ts = 468.675354
current_received_ts = 468.675171
current_seq = 1025
count = 410
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.675354
last_received_ts = 468.675171
last_seq = 1025
current_ts = 468.683716
current_received_ts = 468.683411
current_seq = 1026
count = 411
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.683716
last_received_ts = 468.683411
last_seq = 1026
current_ts = 468.692047
current_received_ts = 468.691833
current_seq = 1027
count = 412
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.692047
last_received_ts = 468.691833
last_seq = 1027
current_ts = 468.700378
current_received_ts = 468.700073
current_seq = 1028
count = 413
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.700378
last_received_ts = 468.700073
last_seq = 1028
current_ts = 468.708710
current_received_ts = 468.708496
current_seq = 1029
count = 414
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.708710
last_received_ts = 468.708496
last_seq = 1029
current_ts = 468.717041
current_received_ts = 468.716705
current_seq = 1030
count = 415
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.717041
last_received_ts = 468.716705
last_seq = 1030
current_ts = 468.725372
current_received_ts = 468.725067
current_seq = 1031
count = 416
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.725372
last_received_ts = 468.725067
last_seq = 1031
current_ts = 468.733734
current_received_ts = 468.733459
current_seq = 1032
count = 417
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.733734
last_received_ts = 468.733459
last_seq = 1032
current_ts = 468.742065
current_received_ts = 468.741730
current_seq = 1033
count = 418
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.742065
last_received_ts = 468.741730
last_seq = 1033
current_ts = 468.750397
current_received_ts = 468.750092
current_seq = 1034
count = 419
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.750397
last_received_ts = 468.750092
last_seq = 1034
current_ts = 468.758728
current_received_ts = 468.758453
current_seq = 1035
count = 420
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.758728
last_received_ts = 468.758453
last_seq = 1035
current_ts = 468.767059
current_received_ts = 468.766846
current_seq = 1036
count = 421
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.767059
last_received_ts = 468.766846
last_seq = 1036
current_ts = 468.775391
current_received_ts = 468.775085
current_seq = 1037
count = 422
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.775391
last_received_ts = 468.775085
last_seq = 1037
current_ts = 468.783752
current_received_ts = 468.783417
current_seq = 1038
count = 423
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.783752
last_received_ts = 468.783417
last_seq = 1038
current_ts = 468.792084
current_received_ts = 468.791840
current_seq = 1039
count = 424
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.792084
last_received_ts = 468.791840
last_seq = 1039
current_ts = 468.800415
current_received_ts = 468.800110
current_seq = 1040
count = 425
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.800415
last_received_ts = 468.800110
last_seq = 1040
current_ts = 468.808746
current_received_ts = 468.808411
current_seq = 1041
count = 426
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.808746
last_received_ts = 468.808411
last_seq = 1041
current_ts = 468.817108
current_received_ts = 468.816772
current_seq = 1042
count = 427
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.817108
last_received_ts = 468.816772
last_seq = 1042
current_ts = 468.825439
current_received_ts = 468.825256
current_seq = 1043
count = 428
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.825439
last_received_ts = 468.825256
last_seq = 1043
current_ts = 468.833771
current_received_ts = 468.833527
current_seq = 1044
count = 429
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.833771
last_received_ts = 468.833527
last_seq = 1044
current_ts = 468.842102
current_received_ts = 468.841858
current_seq = 1045
count = 430
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.842102
last_received_ts = 468.841858
last_seq = 1045
current_ts = 468.850433
current_received_ts = 468.850128
current_seq = 1046
count = 431
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.850433
last_received_ts = 468.850128
last_seq = 1046
current_ts = 468.858765
current_received_ts = 468.858429
current_seq = 1047
count = 432
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.858765
last_received_ts = 468.858429
last_seq = 1047
current_ts = 468.867126
current_received_ts = 468.866791
current_seq = 1048
count = 433
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.867126
last_received_ts = 468.866791
last_seq = 1048
current_ts = 468.875458
current_received_ts = 468.875153
current_seq = 1049
count = 434
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.875458
last_received_ts = 468.875153
last_seq = 1049
current_ts = 468.883789
current_received_ts = 468.883453
current_seq = 1050
count = 435
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.883789
last_received_ts = 468.883453
last_seq = 1050
current_ts = 468.892120
current_received_ts = 468.891785
current_seq = 1051
count = 436
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.892120
last_received_ts = 468.891785
last_seq = 1051
current_ts = 468.900452
current_received_ts = 468.900238
current_seq = 1052
count = 437
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 31us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.900452
last_received_ts = 468.900238
last_seq = 1052
current_ts = 468.908783
current_received_ts = 468.908539
current_seq = 1053
count = 438
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.908783
last_received_ts = 468.908539
last_seq = 1053
current_ts = 468.917145
current_received_ts = 468.916870
current_seq = 1054
count = 439
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.917145
last_received_ts = 468.916870
last_seq = 1054
current_ts = 468.925476
current_received_ts = 468.925171
current_seq = 1055
count = 440
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.925476
last_received_ts = 468.925171
last_seq = 1055
current_ts = 468.933807
current_received_ts = 468.933472
current_seq = 1056
count = 441
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.933807
last_received_ts = 468.933472
last_seq = 1056
current_ts = 468.942139
current_received_ts = 468.941895
current_seq = 1057
count = 442
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.942139
last_received_ts = 468.941895
last_seq = 1057
current_ts = 468.950470
current_received_ts = 468.950165
current_seq = 1058
count = 443
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.950470
last_received_ts = 468.950165
last_seq = 1058
current_ts = 468.958801
current_received_ts = 468.958588
current_seq = 1059
count = 444
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 34us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.958801
last_received_ts = 468.958588
last_seq = 1059
current_ts = 468.967163
current_received_ts = 468.966919
current_seq = 1060
count = 445
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 70us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.967163
last_received_ts = 468.966919
last_seq = 1060
current_ts = 468.975494
current_received_ts = 468.975281
current_seq = 1061
count = 446
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.975494
last_received_ts = 468.975281
last_seq = 1061
current_ts = 468.983826
current_received_ts = 468.983521
current_seq = 1062
count = 447
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 32us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.983826
last_received_ts = 468.983521
last_seq = 1062
current_ts = 468.992157
current_received_ts = 468.991852
current_seq = 1063
count = 448
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 468.992157
last_received_ts = 468.991852
last_seq = 1063
current_ts = 469.000488
current_received_ts = 469.000244
current_seq = 1064
count = 449
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 469.000488
last_received_ts = 469.000244
last_seq = 1064
current_ts = 469.008850
current_received_ts = 469.008575
current_seq = 1065
count = 450
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 469.008850
last_received_ts = 469.008575
last_seq = 1065
current_ts = 469.017181
current_received_ts = 469.016968
current_seq = 1066
count = 451
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 469.017181
last_received_ts = 469.016968
last_seq = 1066
current_ts = 469.025513
current_received_ts = 469.025177
current_seq = 1067
count = 452
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 469.025513
last_received_ts = 469.025177
last_seq = 1067
current_ts = 469.033844
current_received_ts = 469.033600
current_seq = 1068
count = 453
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 35us
(kms_flip:2472) DEBUG: name = flip
last_ts = 469.033844
last_received_ts = 469.033600
last_seq = 1068
current_ts = 469.042206
current_received_ts = 469.041992
current_seq = 1069
count = 454
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 36us
(kms_flip:2472) DEBUG: name = flip
last_ts = 469.042206
last_received_ts = 469.041992
last_seq = 1069
current_ts = 469.050537
current_received_ts = 469.050201
current_seq = 1070
count = 455
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 29us
(kms_flip:2472) DEBUG: name = flip
last_ts = 469.050537
last_received_ts = 469.050201
last_seq = 1070
current_ts = 469.058868
current_received_ts = 469.058594
current_seq = 1071
count = 456
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 33us
(kms_flip:2472) DEBUG: name = flip
last_ts = 469.058868
last_received_ts = 469.058594
last_seq = 1071
current_ts = 469.067200
current_received_ts = 469.066956
current_seq = 1072
count = 457
seq_step = 1
(kms_flip:2472) DEBUG: Vblank took 524us
(kms_flip:2472) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2472) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2472) igt_core-INFO: Stack trace:
(kms_flip:2472) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2472) igt_core-INFO:   #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0()
(kms_flip:2472) igt_core-INFO:   #2 ../tests/kms_flip.c:1887 run_test()
(kms_flip:2472) igt_core-INFO:   #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043()
(kms_flip:2472) igt_core-INFO:   #4 ../tests/kms_flip.c:2043 main()
(kms_flip:2472) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2472) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2472) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (4.124s)

Dmesg

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

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

<7> [479.419369] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:637]

<7> [479.457263] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:170:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [479.497582] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:170:pipe A]

<7> [479.498502] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:308:pipe B]

<7> [479.498763] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:446:pipe C]

<7> [479.499005] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:584:pipe D]

<7> [479.499259] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:308:pipe B]

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

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

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

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

<7> [479.500145] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:586:DDI B/PHY B] [CRTC:308:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [479.512296] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:172:plane 1B] ddb ( 0 - 0) -> ( 0 - 1993), size 0 -> 1993

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

<7> [479.512723] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:172: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> [479.512935] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:172:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 8, 8, 8, 8, 11, 16, 16, 0, 0, 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [479.521020] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 285500, pipe src: 1920x1080+0+0, pixel rate 285500, min cdclk 192000

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [479.534090] i915 0000:00:02.0: [drm:pxp_session_work [i915]] PXP: processing event-flags 0x0000000d

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [479.554112] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:308:pipe B]

<7> [479.555960] i915 0000:00:02.0: [drm:pxp_session_work [i915]] PXP: processing event-flags 0x0000000a

<7> [479.556143] i915 0000:00:02.0: [drm:pxp_session_work [i915]] PXP: creating arb_session after invalidation

<7> [479.585599] i915 0000:00:02.0: [drm:pxp_session_work [i915]] PXP ARB session is alive

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

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