igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a2 on shard-rkl@Patchwork

Detail	Value
Duration	8.68 seconds
Hostname	shard-rkl-7
Igt-Version	IGT-Version: 2.4-g02b0e01dd (x86_64) (Linux: 7.1.0-rc1-Patchwork_165747v1-g0ed5f88da70b+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A2 1920x1080: 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-HDMI-A2: FAIL (8.682s)
Err	Starting dynamic subtest: B-HDMI-A2 (kms_flip:2333) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2333) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2333) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-HDMI-A2 failed. ** DEBUG (kms_flip:2333) DEBUG: Vblank took 35us (kms_flip:2333) DEBUG: name = flip last_ts = 170.197678 last_received_ts = 170.197098 last_seq = 426 current_ts = 170.216721 current_received_ts = 170.216156 current_seq = 427 count = 326 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 32us (kms_flip:2333) DEBUG: name = flip last_ts = 170.216721 last_received_ts = 170.216156 last_seq = 427 current_ts = 170.235733 current_received_ts = 170.235138 current_seq = 428 count = 327 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 33us (kms_flip:2333) DEBUG: name = flip last_ts = 170.235733 last_received_ts = 170.235138 last_seq = 428 current_ts = 170.254776 current_received_ts = 170.254166 current_seq = 429 count = 328 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 35us (kms_flip:2333) DEBUG: name = flip last_ts = 170.254776 last_received_ts = 170.254166 last_seq = 429 current_ts = 170.273788 current_received_ts = 170.273163 current_seq = 430 count = 329 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 33us (kms_flip:2333) DEBUG: name = flip last_ts = 170.273788 last_received_ts = 170.273163 last_seq = 430 current_ts = 170.292816 current_received_ts = 170.292252 current_seq = 431 count = 330 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 32us (kms_flip:2333) DEBUG: name = flip last_ts = 170.292816 last_received_ts = 170.292252 last_seq = 431 current_ts = 170.311844 current_received_ts = 170.311295 current_seq = 432 count = 331 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 31us (kms_flip:2333) DEBUG: name = flip last_ts = 170.311844 last_received_ts = 170.311295 last_seq = 432 current_ts = 170.330872 current_received_ts = 170.330292 current_seq = 433 count = 332 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 29us (kms_flip:2333) DEBUG: name = flip last_ts = 170.330872 last_received_ts = 170.330292 last_seq = 433 current_ts = 170.349899 current_received_ts = 170.349304 current_seq = 434 count = 333 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 27us (kms_flip:2333) DEBUG: name = flip last_ts = 170.349899 last_received_ts = 170.349304 last_seq = 434 current_ts = 170.368912 current_received_ts = 170.368271 current_seq = 435 count = 334 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 27us (kms_flip:2333) DEBUG: name = flip last_ts = 170.368912 last_received_ts = 170.368271 last_seq = 435 current_ts = 170.387955 current_received_ts = 170.387314 current_seq = 436 count = 335 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 31us (kms_flip:2333) DEBUG: name = flip last_ts = 170.387955 last_received_ts = 170.387314 last_seq = 436 current_ts = 170.406982 current_received_ts = 170.406387 current_seq = 437 count = 336 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 32us (kms_flip:2333) DEBUG: name = flip last_ts = 170.406982 last_received_ts = 170.406387 last_seq = 437 current_ts = 170.425995 current_received_ts = 170.425385 current_seq = 438 count = 337 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 33us (kms_flip:2333) DEBUG: name = flip last_ts = 170.425995 last_received_ts = 170.425385 last_seq = 438 current_ts = 170.445038 current_received_ts = 170.444458 current_seq = 439 count = 338 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 32us (kms_flip:2333) DEBUG: name = flip last_ts = 170.445038 last_received_ts = 170.444458 last_seq = 439 current_ts = 170.464066 current_received_ts = 170.463501 current_seq = 440 count = 339 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 48us (kms_flip:2333) DEBUG: name = flip last_ts = 170.464066 last_received_ts = 170.463501 last_seq = 440 current_ts = 170.483093 current_received_ts = 170.482483 current_seq = 441 count = 340 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 170.483093 last_received_ts = 170.482483 last_seq = 441 current_ts = 170.502106 current_received_ts = 170.501526 current_seq = 442 count = 341 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 33us (kms_flip:2333) DEBUG: name = flip last_ts = 170.502106 last_received_ts = 170.501526 last_seq = 442 current_ts = 170.521133 current_received_ts = 170.520538 current_seq = 443 count = 342 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 170.521133 last_received_ts = 170.520538 last_seq = 443 current_ts = 170.540161 current_received_ts = 170.539551 current_seq = 444 count = 343 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 33us (kms_flip:2333) DEBUG: name = flip last_ts = 170.540161 last_received_ts = 170.539551 last_seq = 444 current_ts = 170.559204 current_received_ts = 170.558685 current_seq = 445 count = 344 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 170.559204 last_received_ts = 170.558685 last_seq = 445 current_ts = 170.578217 current_received_ts = 170.577667 current_seq = 446 count = 345 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 35us (kms_flip:2333) DEBUG: name = flip last_ts = 170.578217 last_received_ts = 170.577667 last_seq = 446 current_ts = 170.597244 current_received_ts = 170.596634 current_seq = 447 count = 346 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 31us (kms_flip:2333) DEBUG: name = flip last_ts = 170.597244 last_received_ts = 170.596634 last_seq = 447 current_ts = 170.616272 current_received_ts = 170.615677 current_seq = 448 count = 347 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 31us (kms_flip:2333) DEBUG: name = flip last_ts = 170.616272 last_received_ts = 170.615677 last_seq = 448 current_ts = 170.635300 current_received_ts = 170.634796 current_seq = 449 count = 348 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 31us (kms_flip:2333) DEBUG: name = flip last_ts = 170.635300 last_received_ts = 170.634796 last_seq = 449 current_ts = 170.654327 current_received_ts = 170.653717 current_seq = 450 count = 349 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 35us (kms_flip:2333) DEBUG: name = flip last_ts = 170.654327 last_received_ts = 170.653717 last_seq = 450 current_ts = 170.673340 current_received_ts = 170.672729 current_seq = 451 count = 350 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 33us (kms_flip:2333) DEBUG: name = flip last_ts = 170.673340 last_received_ts = 170.672729 last_seq = 451 current_ts = 170.692368 current_received_ts = 170.691833 current_seq = 452 count = 351 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 27us (kms_flip:2333) DEBUG: name = flip last_ts = 170.692368 last_received_ts = 170.691833 last_seq = 452 current_ts = 170.711395 current_received_ts = 170.710815 current_seq = 453 count = 352 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 33us (kms_flip:2333) DEBUG: name = flip last_ts = 170.711395 last_received_ts = 170.710815 last_seq = 453 current_ts = 170.730438 current_received_ts = 170.729843 current_seq = 454 count = 353 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 170.730438 last_received_ts = 170.729843 last_seq = 454 current_ts = 170.749451 current_received_ts = 170.748947 current_seq = 455 count = 354 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 56us (kms_flip:2333) DEBUG: name = flip last_ts = 170.749451 last_received_ts = 170.748947 last_seq = 455 current_ts = 170.768478 current_received_ts = 170.767899 current_seq = 456 count = 355 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 170.768478 last_received_ts = 170.767899 last_seq = 456 current_ts = 170.787506 current_received_ts = 170.786896 current_seq = 457 count = 356 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 170.787506 last_received_ts = 170.786896 last_seq = 457 current_ts = 170.806549 current_received_ts = 170.805984 current_seq = 458 count = 357 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 69us (kms_flip:2333) DEBUG: name = flip last_ts = 170.806549 last_received_ts = 170.805984 last_seq = 458 current_ts = 170.825577 current_received_ts = 170.824982 current_seq = 459 count = 358 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 170.825577 last_received_ts = 170.824982 last_seq = 459 current_ts = 170.844604 current_received_ts = 170.844025 current_seq = 460 count = 359 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 170.844604 last_received_ts = 170.844025 last_seq = 460 current_ts = 170.863632 current_received_ts = 170.863098 current_seq = 461 count = 360 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 35us (kms_flip:2333) DEBUG: name = flip last_ts = 170.863632 last_received_ts = 170.863098 last_seq = 461 current_ts = 170.882660 current_received_ts = 170.882111 current_seq = 462 count = 361 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 35us (kms_flip:2333) DEBUG: name = flip last_ts = 170.882660 last_received_ts = 170.882111 last_seq = 462 current_ts = 170.901688 current_received_ts = 170.901062 current_seq = 463 count = 362 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 33us (kms_flip:2333) DEBUG: name = flip last_ts = 170.901688 last_received_ts = 170.901062 last_seq = 463 current_ts = 170.920700 current_received_ts = 170.920181 current_seq = 464 count = 363 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 170.920700 last_received_ts = 170.920181 last_seq = 464 current_ts = 170.939728 current_received_ts = 170.939133 current_seq = 465 count = 364 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 170.939728 last_received_ts = 170.939133 last_seq = 465 current_ts = 170.958755 current_received_ts = 170.958221 current_seq = 466 count = 365 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 170.958755 last_received_ts = 170.958221 last_seq = 466 current_ts = 170.977783 current_received_ts = 170.977173 current_seq = 467 count = 366 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 32us (kms_flip:2333) DEBUG: name = flip last_ts = 170.977783 last_received_ts = 170.977173 last_seq = 467 current_ts = 170.996811 current_received_ts = 170.996155 current_seq = 468 count = 367 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 27us (kms_flip:2333) DEBUG: name = flip last_ts = 170.996811 last_received_ts = 170.996155 last_seq = 468 current_ts = 171.015839 current_received_ts = 171.015274 current_seq = 469 count = 368 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.015839 last_received_ts = 171.015274 last_seq = 469 current_ts = 171.034851 current_received_ts = 171.034195 current_seq = 470 count = 369 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 27us (kms_flip:2333) DEBUG: name = flip last_ts = 171.034851 last_received_ts = 171.034195 last_seq = 470 current_ts = 171.053894 current_received_ts = 171.053329 current_seq = 471 count = 370 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.053894 last_received_ts = 171.053329 last_seq = 471 current_ts = 171.072922 current_received_ts = 171.072327 current_seq = 472 count = 371 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 27us (kms_flip:2333) DEBUG: name = flip last_ts = 171.072922 last_received_ts = 171.072327 last_seq = 472 current_ts = 171.091934 current_received_ts = 171.091400 current_seq = 473 count = 372 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 32us (kms_flip:2333) DEBUG: name = flip last_ts = 171.091934 last_received_ts = 171.091400 last_seq = 473 current_ts = 171.110977 current_received_ts = 171.110367 current_seq = 474 count = 373 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.110977 last_received_ts = 171.110367 last_seq = 474 current_ts = 171.129990 current_received_ts = 171.129364 current_seq = 475 count = 374 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 31us (kms_flip:2333) DEBUG: name = flip last_ts = 171.129990 last_received_ts = 171.129364 last_seq = 475 current_ts = 171.149033 current_received_ts = 171.148407 current_seq = 476 count = 375 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 33us (kms_flip:2333) DEBUG: name = flip last_ts = 171.149033 last_received_ts = 171.148407 last_seq = 476 current_ts = 171.168045 current_received_ts = 171.167526 current_seq = 477 count = 376 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 33us (kms_flip:2333) DEBUG: name = flip last_ts = 171.168045 last_received_ts = 171.167526 last_seq = 477 current_ts = 171.187088 current_received_ts = 171.186523 current_seq = 478 count = 377 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.187088 last_received_ts = 171.186523 last_seq = 478 current_ts = 171.206100 current_received_ts = 171.205597 current_seq = 479 count = 378 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 27us (kms_flip:2333) DEBUG: name = flip last_ts = 171.206100 last_received_ts = 171.205597 last_seq = 479 current_ts = 171.225128 current_received_ts = 171.224533 current_seq = 480 count = 379 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 31us (kms_flip:2333) DEBUG: name = flip last_ts = 171.225128 last_received_ts = 171.224533 last_seq = 480 current_ts = 171.244141 current_received_ts = 171.243546 current_seq = 481 count = 380 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 32us (kms_flip:2333) DEBUG: name = flip last_ts = 171.244141 last_received_ts = 171.243546 last_seq = 481 current_ts = 171.263168 current_received_ts = 171.262634 current_seq = 482 count = 381 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 27us (kms_flip:2333) DEBUG: name = flip last_ts = 171.263168 last_received_ts = 171.262634 last_seq = 482 current_ts = 171.282196 current_received_ts = 171.281525 current_seq = 483 count = 382 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 32us (kms_flip:2333) DEBUG: name = flip last_ts = 171.282196 last_received_ts = 171.281525 last_seq = 483 current_ts = 171.301208 current_received_ts = 171.300644 current_seq = 484 count = 383 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 32us (kms_flip:2333) DEBUG: name = flip last_ts = 171.301208 last_received_ts = 171.300644 last_seq = 484 current_ts = 171.320236 current_received_ts = 171.319656 current_seq = 485 count = 384 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.320236 last_received_ts = 171.319656 last_seq = 485 current_ts = 171.339249 current_received_ts = 171.338745 current_seq = 486 count = 385 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 28us (kms_flip:2333) DEBUG: name = flip last_ts = 171.339249 last_received_ts = 171.338745 last_seq = 486 current_ts = 171.358276 current_received_ts = 171.357681 current_seq = 487 count = 386 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.358276 last_received_ts = 171.357681 last_seq = 487 current_ts = 171.377289 current_received_ts = 171.376709 current_seq = 488 count = 387 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.377289 last_received_ts = 171.376709 last_seq = 488 current_ts = 171.396317 current_received_ts = 171.395706 current_seq = 489 count = 388 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 30us (kms_flip:2333) DEBUG: name = flip last_ts = 171.396317 last_received_ts = 171.395706 last_seq = 489 current_ts = 171.415344 current_received_ts = 171.414734 current_seq = 490 count = 389 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.415344 last_received_ts = 171.414734 last_seq = 490 current_ts = 171.434357 current_received_ts = 171.433701 current_seq = 491 count = 390 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 27us (kms_flip:2333) DEBUG: name = flip last_ts = 171.434357 last_received_ts = 171.433701 last_seq = 491 current_ts = 171.453384 current_received_ts = 171.452805 current_seq = 492 count = 391 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.453384 last_received_ts = 171.452805 last_seq = 492 current_ts = 171.472397 current_received_ts = 171.471802 current_seq = 493 count = 392 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.472397 last_received_ts = 171.471802 last_seq = 493 current_ts = 171.491425 current_received_ts = 171.490829 current_seq = 494 count = 393 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 35us (kms_flip:2333) DEBUG: name = flip last_ts = 171.491425 last_received_ts = 171.490829 last_seq = 494 current_ts = 171.510452 current_received_ts = 171.510056 current_seq = 495 count = 394 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 35us (kms_flip:2333) DEBUG: name = flip last_ts = 171.510452 last_received_ts = 171.510056 last_seq = 495 current_ts = 171.529465 current_received_ts = 171.528870 current_seq = 496 count = 395 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.529465 last_received_ts = 171.528870 last_seq = 496 current_ts = 171.548477 current_received_ts = 171.547867 current_seq = 497 count = 396 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.548477 last_received_ts = 171.547867 last_seq = 497 current_ts = 171.567520 current_received_ts = 171.567001 current_seq = 498 count = 397 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 31us (kms_flip:2333) DEBUG: name = flip last_ts = 171.567520 last_received_ts = 171.567001 last_seq = 498 current_ts = 171.586533 current_received_ts = 171.585938 current_seq = 499 count = 398 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 46us (kms_flip:2333) DEBUG: name = flip last_ts = 171.586533 last_received_ts = 171.585938 last_seq = 499 current_ts = 171.605560 current_received_ts = 171.604950 current_seq = 500 count = 399 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 52us (kms_flip:2333) DEBUG: name = flip last_ts = 171.605560 last_received_ts = 171.604950 last_seq = 500 current_ts = 171.624573 current_received_ts = 171.623962 current_seq = 501 count = 400 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 51us (kms_flip:2333) DEBUG: name = flip last_ts = 171.624573 last_received_ts = 171.623962 last_seq = 501 current_ts = 171.643600 current_received_ts = 171.642990 current_seq = 502 count = 401 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 32us (kms_flip:2333) DEBUG: name = flip last_ts = 171.643600 last_received_ts = 171.642990 last_seq = 502 current_ts = 171.662613 current_received_ts = 171.662048 current_seq = 503 count = 402 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.662613 last_received_ts = 171.662048 last_seq = 503 current_ts = 171.681625 current_received_ts = 171.681046 current_seq = 504 count = 403 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.681625 last_received_ts = 171.681046 last_seq = 504 current_ts = 171.700653 current_received_ts = 171.700104 current_seq = 505 count = 404 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 29us (kms_flip:2333) DEBUG: name = flip last_ts = 171.700653 last_received_ts = 171.700104 last_seq = 505 current_ts = 171.719681 current_received_ts = 171.719055 current_seq = 506 count = 405 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 28us (kms_flip:2333) DEBUG: name = flip last_ts = 171.719681 last_received_ts = 171.719055 last_seq = 506 current_ts = 171.738708 current_received_ts = 171.738129 current_seq = 507 count = 406 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 32us (kms_flip:2333) DEBUG: name = flip last_ts = 171.738708 last_received_ts = 171.738129 last_seq = 507 current_ts = 171.757721 current_received_ts = 171.757126 current_seq = 508 count = 407 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 35us (kms_flip:2333) DEBUG: name = flip last_ts = 171.757721 last_received_ts = 171.757126 last_seq = 508 current_ts = 171.776749 current_received_ts = 171.776138 current_seq = 509 count = 408 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 34us (kms_flip:2333) DEBUG: name = flip last_ts = 171.776749 last_received_ts = 171.776138 last_seq = 509 current_ts = 171.795761 current_received_ts = 171.795181 current_seq = 510 count = 409 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 30us (kms_flip:2333) DEBUG: name = flip last_ts = 171.795761 last_received_ts = 171.795181 last_seq = 510 current_ts = 171.814789 current_received_ts = 171.814224 current_seq = 511 count = 410 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 70us (kms_flip:2333) DEBUG: name = flip last_ts = 171.814789 last_received_ts = 171.814224 last_seq = 511 current_ts = 171.833801 current_received_ts = 171.834152 current_seq = 512 count = 411 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 31us (kms_flip:2333) DEBUG: name = flip last_ts = 171.833801 last_received_ts = 171.834152 last_seq = 512 current_ts = 171.852829 current_received_ts = 171.852188 current_seq = 513 count = 412 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 42us (kms_flip:2333) DEBUG: name = flip last_ts = 171.852829 last_received_ts = 171.852188 last_seq = 513 current_ts = 171.871857 current_received_ts = 171.871216 current_seq = 514 count = 413 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 41us (kms_flip:2333) DEBUG: name = flip last_ts = 171.871857 last_received_ts = 171.871216 last_seq = 514 current_ts = 171.890884 current_received_ts = 171.890289 current_seq = 515 count = 414 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 40us (kms_flip:2333) DEBUG: name = flip last_ts = 171.890884 last_received_ts = 171.890289 last_seq = 515 current_ts = 171.909897 current_received_ts = 171.909317 current_seq = 516 count = 415 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 35us (kms_flip:2333) DEBUG: name = flip last_ts = 171.909897 last_received_ts = 171.909317 last_seq = 516 current_ts = 171.928909 current_received_ts = 171.928329 current_seq = 517 count = 416 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 37us (kms_flip:2333) DEBUG: name = flip last_ts = 171.928909 last_received_ts = 171.928329 last_seq = 517 current_ts = 171.947937 current_received_ts = 171.947327 current_seq = 518 count = 417 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 42us (kms_flip:2333) DEBUG: name = flip last_ts = 171.947937 last_received_ts = 171.947327 last_seq = 518 current_ts = 171.966965 current_received_ts = 171.966324 current_seq = 519 count = 418 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 41us (kms_flip:2333) DEBUG: name = flip last_ts = 171.966965 last_received_ts = 171.966324 last_seq = 519 current_ts = 171.985977 current_received_ts = 171.985458 current_seq = 520 count = 419 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 41us (kms_flip:2333) DEBUG: name = flip last_ts = 171.985977 last_received_ts = 171.985458 last_seq = 520 current_ts = 172.005005 current_received_ts = 172.004364 current_seq = 521 count = 420 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 39us (kms_flip:2333) DEBUG: name = flip last_ts = 172.005005 last_received_ts = 172.004364 last_seq = 521 current_ts = 172.024033 current_received_ts = 172.023468 current_seq = 522 count = 421 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 40us (kms_flip:2333) DEBUG: name = flip last_ts = 172.024033 last_received_ts = 172.023468 last_seq = 522 current_ts = 172.043045 current_received_ts = 172.042435 current_seq = 523 count = 422 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 36us (kms_flip:2333) DEBUG: name = flip last_ts = 172.043045 last_received_ts = 172.042435 last_seq = 523 current_ts = 172.062073 current_received_ts = 172.061447 current_seq = 524 count = 423 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 39us (kms_flip:2333) DEBUG: name = flip last_ts = 172.062073 last_received_ts = 172.061447 last_seq = 524 current_ts = 172.081085 current_received_ts = 172.080475 current_seq = 525 count = 424 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 41us (kms_flip:2333) DEBUG: name = flip last_ts = 172.081085 last_received_ts = 172.080475 last_seq = 525 current_ts = 172.100113 current_received_ts = 172.099518 current_seq = 526 count = 425 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 39us (kms_flip:2333) DEBUG: name = flip last_ts = 172.100113 last_received_ts = 172.099518 last_seq = 526 current_ts = 172.119141 current_received_ts = 172.118500 current_seq = 527 count = 426 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 41us (kms_flip:2333) DEBUG: name = flip last_ts = 172.119141 last_received_ts = 172.118500 last_seq = 527 current_ts = 172.138153 current_received_ts = 172.137512 current_seq = 528 count = 427 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 41us (kms_flip:2333) DEBUG: name = flip last_ts = 172.138153 last_received_ts = 172.137512 last_seq = 528 current_ts = 172.157166 current_received_ts = 172.156586 current_seq = 529 count = 428 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 37us (kms_flip:2333) DEBUG: name = flip last_ts = 172.157166 last_received_ts = 172.156586 last_seq = 529 current_ts = 172.176193 current_received_ts = 172.175598 current_seq = 530 count = 429 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 38us (kms_flip:2333) DEBUG: name = flip last_ts = 172.176193 last_received_ts = 172.175598 last_seq = 530 current_ts = 172.195221 current_received_ts = 172.194595 current_seq = 531 count = 430 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 37us (kms_flip:2333) DEBUG: name = flip last_ts = 172.195221 last_received_ts = 172.194595 last_seq = 531 current_ts = 172.214233 current_received_ts = 172.213608 current_seq = 532 count = 431 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 38us (kms_flip:2333) DEBUG: name = flip last_ts = 172.214233 last_received_ts = 172.213608 last_seq = 532 current_ts = 172.233246 current_received_ts = 172.232742 current_seq = 533 count = 432 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 37us (kms_flip:2333) DEBUG: name = flip last_ts = 172.233246 last_received_ts = 172.232742 last_seq = 533 current_ts = 172.252274 current_received_ts = 172.251617 current_seq = 534 count = 433 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 37us (kms_flip:2333) DEBUG: name = flip last_ts = 172.252274 last_received_ts = 172.251617 last_seq = 534 current_ts = 172.271286 current_received_ts = 172.270752 current_seq = 535 count = 434 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 40us (kms_flip:2333) DEBUG: name = flip last_ts = 172.271286 last_received_ts = 172.270752 last_seq = 535 current_ts = 172.290314 current_received_ts = 172.289719 current_seq = 536 count = 435 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 41us (kms_flip:2333) DEBUG: name = flip last_ts = 172.290314 last_received_ts = 172.289719 last_seq = 536 current_ts = 172.309326 current_received_ts = 172.308701 current_seq = 537 count = 436 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 40us (kms_flip:2333) DEBUG: name = flip last_ts = 172.309326 last_received_ts = 172.308701 last_seq = 537 current_ts = 172.328339 current_received_ts = 172.327805 current_seq = 538 count = 437 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 42us (kms_flip:2333) DEBUG: name = flip last_ts = 172.328339 last_received_ts = 172.327805 last_seq = 538 current_ts = 172.347351 current_received_ts = 172.346725 current_seq = 539 count = 438 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 41us (kms_flip:2333) DEBUG: name = flip last_ts = 172.347351 last_received_ts = 172.346725 last_seq = 539 current_ts = 172.366364 current_received_ts = 172.365738 current_seq = 540 count = 439 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 41us (kms_flip:2333) DEBUG: name = flip last_ts = 172.366364 last_received_ts = 172.365738 last_seq = 540 current_ts = 172.385391 current_received_ts = 172.384827 current_seq = 541 count = 440 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 40us (kms_flip:2333) DEBUG: name = flip last_ts = 172.385391 last_received_ts = 172.384827 last_seq = 541 current_ts = 172.404388 current_received_ts = 172.403824 current_seq = 542 count = 441 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 42us (kms_flip:2333) DEBUG: name = flip last_ts = 172.404388 last_received_ts = 172.403824 last_seq = 542 current_ts = 172.423416 current_received_ts = 172.422806 current_seq = 543 count = 442 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 40us (kms_flip:2333) DEBUG: name = flip last_ts = 172.423416 last_received_ts = 172.422806 last_seq = 543 current_ts = 172.442429 current_received_ts = 172.441895 current_seq = 544 count = 443 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 43us (kms_flip:2333) DEBUG: name = flip last_ts = 172.442429 last_received_ts = 172.441895 last_seq = 544 current_ts = 172.461441 current_received_ts = 172.460831 current_seq = 545 count = 444 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 41us (kms_flip:2333) DEBUG: name = flip last_ts = 172.461441 last_received_ts = 172.460831 last_seq = 545 current_ts = 172.480469 current_received_ts = 172.479828 current_seq = 546 count = 445 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 40us (kms_flip:2333) DEBUG: name = flip last_ts = 172.480469 last_received_ts = 172.479828 last_seq = 546 current_ts = 172.499496 current_received_ts = 172.498947 current_seq = 547 count = 446 seq_step = 1 (kms_flip:2333) DEBUG: Vblank took 971us (kms_flip:2333) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2333) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2333) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:2333) igt_core-INFO: Stack trace: (kms_flip:2333) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2333) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:2333) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:2333) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() (kms_flip:2333) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:2333) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2333) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2333) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A2: FAIL (8.682s)
Dmesg	<6> [223.941775] [IGT] kms_flip: starting dynamic subtest B-HDMI-A2 <7> [223.942850] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:418] <7> [223.943165] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:428] <7> [223.961270] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [223.961378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [223.961566] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [223.961718] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [223.961860] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [223.962001] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [223.962142] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [223.962304] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [223.962445] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2360, found 0) <7> [223.962585] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [223.962728] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2360, found 0) <7> [223.962860] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [223.962993] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2096, found 0) <7> [223.963126] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [223.963270] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [223.963407] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [223.963540] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [223.963673] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [223.963807] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [223.963939] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [223.964071] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2360, found 0) <7> [223.964212] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [223.964344] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2360, found 0) <7> [223.964476] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [223.964612] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2096, found 0) <7> [223.964747] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [223.964882] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [223.965016] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [223.965154] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [223.965287] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [223.965420] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [223.965552] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [223.965685] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [223.965818] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [223.965951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [223.966083] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 139929, found 0) <7> [223.966223] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 139929, found 0) <7> [223.966355] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 139929, found 0) <7> [223.966487] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [223.966620] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:151:pipe A] releasing DPLL 0 <7> [223.966779] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no <7> [223.966911] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:151:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [223.967062] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:145:cursor A] ddb (2016 - 2048) -> ( 0 - 0), size 32 -> 0 <7> [223.967217] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:151:pipe A] min cdclk: 69965 kHz -> 0 kHz <7> [223.967357] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:151:pipe A] enable: no [modeset] <7> [223.967492] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [223.967626] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [223.967763] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [223.967898] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [223.968033] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [223.968173] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [223.968392] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [223.977128] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_TC1 <7> [223.977406] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [223.977565] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0 <7> [223.977713] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:389:DDI B/PHY B] <7> [223.977851] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:399:DDI TC1/PHY C] <7> [223.977999] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:403:DDI TC2/PHY D] <7> [223.978145] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:405:DP-MST A] <7> [223.978278] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:406:DP-MST B] <7> [223.978410] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:407:DP-MST C] <7> [223.978543] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:400:HDMI-A-2] <7> [223.978737] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [223.978919] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_3 <7> [223.979090] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:151:pipe A] <7> [223.979461] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [223.979583] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C] <7> [223.979694] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [223.979713] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:400:HDMI-A-2] <7> [223.979767] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:400:HDMI-A-2] Limiting target display pipe bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36) <7> [223.979917] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [223.980060] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:269:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [223.980196] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:399:DDI TC1/PHY C] [CRTC:269:pipe B] <7> [223.980326] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [223.980465] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [223.980602] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [223.980736] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [223.980870] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [223.981003] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [223.981149] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [223.981281] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2360) <7> [223.981412] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [223.981544] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2360) <7> [223.981677] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [223.981808] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2096) <7> [223.981940] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [223.982079] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [223.982210] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [223.982342] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [223.982477] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [223.982609] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [223.982740] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [223.982872] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2360) <7> [223.983003] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [223.983148] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2360) <7> [223.983280] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [223.983411] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2096) <7> [223.983542] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [223.983673] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [223.983803] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [223.983933] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [223.984072] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [223.984203] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [223.984333] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [223.984464] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [223.984594] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [223.984726] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [223.984856] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 139929) <7> [223.984987] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 139929) <7> [223.985129] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in port_clock (expected 0, found 139929) <7> [223.985260] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:269:pipe B] fastset requirement not met, forcing full modeset <7> [223.985410] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no <7> [223.985544] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:269:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2 <7> [223.985695] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:153:plane 1B] ddb ( 0 - 0) -> ( 0 - 2016), size 0 -> 2016 <7> [223.985825] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:263:cursor B] ddb ( 0 - 0) -> (2016 - 2048), size 0 -> 32 <7> [223.985954] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,*twm, swm, stwm <7> [223.986092] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 2, 2, 2, 2, 5, 8, 9, 0, 0, 0 <7> [223.986224] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 33, 33, 33, 33, 81, 129, 145, 30, 0, 0 <7> [223.986355] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 38, 38, 38, 38, 91, 143, 161, 31, 0, 0 <7> [223.986498] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:269:pipe B] data rate 559716 num active planes 1 <7> [223.986634] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 16761 required 560 <7> [223.986767] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [223.986910] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:269:pipe B] min cdclk: 0 kHz -> 69965 kHz <7> [223.987108] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:269:pipe B] allocated DPLL 0 <7> [223.987247] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:269:pipe B] reserving DPLL 0 <7> [223.987384] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:269:pipe B] enable: yes [modeset] <7> [223.987520] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [223.987655] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [223.987789] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [223.987920] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [223.988062] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [223.988193] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [223.988324] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0 <7> [223.988456] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [223.988587] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [223.988718] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 42, guardband: 44 vsync start: 0, vsync end: 0 <7> [223.988849] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1081, vmax vblank: 1081, vmin vtotal: 1125, vmax vtotal: 1125 <7> [223.988984] 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> [223.989115] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 <7> [223.989246] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 <7> [223.989377] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=139929, hd=1920 hb=1920-2360 hs=2008-2096 ht=2360, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [223.989509] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 53 139929 1920 2008 2096 2360 1080 1084 1089 1125 0x40 0x5 <7> [223.989642] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=139929, hd=1920 hb=1920-2360 hs=2008-2096 ht=2360, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [223.989773] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 139929, pixel rate 139929, min cdclk 69965, min voltage level 0 <7> [223.989903] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 135, ips linetime: 0 <7> [223.990041] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [223.990172] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [223.990302] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [223.990432] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [223.990563] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [223.990692] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1a6655d, cfgcr1: 0xe84, 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> [223.990823] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [223.990954] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [223.991096] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [223.991226] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [223.991357] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [223.991487] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [223.991617] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [223.991748] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [223.991878] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [223.992016] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [223.992147] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [223.992277] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [223.992407] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:153:plane 1B] fb: [FB:418] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [223.992539] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [223.992669] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [223.992799] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:183:plane 2B] fb: [NOFB], visible: no <7> [223.992930] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:213:plane 3B] fb: [NOFB], visible: no <7> [223.993071] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:243:plane 4B] fb: [NOFB], visible: no <7> [223.993202] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:253:plane 5B] fb: [NOFB], visible: no <7> [223.993332] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:263:cursor B] fb: [NOFB], visible: no <7> [223.993957] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_3 <7> [223.994118] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:389:DDI B/PHY B] <7> [223.994255] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:399:DDI TC1/PHY C] <7> [223.994390] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:403:DDI TC2/PHY D] <7> [223.994524] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:405:DP-MST A] <7> [223.994659] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:406:DP-MST B] <7> [223.994792] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:407:DP-MST C] <7> [223.994965] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [223.995135] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:269:pipe B] <7> [223.995275] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0 <7> [223.995466] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_TC1 <7> [223.995654] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [224.015783] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:400:HDMI-A-2] <7> [224.016067] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:269:pipe B] <6> [232.626859] [IGT] kms_flip: finished subtest B-HDMI-A2, FAIL

Detail

Value

Duration

8.68 seconds

Hostname

shard-rkl-7

Igt-Version

IGT-Version: 2.4-g02b0e01dd (x86_64) (Linux: 7.1.0-rc1-Patchwork_165747v1-g0ed5f88da70b+ x86_64)

Out

Starting dynamic subtest: B-HDMI-A2
  1920x1080: 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A2: FAIL (8.682s)

Err

Starting dynamic subtest: B-HDMI-A2
(kms_flip:2333) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2333) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2333) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:2333) DEBUG: Vblank took 35us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.197678
last_received_ts = 170.197098
last_seq = 426
current_ts = 170.216721
current_received_ts = 170.216156
current_seq = 427
count = 326
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 32us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.216721
last_received_ts = 170.216156
last_seq = 427
current_ts = 170.235733
current_received_ts = 170.235138
current_seq = 428
count = 327
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 33us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.235733
last_received_ts = 170.235138
last_seq = 428
current_ts = 170.254776
current_received_ts = 170.254166
current_seq = 429
count = 328
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 35us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.254776
last_received_ts = 170.254166
last_seq = 429
current_ts = 170.273788
current_received_ts = 170.273163
current_seq = 430
count = 329
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 33us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.273788
last_received_ts = 170.273163
last_seq = 430
current_ts = 170.292816
current_received_ts = 170.292252
current_seq = 431
count = 330
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 32us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.292816
last_received_ts = 170.292252
last_seq = 431
current_ts = 170.311844
current_received_ts = 170.311295
current_seq = 432
count = 331
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 31us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.311844
last_received_ts = 170.311295
last_seq = 432
current_ts = 170.330872
current_received_ts = 170.330292
current_seq = 433
count = 332
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 29us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.330872
last_received_ts = 170.330292
last_seq = 433
current_ts = 170.349899
current_received_ts = 170.349304
current_seq = 434
count = 333
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 27us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.349899
last_received_ts = 170.349304
last_seq = 434
current_ts = 170.368912
current_received_ts = 170.368271
current_seq = 435
count = 334
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 27us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.368912
last_received_ts = 170.368271
last_seq = 435
current_ts = 170.387955
current_received_ts = 170.387314
current_seq = 436
count = 335
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 31us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.387955
last_received_ts = 170.387314
last_seq = 436
current_ts = 170.406982
current_received_ts = 170.406387
current_seq = 437
count = 336
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 32us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.406982
last_received_ts = 170.406387
last_seq = 437
current_ts = 170.425995
current_received_ts = 170.425385
current_seq = 438
count = 337
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 33us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.425995
last_received_ts = 170.425385
last_seq = 438
current_ts = 170.445038
current_received_ts = 170.444458
current_seq = 439
count = 338
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 32us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.445038
last_received_ts = 170.444458
last_seq = 439
current_ts = 170.464066
current_received_ts = 170.463501
current_seq = 440
count = 339
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 48us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.464066
last_received_ts = 170.463501
last_seq = 440
current_ts = 170.483093
current_received_ts = 170.482483
current_seq = 441
count = 340
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.483093
last_received_ts = 170.482483
last_seq = 441
current_ts = 170.502106
current_received_ts = 170.501526
current_seq = 442
count = 341
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 33us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.502106
last_received_ts = 170.501526
last_seq = 442
current_ts = 170.521133
current_received_ts = 170.520538
current_seq = 443
count = 342
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.521133
last_received_ts = 170.520538
last_seq = 443
current_ts = 170.540161
current_received_ts = 170.539551
current_seq = 444
count = 343
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 33us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.540161
last_received_ts = 170.539551
last_seq = 444
current_ts = 170.559204
current_received_ts = 170.558685
current_seq = 445
count = 344
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.559204
last_received_ts = 170.558685
last_seq = 445
current_ts = 170.578217
current_received_ts = 170.577667
current_seq = 446
count = 345
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 35us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.578217
last_received_ts = 170.577667
last_seq = 446
current_ts = 170.597244
current_received_ts = 170.596634
current_seq = 447
count = 346
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 31us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.597244
last_received_ts = 170.596634
last_seq = 447
current_ts = 170.616272
current_received_ts = 170.615677
current_seq = 448
count = 347
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 31us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.616272
last_received_ts = 170.615677
last_seq = 448
current_ts = 170.635300
current_received_ts = 170.634796
current_seq = 449
count = 348
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 31us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.635300
last_received_ts = 170.634796
last_seq = 449
current_ts = 170.654327
current_received_ts = 170.653717
current_seq = 450
count = 349
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 35us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.654327
last_received_ts = 170.653717
last_seq = 450
current_ts = 170.673340
current_received_ts = 170.672729
current_seq = 451
count = 350
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 33us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.673340
last_received_ts = 170.672729
last_seq = 451
current_ts = 170.692368
current_received_ts = 170.691833
current_seq = 452
count = 351
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 27us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.692368
last_received_ts = 170.691833
last_seq = 452
current_ts = 170.711395
current_received_ts = 170.710815
current_seq = 453
count = 352
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 33us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.711395
last_received_ts = 170.710815
last_seq = 453
current_ts = 170.730438
current_received_ts = 170.729843
current_seq = 454
count = 353
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.730438
last_received_ts = 170.729843
last_seq = 454
current_ts = 170.749451
current_received_ts = 170.748947
current_seq = 455
count = 354
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 56us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.749451
last_received_ts = 170.748947
last_seq = 455
current_ts = 170.768478
current_received_ts = 170.767899
current_seq = 456
count = 355
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.768478
last_received_ts = 170.767899
last_seq = 456
current_ts = 170.787506
current_received_ts = 170.786896
current_seq = 457
count = 356
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.787506
last_received_ts = 170.786896
last_seq = 457
current_ts = 170.806549
current_received_ts = 170.805984
current_seq = 458
count = 357
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 69us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.806549
last_received_ts = 170.805984
last_seq = 458
current_ts = 170.825577
current_received_ts = 170.824982
current_seq = 459
count = 358
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.825577
last_received_ts = 170.824982
last_seq = 459
current_ts = 170.844604
current_received_ts = 170.844025
current_seq = 460
count = 359
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.844604
last_received_ts = 170.844025
last_seq = 460
current_ts = 170.863632
current_received_ts = 170.863098
current_seq = 461
count = 360
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 35us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.863632
last_received_ts = 170.863098
last_seq = 461
current_ts = 170.882660
current_received_ts = 170.882111
current_seq = 462
count = 361
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 35us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.882660
last_received_ts = 170.882111
last_seq = 462
current_ts = 170.901688
current_received_ts = 170.901062
current_seq = 463
count = 362
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 33us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.901688
last_received_ts = 170.901062
last_seq = 463
current_ts = 170.920700
current_received_ts = 170.920181
current_seq = 464
count = 363
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.920700
last_received_ts = 170.920181
last_seq = 464
current_ts = 170.939728
current_received_ts = 170.939133
current_seq = 465
count = 364
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.939728
last_received_ts = 170.939133
last_seq = 465
current_ts = 170.958755
current_received_ts = 170.958221
current_seq = 466
count = 365
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.958755
last_received_ts = 170.958221
last_seq = 466
current_ts = 170.977783
current_received_ts = 170.977173
current_seq = 467
count = 366
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 32us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.977783
last_received_ts = 170.977173
last_seq = 467
current_ts = 170.996811
current_received_ts = 170.996155
current_seq = 468
count = 367
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 27us
(kms_flip:2333) DEBUG: name = flip
last_ts = 170.996811
last_received_ts = 170.996155
last_seq = 468
current_ts = 171.015839
current_received_ts = 171.015274
current_seq = 469
count = 368
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.015839
last_received_ts = 171.015274
last_seq = 469
current_ts = 171.034851
current_received_ts = 171.034195
current_seq = 470
count = 369
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 27us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.034851
last_received_ts = 171.034195
last_seq = 470
current_ts = 171.053894
current_received_ts = 171.053329
current_seq = 471
count = 370
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.053894
last_received_ts = 171.053329
last_seq = 471
current_ts = 171.072922
current_received_ts = 171.072327
current_seq = 472
count = 371
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 27us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.072922
last_received_ts = 171.072327
last_seq = 472
current_ts = 171.091934
current_received_ts = 171.091400
current_seq = 473
count = 372
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 32us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.091934
last_received_ts = 171.091400
last_seq = 473
current_ts = 171.110977
current_received_ts = 171.110367
current_seq = 474
count = 373
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.110977
last_received_ts = 171.110367
last_seq = 474
current_ts = 171.129990
current_received_ts = 171.129364
current_seq = 475
count = 374
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 31us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.129990
last_received_ts = 171.129364
last_seq = 475
current_ts = 171.149033
current_received_ts = 171.148407
current_seq = 476
count = 375
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 33us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.149033
last_received_ts = 171.148407
last_seq = 476
current_ts = 171.168045
current_received_ts = 171.167526
current_seq = 477
count = 376
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 33us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.168045
last_received_ts = 171.167526
last_seq = 477
current_ts = 171.187088
current_received_ts = 171.186523
current_seq = 478
count = 377
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.187088
last_received_ts = 171.186523
last_seq = 478
current_ts = 171.206100
current_received_ts = 171.205597
current_seq = 479
count = 378
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 27us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.206100
last_received_ts = 171.205597
last_seq = 479
current_ts = 171.225128
current_received_ts = 171.224533
current_seq = 480
count = 379
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 31us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.225128
last_received_ts = 171.224533
last_seq = 480
current_ts = 171.244141
current_received_ts = 171.243546
current_seq = 481
count = 380
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 32us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.244141
last_received_ts = 171.243546
last_seq = 481
current_ts = 171.263168
current_received_ts = 171.262634
current_seq = 482
count = 381
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 27us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.263168
last_received_ts = 171.262634
last_seq = 482
current_ts = 171.282196
current_received_ts = 171.281525
current_seq = 483
count = 382
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 32us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.282196
last_received_ts = 171.281525
last_seq = 483
current_ts = 171.301208
current_received_ts = 171.300644
current_seq = 484
count = 383
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 32us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.301208
last_received_ts = 171.300644
last_seq = 484
current_ts = 171.320236
current_received_ts = 171.319656
current_seq = 485
count = 384
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.320236
last_received_ts = 171.319656
last_seq = 485
current_ts = 171.339249
current_received_ts = 171.338745
current_seq = 486
count = 385
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 28us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.339249
last_received_ts = 171.338745
last_seq = 486
current_ts = 171.358276
current_received_ts = 171.357681
current_seq = 487
count = 386
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.358276
last_received_ts = 171.357681
last_seq = 487
current_ts = 171.377289
current_received_ts = 171.376709
current_seq = 488
count = 387
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.377289
last_received_ts = 171.376709
last_seq = 488
current_ts = 171.396317
current_received_ts = 171.395706
current_seq = 489
count = 388
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 30us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.396317
last_received_ts = 171.395706
last_seq = 489
current_ts = 171.415344
current_received_ts = 171.414734
current_seq = 490
count = 389
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.415344
last_received_ts = 171.414734
last_seq = 490
current_ts = 171.434357
current_received_ts = 171.433701
current_seq = 491
count = 390
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 27us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.434357
last_received_ts = 171.433701
last_seq = 491
current_ts = 171.453384
current_received_ts = 171.452805
current_seq = 492
count = 391
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.453384
last_received_ts = 171.452805
last_seq = 492
current_ts = 171.472397
current_received_ts = 171.471802
current_seq = 493
count = 392
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.472397
last_received_ts = 171.471802
last_seq = 493
current_ts = 171.491425
current_received_ts = 171.490829
current_seq = 494
count = 393
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 35us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.491425
last_received_ts = 171.490829
last_seq = 494
current_ts = 171.510452
current_received_ts = 171.510056
current_seq = 495
count = 394
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 35us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.510452
last_received_ts = 171.510056
last_seq = 495
current_ts = 171.529465
current_received_ts = 171.528870
current_seq = 496
count = 395
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.529465
last_received_ts = 171.528870
last_seq = 496
current_ts = 171.548477
current_received_ts = 171.547867
current_seq = 497
count = 396
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.548477
last_received_ts = 171.547867
last_seq = 497
current_ts = 171.567520
current_received_ts = 171.567001
current_seq = 498
count = 397
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 31us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.567520
last_received_ts = 171.567001
last_seq = 498
current_ts = 171.586533
current_received_ts = 171.585938
current_seq = 499
count = 398
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 46us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.586533
last_received_ts = 171.585938
last_seq = 499
current_ts = 171.605560
current_received_ts = 171.604950
current_seq = 500
count = 399
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 52us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.605560
last_received_ts = 171.604950
last_seq = 500
current_ts = 171.624573
current_received_ts = 171.623962
current_seq = 501
count = 400
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 51us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.624573
last_received_ts = 171.623962
last_seq = 501
current_ts = 171.643600
current_received_ts = 171.642990
current_seq = 502
count = 401
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 32us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.643600
last_received_ts = 171.642990
last_seq = 502
current_ts = 171.662613
current_received_ts = 171.662048
current_seq = 503
count = 402
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.662613
last_received_ts = 171.662048
last_seq = 503
current_ts = 171.681625
current_received_ts = 171.681046
current_seq = 504
count = 403
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.681625
last_received_ts = 171.681046
last_seq = 504
current_ts = 171.700653
current_received_ts = 171.700104
current_seq = 505
count = 404
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 29us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.700653
last_received_ts = 171.700104
last_seq = 505
current_ts = 171.719681
current_received_ts = 171.719055
current_seq = 506
count = 405
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 28us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.719681
last_received_ts = 171.719055
last_seq = 506
current_ts = 171.738708
current_received_ts = 171.738129
current_seq = 507
count = 406
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 32us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.738708
last_received_ts = 171.738129
last_seq = 507
current_ts = 171.757721
current_received_ts = 171.757126
current_seq = 508
count = 407
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 35us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.757721
last_received_ts = 171.757126
last_seq = 508
current_ts = 171.776749
current_received_ts = 171.776138
current_seq = 509
count = 408
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 34us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.776749
last_received_ts = 171.776138
last_seq = 509
current_ts = 171.795761
current_received_ts = 171.795181
current_seq = 510
count = 409
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 30us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.795761
last_received_ts = 171.795181
last_seq = 510
current_ts = 171.814789
current_received_ts = 171.814224
current_seq = 511
count = 410
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 70us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.814789
last_received_ts = 171.814224
last_seq = 511
current_ts = 171.833801
current_received_ts = 171.834152
current_seq = 512
count = 411
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 31us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.833801
last_received_ts = 171.834152
last_seq = 512
current_ts = 171.852829
current_received_ts = 171.852188
current_seq = 513
count = 412
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 42us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.852829
last_received_ts = 171.852188
last_seq = 513
current_ts = 171.871857
current_received_ts = 171.871216
current_seq = 514
count = 413
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 41us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.871857
last_received_ts = 171.871216
last_seq = 514
current_ts = 171.890884
current_received_ts = 171.890289
current_seq = 515
count = 414
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 40us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.890884
last_received_ts = 171.890289
last_seq = 515
current_ts = 171.909897
current_received_ts = 171.909317
current_seq = 516
count = 415
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 35us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.909897
last_received_ts = 171.909317
last_seq = 516
current_ts = 171.928909
current_received_ts = 171.928329
current_seq = 517
count = 416
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 37us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.928909
last_received_ts = 171.928329
last_seq = 517
current_ts = 171.947937
current_received_ts = 171.947327
current_seq = 518
count = 417
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 42us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.947937
last_received_ts = 171.947327
last_seq = 518
current_ts = 171.966965
current_received_ts = 171.966324
current_seq = 519
count = 418
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 41us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.966965
last_received_ts = 171.966324
last_seq = 519
current_ts = 171.985977
current_received_ts = 171.985458
current_seq = 520
count = 419
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 41us
(kms_flip:2333) DEBUG: name = flip
last_ts = 171.985977
last_received_ts = 171.985458
last_seq = 520
current_ts = 172.005005
current_received_ts = 172.004364
current_seq = 521
count = 420
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 39us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.005005
last_received_ts = 172.004364
last_seq = 521
current_ts = 172.024033
current_received_ts = 172.023468
current_seq = 522
count = 421
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 40us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.024033
last_received_ts = 172.023468
last_seq = 522
current_ts = 172.043045
current_received_ts = 172.042435
current_seq = 523
count = 422
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 36us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.043045
last_received_ts = 172.042435
last_seq = 523
current_ts = 172.062073
current_received_ts = 172.061447
current_seq = 524
count = 423
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 39us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.062073
last_received_ts = 172.061447
last_seq = 524
current_ts = 172.081085
current_received_ts = 172.080475
current_seq = 525
count = 424
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 41us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.081085
last_received_ts = 172.080475
last_seq = 525
current_ts = 172.100113
current_received_ts = 172.099518
current_seq = 526
count = 425
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 39us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.100113
last_received_ts = 172.099518
last_seq = 526
current_ts = 172.119141
current_received_ts = 172.118500
current_seq = 527
count = 426
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 41us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.119141
last_received_ts = 172.118500
last_seq = 527
current_ts = 172.138153
current_received_ts = 172.137512
current_seq = 528
count = 427
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 41us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.138153
last_received_ts = 172.137512
last_seq = 528
current_ts = 172.157166
current_received_ts = 172.156586
current_seq = 529
count = 428
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 37us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.157166
last_received_ts = 172.156586
last_seq = 529
current_ts = 172.176193
current_received_ts = 172.175598
current_seq = 530
count = 429
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 38us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.176193
last_received_ts = 172.175598
last_seq = 530
current_ts = 172.195221
current_received_ts = 172.194595
current_seq = 531
count = 430
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 37us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.195221
last_received_ts = 172.194595
last_seq = 531
current_ts = 172.214233
current_received_ts = 172.213608
current_seq = 532
count = 431
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 38us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.214233
last_received_ts = 172.213608
last_seq = 532
current_ts = 172.233246
current_received_ts = 172.232742
current_seq = 533
count = 432
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 37us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.233246
last_received_ts = 172.232742
last_seq = 533
current_ts = 172.252274
current_received_ts = 172.251617
current_seq = 534
count = 433
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 37us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.252274
last_received_ts = 172.251617
last_seq = 534
current_ts = 172.271286
current_received_ts = 172.270752
current_seq = 535
count = 434
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 40us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.271286
last_received_ts = 172.270752
last_seq = 535
current_ts = 172.290314
current_received_ts = 172.289719
current_seq = 536
count = 435
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 41us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.290314
last_received_ts = 172.289719
last_seq = 536
current_ts = 172.309326
current_received_ts = 172.308701
current_seq = 537
count = 436
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 40us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.309326
last_received_ts = 172.308701
last_seq = 537
current_ts = 172.328339
current_received_ts = 172.327805
current_seq = 538
count = 437
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 42us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.328339
last_received_ts = 172.327805
last_seq = 538
current_ts = 172.347351
current_received_ts = 172.346725
current_seq = 539
count = 438
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 41us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.347351
last_received_ts = 172.346725
last_seq = 539
current_ts = 172.366364
current_received_ts = 172.365738
current_seq = 540
count = 439
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 41us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.366364
last_received_ts = 172.365738
last_seq = 540
current_ts = 172.385391
current_received_ts = 172.384827
current_seq = 541
count = 440
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 40us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.385391
last_received_ts = 172.384827
last_seq = 541
current_ts = 172.404388
current_received_ts = 172.403824
current_seq = 542
count = 441
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 42us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.404388
last_received_ts = 172.403824
last_seq = 542
current_ts = 172.423416
current_received_ts = 172.422806
current_seq = 543
count = 442
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 40us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.423416
last_received_ts = 172.422806
last_seq = 543
current_ts = 172.442429
current_received_ts = 172.441895
current_seq = 544
count = 443
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 43us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.442429
last_received_ts = 172.441895
last_seq = 544
current_ts = 172.461441
current_received_ts = 172.460831
current_seq = 545
count = 444
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 41us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.461441
last_received_ts = 172.460831
last_seq = 545
current_ts = 172.480469
current_received_ts = 172.479828
current_seq = 546
count = 445
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 40us
(kms_flip:2333) DEBUG: name = flip
last_ts = 172.480469
last_received_ts = 172.479828
last_seq = 546
current_ts = 172.499496
current_received_ts = 172.498947
current_seq = 547
count = 446
seq_step = 1
(kms_flip:2333) DEBUG: Vblank took 971us
(kms_flip:2333) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2333) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2333) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2333) igt_core-INFO: Stack trace:
(kms_flip:2333) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2333) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:2333) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:2333) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:2333) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:2333) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2333) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2333) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A2: FAIL (8.682s)

Dmesg

<6> [223.941775] [IGT] kms_flip: starting dynamic subtest B-HDMI-A2

<7> [223.942850] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:418]

<7> [223.943165] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:428]

<7> [223.961270] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [223.967062] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:145:cursor A] ddb (2016 - 2048) -> ( 0 - 0), size 32 -> 0

<7> [223.967217] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:151:pipe A] min cdclk: 69965 kHz -> 0 kHz

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

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

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

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

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

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

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

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

<7> [223.977128] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_TC1

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

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

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

<7> [223.977851] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:399:DDI TC1/PHY C]

<7> [223.977999] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:403:DDI TC2/PHY D]

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

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

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

<7> [223.978543] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:400:HDMI-A-2]

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

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

<7> [223.979090] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:151:pipe A]

<7> [223.979461] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]

<7> [223.979583] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C]

<7> [223.979694] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]

<7> [223.979713] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:400:HDMI-A-2]

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

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

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

<7> [223.980196] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:399:DDI TC1/PHY C] [CRTC:269:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [223.985695] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:153:plane 1B] ddb ( 0 - 0) -> ( 0 - 2016), size 0 -> 2016

<7> [223.985825] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:263:cursor B] ddb ( 0 - 0) -> (2016 - 2048), size 0 -> 32

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

<7> [223.986092] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 2, 2, 2, 2, 5, 8, 9, 0, 0, 0

<7> [223.986224] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 33, 33, 33, 33, 81, 129, 145, 30, 0, 0

<7> [223.986355] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:153:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 38, 38, 38, 38, 91, 143, 161, 31, 0, 0

<7> [223.986498] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:269:pipe B] data rate 559716 num active planes 1

<7> [223.986634] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 16761 required 560

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

<7> [223.986910] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:269:pipe B] min cdclk: 0 kHz -> 69965 kHz

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

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

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

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

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

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

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

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

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

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

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

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

<7> [223.988718] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 42, guardband: 44 vsync start: 0, vsync end: 0

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

<7> [223.988984] 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> [223.989115] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5

<7> [223.989246] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5

<7> [223.989377] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=139929, hd=1920 hb=1920-2360 hs=2008-2096 ht=2360, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [223.989509] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 53 139929 1920 2008 2096 2360 1080 1084 1089 1125 0x40 0x5

<7> [223.989642] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=139929, hd=1920 hb=1920-2360 hs=2008-2096 ht=2360, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [223.989773] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 139929, pixel rate 139929, min cdclk 69965, min voltage level 0

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

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

<7> [223.990172] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0

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

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

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

<7> [223.990692] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1a6655d, cfgcr1: 0xe84, 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> [223.990823] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [223.994255] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:399:DDI TC1/PHY C]

<7> [223.994390] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:403:DDI TC2/PHY D]

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

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

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

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

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

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

<7> [223.995466] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_TC1

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

<7> [224.015783] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:400:HDMI-A-2]

<7> [224.016067] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:269:pipe B]

<6> [232.626859] [IGT] kms_flip: finished subtest B-HDMI-A2, FAIL

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