igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1 on shard-lnl@xe-pw-163788v1 Test details

Detail	Value
Duration	10.53 seconds
Hostname	shard-lnl-4
Igt-Version	IGT-Version: 2.3-g31b303e63 (x86_64) (Linux: 7.0.0-rc5-lgci-xe-xe-pw-163788v1-debug+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1891 run_test() #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047() #4 ../tests/kms_flip.c:2047 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (10.534s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:3952) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:3952) CRITICAL: Failed assertion: end - start < 500 (kms_flip:3952) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:3952) DEBUG: Vblank took 36us (kms_flip:3952) DEBUG: name = flip last_ts = 109.826546 last_received_ts = 109.826096 last_seq = 447 current_ts = 109.843208 current_received_ts = 109.842659 current_seq = 448 count = 436 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 116us (kms_flip:3952) DEBUG: name = flip last_ts = 109.843208 last_received_ts = 109.842659 last_seq = 448 current_ts = 109.859871 current_received_ts = 109.859314 current_seq = 449 count = 437 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 163us (kms_flip:3952) DEBUG: name = flip last_ts = 109.859871 last_received_ts = 109.859314 last_seq = 449 current_ts = 109.876534 current_received_ts = 109.875786 current_seq = 450 count = 438 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 118us (kms_flip:3952) DEBUG: name = flip last_ts = 109.876534 last_received_ts = 109.875786 last_seq = 450 current_ts = 109.893204 current_received_ts = 109.892403 current_seq = 451 count = 439 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 80us (kms_flip:3952) DEBUG: name = flip last_ts = 109.893204 last_received_ts = 109.892403 last_seq = 451 current_ts = 109.909859 current_received_ts = 109.909050 current_seq = 452 count = 440 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 68us (kms_flip:3952) DEBUG: name = flip last_ts = 109.909859 last_received_ts = 109.909050 last_seq = 452 current_ts = 109.926521 current_received_ts = 109.925713 current_seq = 453 count = 441 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 67us (kms_flip:3952) DEBUG: name = flip last_ts = 109.926521 last_received_ts = 109.925713 last_seq = 453 current_ts = 109.943192 current_received_ts = 109.942375 current_seq = 454 count = 442 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 109.943192 last_received_ts = 109.942375 last_seq = 454 current_ts = 109.959854 current_received_ts = 109.959053 current_seq = 455 count = 443 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 67us (kms_flip:3952) DEBUG: name = flip last_ts = 109.959854 last_received_ts = 109.959053 last_seq = 455 current_ts = 109.976517 current_received_ts = 109.975700 current_seq = 456 count = 444 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 109.976517 last_received_ts = 109.975700 last_seq = 456 current_ts = 109.993179 current_received_ts = 109.992599 current_seq = 457 count = 445 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 104us (kms_flip:3952) DEBUG: name = flip last_ts = 109.993179 last_received_ts = 109.992599 last_seq = 457 current_ts = 110.009842 current_received_ts = 110.010437 current_seq = 458 count = 446 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 89us (kms_flip:3952) DEBUG: name = flip last_ts = 110.009842 last_received_ts = 110.010437 last_seq = 458 current_ts = 110.026505 current_received_ts = 110.025711 current_seq = 459 count = 447 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 101us (kms_flip:3952) DEBUG: name = flip last_ts = 110.026505 last_received_ts = 110.025711 last_seq = 459 current_ts = 110.043175 current_received_ts = 110.042366 current_seq = 460 count = 448 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 69us (kms_flip:3952) DEBUG: name = flip last_ts = 110.043175 last_received_ts = 110.042366 last_seq = 460 current_ts = 110.059830 current_received_ts = 110.059067 current_seq = 461 count = 449 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 69us (kms_flip:3952) DEBUG: name = flip last_ts = 110.059830 last_received_ts = 110.059067 last_seq = 461 current_ts = 110.076492 current_received_ts = 110.075714 current_seq = 462 count = 450 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 106us (kms_flip:3952) DEBUG: name = flip last_ts = 110.076492 last_received_ts = 110.075714 last_seq = 462 current_ts = 110.093163 current_received_ts = 110.092354 current_seq = 463 count = 451 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 79us (kms_flip:3952) DEBUG: name = flip last_ts = 110.093163 last_received_ts = 110.092354 last_seq = 463 current_ts = 110.109825 current_received_ts = 110.109039 current_seq = 464 count = 452 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 72us (kms_flip:3952) DEBUG: name = flip last_ts = 110.109825 last_received_ts = 110.109039 last_seq = 464 current_ts = 110.126488 current_received_ts = 110.125687 current_seq = 465 count = 453 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 68us (kms_flip:3952) DEBUG: name = flip last_ts = 110.126488 last_received_ts = 110.125687 last_seq = 465 current_ts = 110.143150 current_received_ts = 110.142342 current_seq = 466 count = 454 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 110.143150 last_received_ts = 110.142342 last_seq = 466 current_ts = 110.159813 current_received_ts = 110.159042 current_seq = 467 count = 455 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 110.159813 last_received_ts = 110.159042 last_seq = 467 current_ts = 110.176476 current_received_ts = 110.175674 current_seq = 468 count = 456 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.176476 last_received_ts = 110.175674 last_seq = 468 current_ts = 110.193146 current_received_ts = 110.192329 current_seq = 469 count = 457 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 110.193146 last_received_ts = 110.192329 last_seq = 469 current_ts = 110.209801 current_received_ts = 110.209000 current_seq = 470 count = 458 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.209801 last_received_ts = 110.209000 last_seq = 470 current_ts = 110.226463 current_received_ts = 110.225655 current_seq = 471 count = 459 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 110.226463 last_received_ts = 110.225655 last_seq = 471 current_ts = 110.243134 current_received_ts = 110.242317 current_seq = 472 count = 460 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.243134 last_received_ts = 110.242317 last_seq = 472 current_ts = 110.259796 current_received_ts = 110.258987 current_seq = 473 count = 461 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 67us (kms_flip:3952) DEBUG: name = flip last_ts = 110.259796 last_received_ts = 110.258987 last_seq = 473 current_ts = 110.276459 current_received_ts = 110.275650 current_seq = 474 count = 462 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 67us (kms_flip:3952) DEBUG: name = flip last_ts = 110.276459 last_received_ts = 110.275650 last_seq = 474 current_ts = 110.293121 current_received_ts = 110.292305 current_seq = 475 count = 463 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 90us (kms_flip:3952) DEBUG: name = flip last_ts = 110.293121 last_received_ts = 110.292305 last_seq = 475 current_ts = 110.309792 current_received_ts = 110.308975 current_seq = 476 count = 464 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 76us (kms_flip:3952) DEBUG: name = flip last_ts = 110.309792 last_received_ts = 110.308975 last_seq = 476 current_ts = 110.326447 current_received_ts = 110.325645 current_seq = 477 count = 465 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 110.326447 last_received_ts = 110.325645 last_seq = 477 current_ts = 110.343117 current_received_ts = 110.342300 current_seq = 478 count = 466 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.343117 last_received_ts = 110.342300 last_seq = 478 current_ts = 110.359772 current_received_ts = 110.358963 current_seq = 479 count = 467 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 76us (kms_flip:3952) DEBUG: name = flip last_ts = 110.359772 last_received_ts = 110.358963 last_seq = 479 current_ts = 110.376442 current_received_ts = 110.375633 current_seq = 480 count = 468 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 110.376442 last_received_ts = 110.375633 last_seq = 480 current_ts = 110.393105 current_received_ts = 110.392288 current_seq = 481 count = 469 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 110.393105 last_received_ts = 110.392288 last_seq = 481 current_ts = 110.409767 current_received_ts = 110.408958 current_seq = 482 count = 470 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 100us (kms_flip:3952) DEBUG: name = flip last_ts = 110.409767 last_received_ts = 110.408958 last_seq = 482 current_ts = 110.426430 current_received_ts = 110.425621 current_seq = 483 count = 471 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 110.426430 last_received_ts = 110.425621 last_seq = 483 current_ts = 110.443092 current_received_ts = 110.442284 current_seq = 484 count = 472 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 64us (kms_flip:3952) DEBUG: name = flip last_ts = 110.443092 last_received_ts = 110.442284 last_seq = 484 current_ts = 110.459763 current_received_ts = 110.458954 current_seq = 485 count = 473 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 84us (kms_flip:3952) DEBUG: name = flip last_ts = 110.459763 last_received_ts = 110.458954 last_seq = 485 current_ts = 110.476418 current_received_ts = 110.475609 current_seq = 486 count = 474 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 110.476418 last_received_ts = 110.475609 last_seq = 486 current_ts = 110.493088 current_received_ts = 110.492264 current_seq = 487 count = 475 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 110.493088 last_received_ts = 110.492264 last_seq = 487 current_ts = 110.509750 current_received_ts = 110.508934 current_seq = 488 count = 476 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 94us (kms_flip:3952) DEBUG: name = flip last_ts = 110.509750 last_received_ts = 110.508934 last_seq = 488 current_ts = 110.526413 current_received_ts = 110.525604 current_seq = 489 count = 477 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 110.526413 last_received_ts = 110.525604 last_seq = 489 current_ts = 110.543076 current_received_ts = 110.542267 current_seq = 490 count = 478 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 94us (kms_flip:3952) DEBUG: name = flip last_ts = 110.543076 last_received_ts = 110.542267 last_seq = 490 current_ts = 110.559738 current_received_ts = 110.558937 current_seq = 491 count = 479 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 76us (kms_flip:3952) DEBUG: name = flip last_ts = 110.559738 last_received_ts = 110.558937 last_seq = 491 current_ts = 110.576401 current_received_ts = 110.575600 current_seq = 492 count = 480 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.576401 last_received_ts = 110.575600 last_seq = 492 current_ts = 110.593063 current_received_ts = 110.592262 current_seq = 493 count = 481 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 68us (kms_flip:3952) DEBUG: name = flip last_ts = 110.593063 last_received_ts = 110.592262 last_seq = 493 current_ts = 110.609726 current_received_ts = 110.608925 current_seq = 494 count = 482 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 99us (kms_flip:3952) DEBUG: name = flip last_ts = 110.609726 last_received_ts = 110.608925 last_seq = 494 current_ts = 110.626389 current_received_ts = 110.625587 current_seq = 495 count = 483 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 67us (kms_flip:3952) DEBUG: name = flip last_ts = 110.626389 last_received_ts = 110.625587 last_seq = 495 current_ts = 110.643059 current_received_ts = 110.642250 current_seq = 496 count = 484 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 110.643059 last_received_ts = 110.642250 last_seq = 496 current_ts = 110.659721 current_received_ts = 110.658920 current_seq = 497 count = 485 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 109us (kms_flip:3952) DEBUG: name = flip last_ts = 110.659721 last_received_ts = 110.658920 last_seq = 497 current_ts = 110.676384 current_received_ts = 110.675583 current_seq = 498 count = 486 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.676384 last_received_ts = 110.675583 last_seq = 498 current_ts = 110.693047 current_received_ts = 110.692245 current_seq = 499 count = 487 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.693047 last_received_ts = 110.692245 last_seq = 499 current_ts = 110.709709 current_received_ts = 110.708908 current_seq = 500 count = 488 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.709709 last_received_ts = 110.708908 last_seq = 500 current_ts = 110.726372 current_received_ts = 110.725571 current_seq = 501 count = 489 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.726372 last_received_ts = 110.725571 last_seq = 501 current_ts = 110.743042 current_received_ts = 110.742226 current_seq = 502 count = 490 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.743042 last_received_ts = 110.742226 last_seq = 502 current_ts = 110.759697 current_received_ts = 110.758888 current_seq = 503 count = 491 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 110.759697 last_received_ts = 110.758888 last_seq = 503 current_ts = 110.776367 current_received_ts = 110.775558 current_seq = 504 count = 492 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.776367 last_received_ts = 110.775558 last_seq = 504 current_ts = 110.793030 current_received_ts = 110.792221 current_seq = 505 count = 493 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 110.793030 last_received_ts = 110.792221 last_seq = 505 current_ts = 110.809692 current_received_ts = 110.808884 current_seq = 506 count = 494 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 59us (kms_flip:3952) DEBUG: name = flip last_ts = 110.809692 last_received_ts = 110.808884 last_seq = 506 current_ts = 110.826355 current_received_ts = 110.825546 current_seq = 507 count = 495 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 110.826355 last_received_ts = 110.825546 last_seq = 507 current_ts = 110.843018 current_received_ts = 110.842201 current_seq = 508 count = 496 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 59us (kms_flip:3952) DEBUG: name = flip last_ts = 110.843018 last_received_ts = 110.842201 last_seq = 508 current_ts = 110.859680 current_received_ts = 110.858864 current_seq = 509 count = 497 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 45us (kms_flip:3952) DEBUG: name = flip last_ts = 110.859680 last_received_ts = 110.858864 last_seq = 509 current_ts = 110.876343 current_received_ts = 110.875526 current_seq = 510 count = 498 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 110.876343 last_received_ts = 110.875526 last_seq = 510 current_ts = 110.893013 current_received_ts = 110.892189 current_seq = 511 count = 499 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 59us (kms_flip:3952) DEBUG: name = flip last_ts = 110.893013 last_received_ts = 110.892189 last_seq = 511 current_ts = 110.909676 current_received_ts = 110.908859 current_seq = 512 count = 500 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 110.909676 last_received_ts = 110.908859 last_seq = 512 current_ts = 110.926338 current_received_ts = 110.925529 current_seq = 513 count = 501 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 110.926338 last_received_ts = 110.925529 last_seq = 513 current_ts = 110.943001 current_received_ts = 110.942184 current_seq = 514 count = 502 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 110.943001 last_received_ts = 110.942184 last_seq = 514 current_ts = 110.959663 current_received_ts = 110.958855 current_seq = 515 count = 503 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 110.959663 last_received_ts = 110.958855 last_seq = 515 current_ts = 110.976326 current_received_ts = 110.975525 current_seq = 516 count = 504 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 110.976326 last_received_ts = 110.975525 last_seq = 516 current_ts = 110.992996 current_received_ts = 110.992172 current_seq = 517 count = 505 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 59us (kms_flip:3952) DEBUG: name = flip last_ts = 110.992996 last_received_ts = 110.992172 last_seq = 517 current_ts = 111.009651 current_received_ts = 111.008842 current_seq = 518 count = 506 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.009651 last_received_ts = 111.008842 last_seq = 518 current_ts = 111.026314 current_received_ts = 111.025513 current_seq = 519 count = 507 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 111.026314 last_received_ts = 111.025513 last_seq = 519 current_ts = 111.042984 current_received_ts = 111.042175 current_seq = 520 count = 508 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 111.042984 last_received_ts = 111.042175 last_seq = 520 current_ts = 111.059647 current_received_ts = 111.058830 current_seq = 521 count = 509 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.059647 last_received_ts = 111.058830 last_seq = 521 current_ts = 111.076309 current_received_ts = 111.075500 current_seq = 522 count = 510 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.076309 last_received_ts = 111.075500 last_seq = 522 current_ts = 111.092972 current_received_ts = 111.092163 current_seq = 523 count = 511 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 111.092972 last_received_ts = 111.092163 last_seq = 523 current_ts = 111.109634 current_received_ts = 111.108818 current_seq = 524 count = 512 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.109634 last_received_ts = 111.108818 last_seq = 524 current_ts = 111.126297 current_received_ts = 111.125496 current_seq = 525 count = 513 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 64us (kms_flip:3952) DEBUG: name = flip last_ts = 111.126297 last_received_ts = 111.125496 last_seq = 525 current_ts = 111.142967 current_received_ts = 111.142151 current_seq = 526 count = 514 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 111.142967 last_received_ts = 111.142151 last_seq = 526 current_ts = 111.159622 current_received_ts = 111.158821 current_seq = 527 count = 515 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 111.159622 last_received_ts = 111.158821 last_seq = 527 current_ts = 111.176292 current_received_ts = 111.175484 current_seq = 528 count = 516 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.176292 last_received_ts = 111.175484 last_seq = 528 current_ts = 111.192955 current_received_ts = 111.192139 current_seq = 529 count = 517 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.192955 last_received_ts = 111.192139 last_seq = 529 current_ts = 111.209618 current_received_ts = 111.208809 current_seq = 530 count = 518 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 59us (kms_flip:3952) DEBUG: name = flip last_ts = 111.209618 last_received_ts = 111.208809 last_seq = 530 current_ts = 111.226280 current_received_ts = 111.225471 current_seq = 531 count = 519 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.226280 last_received_ts = 111.225471 last_seq = 531 current_ts = 111.242950 current_received_ts = 111.242126 current_seq = 532 count = 520 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 59us (kms_flip:3952) DEBUG: name = flip last_ts = 111.242950 last_received_ts = 111.242126 last_seq = 532 current_ts = 111.259605 current_received_ts = 111.258797 current_seq = 533 count = 521 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 59us (kms_flip:3952) DEBUG: name = flip last_ts = 111.259605 last_received_ts = 111.258797 last_seq = 533 current_ts = 111.276268 current_received_ts = 111.275467 current_seq = 534 count = 522 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 111.276268 last_received_ts = 111.275467 last_seq = 534 current_ts = 111.292938 current_received_ts = 111.292130 current_seq = 535 count = 523 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.292938 last_received_ts = 111.292130 last_seq = 535 current_ts = 111.309601 current_received_ts = 111.308784 current_seq = 536 count = 524 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.309601 last_received_ts = 111.308784 last_seq = 536 current_ts = 111.326263 current_received_ts = 111.325439 current_seq = 537 count = 525 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.326263 last_received_ts = 111.325439 last_seq = 537 current_ts = 111.342926 current_received_ts = 111.342125 current_seq = 538 count = 526 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.342926 last_received_ts = 111.342125 last_seq = 538 current_ts = 111.359589 current_received_ts = 111.358780 current_seq = 539 count = 527 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 84us (kms_flip:3952) DEBUG: name = flip last_ts = 111.359589 last_received_ts = 111.358780 last_seq = 539 current_ts = 111.376251 current_received_ts = 111.375450 current_seq = 540 count = 528 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 59us (kms_flip:3952) DEBUG: name = flip last_ts = 111.376251 last_received_ts = 111.375450 last_seq = 540 current_ts = 111.392914 current_received_ts = 111.392105 current_seq = 541 count = 529 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.392914 last_received_ts = 111.392105 last_seq = 541 current_ts = 111.409576 current_received_ts = 111.408775 current_seq = 542 count = 530 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.409576 last_received_ts = 111.408775 last_seq = 542 current_ts = 111.426247 current_received_ts = 111.425430 current_seq = 543 count = 531 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 62us (kms_flip:3952) DEBUG: name = flip last_ts = 111.426247 last_received_ts = 111.425430 last_seq = 543 current_ts = 111.442909 current_received_ts = 111.442093 current_seq = 544 count = 532 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.442909 last_received_ts = 111.442093 last_seq = 544 current_ts = 111.459572 current_received_ts = 111.458763 current_seq = 545 count = 533 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.459572 last_received_ts = 111.458763 last_seq = 545 current_ts = 111.476242 current_received_ts = 111.475426 current_seq = 546 count = 534 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.476242 last_received_ts = 111.475426 last_seq = 546 current_ts = 111.492897 current_received_ts = 111.492088 current_seq = 547 count = 535 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.492897 last_received_ts = 111.492088 last_seq = 547 current_ts = 111.509560 current_received_ts = 111.508759 current_seq = 548 count = 536 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 111.509560 last_received_ts = 111.508759 last_seq = 548 current_ts = 111.526230 current_received_ts = 111.525414 current_seq = 549 count = 537 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 111.526230 last_received_ts = 111.525414 last_seq = 549 current_ts = 111.542892 current_received_ts = 111.542076 current_seq = 550 count = 538 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 111.542892 last_received_ts = 111.542076 last_seq = 550 current_ts = 111.559555 current_received_ts = 111.558739 current_seq = 551 count = 539 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 65us (kms_flip:3952) DEBUG: name = flip last_ts = 111.559555 last_received_ts = 111.558739 last_seq = 551 current_ts = 111.576218 current_received_ts = 111.575394 current_seq = 552 count = 540 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.576218 last_received_ts = 111.575394 last_seq = 552 current_ts = 111.592880 current_received_ts = 111.592079 current_seq = 553 count = 541 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.592880 last_received_ts = 111.592079 last_seq = 553 current_ts = 111.609543 current_received_ts = 111.608734 current_seq = 554 count = 542 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 85us (kms_flip:3952) DEBUG: name = flip last_ts = 111.609543 last_received_ts = 111.608734 last_seq = 554 current_ts = 111.626205 current_received_ts = 111.625389 current_seq = 555 count = 543 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.626205 last_received_ts = 111.625389 last_seq = 555 current_ts = 111.642868 current_received_ts = 111.642059 current_seq = 556 count = 544 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.642868 last_received_ts = 111.642059 last_seq = 556 current_ts = 111.659531 current_received_ts = 111.658722 current_seq = 557 count = 545 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.659531 last_received_ts = 111.658722 last_seq = 557 current_ts = 111.676201 current_received_ts = 111.675377 current_seq = 558 count = 546 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.676201 last_received_ts = 111.675377 last_seq = 558 current_ts = 111.692863 current_received_ts = 111.692047 current_seq = 559 count = 547 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.692863 last_received_ts = 111.692047 last_seq = 559 current_ts = 111.709526 current_received_ts = 111.708717 current_seq = 560 count = 548 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 61us (kms_flip:3952) DEBUG: name = flip last_ts = 111.709526 last_received_ts = 111.708717 last_seq = 560 current_ts = 111.726189 current_received_ts = 111.725380 current_seq = 561 count = 549 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 111.726189 last_received_ts = 111.725380 last_seq = 561 current_ts = 111.742851 current_received_ts = 111.742043 current_seq = 562 count = 550 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.742851 last_received_ts = 111.742043 last_seq = 562 current_ts = 111.759514 current_received_ts = 111.758713 current_seq = 563 count = 551 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 111.759514 last_received_ts = 111.758713 last_seq = 563 current_ts = 111.776176 current_received_ts = 111.775368 current_seq = 564 count = 552 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 111.776176 last_received_ts = 111.775368 last_seq = 564 current_ts = 111.792847 current_received_ts = 111.792053 current_seq = 565 count = 553 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 66us (kms_flip:3952) DEBUG: name = flip last_ts = 111.792847 last_received_ts = 111.792053 last_seq = 565 current_ts = 111.809509 current_received_ts = 111.808693 current_seq = 566 count = 554 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 60us (kms_flip:3952) DEBUG: name = flip last_ts = 111.809509 last_received_ts = 111.808693 last_seq = 566 current_ts = 111.826172 current_received_ts = 111.825371 current_seq = 567 count = 555 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 56us (kms_flip:3952) DEBUG: name = flip last_ts = 111.826172 last_received_ts = 111.825371 last_seq = 567 current_ts = 111.842834 current_received_ts = 111.842064 current_seq = 568 count = 556 seq_step = 1 (kms_flip:3952) DEBUG: Vblank took 1635us (kms_flip:3952) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:3952) CRITICAL: Failed assertion: end - start < 500 (kms_flip:3952) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:3952) igt_core-INFO: Stack trace: (kms_flip:3952) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:3952) igt_core-INFO: #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() (kms_flip:3952) igt_core-INFO: #2 ../tests/kms_flip.c:1891 run_test() (kms_flip:3952) igt_core-INFO: #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047() (kms_flip:3952) igt_core-INFO: #4 ../tests/kms_flip.c:2047 main() (kms_flip:3952) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:3952) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:3952) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (10.534s)
Dmesg	<6> [101.383638] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [101.395024] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:433] <7> [101.395422] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:434] <7> [101.462766] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [101.462902] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [101.463143] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [101.463262] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [101.463374] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [101.463481] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [101.463588] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [101.463692] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [101.463796] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [101.463900] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [101.464009] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [101.464113] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [101.464216] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [101.464318] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [101.464422] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [101.464525] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [101.464628] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [101.464730] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [101.464833] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [101.464941] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [101.465045] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [101.465146] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [101.465248] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [101.465349] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [101.465450] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [101.465552] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [101.465653] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [101.465754] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [101.465855] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [101.465961] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [101.466063] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [101.466165] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [101.466266] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [101.466367] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [101.466468] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [101.466571] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [101.466673] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [101.466774] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [101.466875] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [101.466986] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [101.467090] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [101.467245] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [101.467328] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [101.467442] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0 <7> [101.467518] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [101.467590] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm <7> [101.467660] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [101.467732] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [101.467802] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [101.467892] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [101.468155] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400 <7> [101.468273] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400 <7> [101.468385] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [101.468494] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [101.468602] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [101.468712] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [101.468842] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [101.468959] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [101.469069] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [101.469177] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [101.469336] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [101.469455] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [101.469567] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [101.469678] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [101.469789] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [101.469900] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [101.470015] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [101.470220] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [101.470956] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [101.471111] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [101.471861] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [101.472347] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [101.674227] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [101.675684] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [101.688413] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [101.689136] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [101.689723] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [101.740625] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [101.741253] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [101.741787] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [101.742269] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [101.742845] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [101.742750] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [101.743384] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [101.743911] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [101.744304] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [101.744628] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [101.744943] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [101.745270] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [101.745579] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [101.745888] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [101.746210] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [101.746524] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [101.746835] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [101.747164] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [101.747473] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [101.747782] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [101.748106] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [101.748519] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [101.748814] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [101.749110] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [101.749631] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [101.750060] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [101.750540] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [101.750873] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [101.751320] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [101.751608] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [101.753124] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [101.753653] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [101.754110] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [101.754201] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [101.754459] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [101.754897] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [101.755238] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [101.755570] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [101.755882] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [101.756206] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [101.756495] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [101.756766] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [101.757039] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [101.757287] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [101.757533] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [101.757765] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [101.757999] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [101.758218] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [101.758436] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [101.758641] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [101.758843] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [101.759044] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [101.759235] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [101.759420] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [101.759597] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [101.759773] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [101.759942] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [101.760214] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [101.760379] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [101.760538] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [101.760692] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [101.760841] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [101.760994] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [101.761138] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [101.761281] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [101.761423] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [101.761558] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [101.761686] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [101.761815] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [101.761938] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [101.762068] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [101.762191] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [101.762311] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [101.762432] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [101.762550] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [101.762662] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [101.762770] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [101.762880] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [101.763075] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [101.763169] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [101.763281] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [101.763363] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:264:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [101.763435] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [101.763506] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [101.763576] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [101.763645] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [101.763750] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [101.763873] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [101.764043] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [101.764165] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [101.764275] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [101.764384] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [101.764496] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [101.764639] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [101.764756] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [101.764865] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [101.764986] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [101.765135] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [101.765240] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [101.765351] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [101.765471] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [101.765587] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [101.765700] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [101.765812] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [101.765925] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [101.766046] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [101.766158] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [101.766271] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [101.766382] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [101.766495] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [101.766606] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [101.766718] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [101.766829] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [101.766941] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [101.767063] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [101.767179] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [101.767290] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [101.767404] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [101.767517] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [101.767628] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [101.767740] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [101.767851] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [101.767972] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [101.768085] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [101.768198] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [101.768313] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [101.768424] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [101.768536] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [101.768648] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [101.768760] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855 <7> [101.768872] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [101.768988] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [101.769100] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [101.769210] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [101.769318] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [101.769429] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [101.769539] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [101.769651] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [101.769759] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [101.769868] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [101.770009] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [101.770128] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [101.770237] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [101.770346] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [101.770458] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [101.770568] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [101.770677] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [101.770785] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [101.770893] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [101.771022] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [101.771039] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [101.771139] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [101.771201] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [101.771251] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [101.771311] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [101.771362] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [101.771448] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [101.771471] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [101.771584] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [101.771692] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [101.771801] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [101.771911] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:433] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [101.772035] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [101.772147] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [101.772257] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [101.772366] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [101.772475] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [101.772583] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [101.772693] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [101.773264] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [101.773398] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [101.773661] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [101.773827] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [101.773996] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [101.774173] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [101.774305] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [101.774439] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [101.774553] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [101.774668] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [101.774756] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [101.774840] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [101.774924] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [101.775025] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [101.775112] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [101.775196] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [101.775276] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [101.775355] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [101.775435] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [101.775513] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [101.775536] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [101.775598] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [101.775664] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [101.775678] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [101.775763] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [101.775784] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [101.775903] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [101.775982] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [101.776074] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [101.776205] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [101.777026] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [101.777175] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [101.779274] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [101.779390] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (462 ms remaining) <7> [102.250433] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [102.312962] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [102.314119] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [102.314932] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [102.350501] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [102.351138] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [102.351648] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [102.352130] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [102.520471] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [102.521670] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [102.522557] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [102.525706] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [102.527838] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [102.529242] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [102.531142] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [102.532819] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [102.534322] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [102.534874] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [102.536640] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [102.537207] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [102.538259] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [102.539049] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [102.539606] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [102.540233] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 192000 <7> [102.555893] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [102.558028] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [102.558605] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <7> [105.106171] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off <7> [105.106820] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [111.873353] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [111.873709] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [111.873915] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [111.918086] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

10.53 seconds

Hostname

shard-lnl-4

Igt-Version

IGT-Version: 2.3-g31b303e63 (x86_64) (Linux: 7.0.0-rc5-lgci-xe-xe-pw-163788v1-debug+ x86_64)

Out

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

Err

Starting dynamic subtest: B-eDP1
(kms_flip:3952) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:3952) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3952) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:3952) DEBUG: Vblank took 36us
(kms_flip:3952) DEBUG: name = flip
last_ts = 109.826546
last_received_ts = 109.826096
last_seq = 447
current_ts = 109.843208
current_received_ts = 109.842659
current_seq = 448
count = 436
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 116us
(kms_flip:3952) DEBUG: name = flip
last_ts = 109.843208
last_received_ts = 109.842659
last_seq = 448
current_ts = 109.859871
current_received_ts = 109.859314
current_seq = 449
count = 437
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 163us
(kms_flip:3952) DEBUG: name = flip
last_ts = 109.859871
last_received_ts = 109.859314
last_seq = 449
current_ts = 109.876534
current_received_ts = 109.875786
current_seq = 450
count = 438
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 118us
(kms_flip:3952) DEBUG: name = flip
last_ts = 109.876534
last_received_ts = 109.875786
last_seq = 450
current_ts = 109.893204
current_received_ts = 109.892403
current_seq = 451
count = 439
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 80us
(kms_flip:3952) DEBUG: name = flip
last_ts = 109.893204
last_received_ts = 109.892403
last_seq = 451
current_ts = 109.909859
current_received_ts = 109.909050
current_seq = 452
count = 440
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 68us
(kms_flip:3952) DEBUG: name = flip
last_ts = 109.909859
last_received_ts = 109.909050
last_seq = 452
current_ts = 109.926521
current_received_ts = 109.925713
current_seq = 453
count = 441
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 67us
(kms_flip:3952) DEBUG: name = flip
last_ts = 109.926521
last_received_ts = 109.925713
last_seq = 453
current_ts = 109.943192
current_received_ts = 109.942375
current_seq = 454
count = 442
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 109.943192
last_received_ts = 109.942375
last_seq = 454
current_ts = 109.959854
current_received_ts = 109.959053
current_seq = 455
count = 443
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 67us
(kms_flip:3952) DEBUG: name = flip
last_ts = 109.959854
last_received_ts = 109.959053
last_seq = 455
current_ts = 109.976517
current_received_ts = 109.975700
current_seq = 456
count = 444
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 109.976517
last_received_ts = 109.975700
last_seq = 456
current_ts = 109.993179
current_received_ts = 109.992599
current_seq = 457
count = 445
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 104us
(kms_flip:3952) DEBUG: name = flip
last_ts = 109.993179
last_received_ts = 109.992599
last_seq = 457
current_ts = 110.009842
current_received_ts = 110.010437
current_seq = 458
count = 446
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 89us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.009842
last_received_ts = 110.010437
last_seq = 458
current_ts = 110.026505
current_received_ts = 110.025711
current_seq = 459
count = 447
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 101us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.026505
last_received_ts = 110.025711
last_seq = 459
current_ts = 110.043175
current_received_ts = 110.042366
current_seq = 460
count = 448
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 69us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.043175
last_received_ts = 110.042366
last_seq = 460
current_ts = 110.059830
current_received_ts = 110.059067
current_seq = 461
count = 449
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 69us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.059830
last_received_ts = 110.059067
last_seq = 461
current_ts = 110.076492
current_received_ts = 110.075714
current_seq = 462
count = 450
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 106us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.076492
last_received_ts = 110.075714
last_seq = 462
current_ts = 110.093163
current_received_ts = 110.092354
current_seq = 463
count = 451
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 79us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.093163
last_received_ts = 110.092354
last_seq = 463
current_ts = 110.109825
current_received_ts = 110.109039
current_seq = 464
count = 452
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 72us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.109825
last_received_ts = 110.109039
last_seq = 464
current_ts = 110.126488
current_received_ts = 110.125687
current_seq = 465
count = 453
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 68us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.126488
last_received_ts = 110.125687
last_seq = 465
current_ts = 110.143150
current_received_ts = 110.142342
current_seq = 466
count = 454
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.143150
last_received_ts = 110.142342
last_seq = 466
current_ts = 110.159813
current_received_ts = 110.159042
current_seq = 467
count = 455
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.159813
last_received_ts = 110.159042
last_seq = 467
current_ts = 110.176476
current_received_ts = 110.175674
current_seq = 468
count = 456
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.176476
last_received_ts = 110.175674
last_seq = 468
current_ts = 110.193146
current_received_ts = 110.192329
current_seq = 469
count = 457
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.193146
last_received_ts = 110.192329
last_seq = 469
current_ts = 110.209801
current_received_ts = 110.209000
current_seq = 470
count = 458
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.209801
last_received_ts = 110.209000
last_seq = 470
current_ts = 110.226463
current_received_ts = 110.225655
current_seq = 471
count = 459
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.226463
last_received_ts = 110.225655
last_seq = 471
current_ts = 110.243134
current_received_ts = 110.242317
current_seq = 472
count = 460
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.243134
last_received_ts = 110.242317
last_seq = 472
current_ts = 110.259796
current_received_ts = 110.258987
current_seq = 473
count = 461
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 67us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.259796
last_received_ts = 110.258987
last_seq = 473
current_ts = 110.276459
current_received_ts = 110.275650
current_seq = 474
count = 462
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 67us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.276459
last_received_ts = 110.275650
last_seq = 474
current_ts = 110.293121
current_received_ts = 110.292305
current_seq = 475
count = 463
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 90us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.293121
last_received_ts = 110.292305
last_seq = 475
current_ts = 110.309792
current_received_ts = 110.308975
current_seq = 476
count = 464
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 76us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.309792
last_received_ts = 110.308975
last_seq = 476
current_ts = 110.326447
current_received_ts = 110.325645
current_seq = 477
count = 465
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.326447
last_received_ts = 110.325645
last_seq = 477
current_ts = 110.343117
current_received_ts = 110.342300
current_seq = 478
count = 466
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.343117
last_received_ts = 110.342300
last_seq = 478
current_ts = 110.359772
current_received_ts = 110.358963
current_seq = 479
count = 467
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 76us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.359772
last_received_ts = 110.358963
last_seq = 479
current_ts = 110.376442
current_received_ts = 110.375633
current_seq = 480
count = 468
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.376442
last_received_ts = 110.375633
last_seq = 480
current_ts = 110.393105
current_received_ts = 110.392288
current_seq = 481
count = 469
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.393105
last_received_ts = 110.392288
last_seq = 481
current_ts = 110.409767
current_received_ts = 110.408958
current_seq = 482
count = 470
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 100us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.409767
last_received_ts = 110.408958
last_seq = 482
current_ts = 110.426430
current_received_ts = 110.425621
current_seq = 483
count = 471
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.426430
last_received_ts = 110.425621
last_seq = 483
current_ts = 110.443092
current_received_ts = 110.442284
current_seq = 484
count = 472
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 64us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.443092
last_received_ts = 110.442284
last_seq = 484
current_ts = 110.459763
current_received_ts = 110.458954
current_seq = 485
count = 473
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 84us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.459763
last_received_ts = 110.458954
last_seq = 485
current_ts = 110.476418
current_received_ts = 110.475609
current_seq = 486
count = 474
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.476418
last_received_ts = 110.475609
last_seq = 486
current_ts = 110.493088
current_received_ts = 110.492264
current_seq = 487
count = 475
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.493088
last_received_ts = 110.492264
last_seq = 487
current_ts = 110.509750
current_received_ts = 110.508934
current_seq = 488
count = 476
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 94us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.509750
last_received_ts = 110.508934
last_seq = 488
current_ts = 110.526413
current_received_ts = 110.525604
current_seq = 489
count = 477
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.526413
last_received_ts = 110.525604
last_seq = 489
current_ts = 110.543076
current_received_ts = 110.542267
current_seq = 490
count = 478
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 94us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.543076
last_received_ts = 110.542267
last_seq = 490
current_ts = 110.559738
current_received_ts = 110.558937
current_seq = 491
count = 479
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 76us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.559738
last_received_ts = 110.558937
last_seq = 491
current_ts = 110.576401
current_received_ts = 110.575600
current_seq = 492
count = 480
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.576401
last_received_ts = 110.575600
last_seq = 492
current_ts = 110.593063
current_received_ts = 110.592262
current_seq = 493
count = 481
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 68us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.593063
last_received_ts = 110.592262
last_seq = 493
current_ts = 110.609726
current_received_ts = 110.608925
current_seq = 494
count = 482
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 99us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.609726
last_received_ts = 110.608925
last_seq = 494
current_ts = 110.626389
current_received_ts = 110.625587
current_seq = 495
count = 483
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 67us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.626389
last_received_ts = 110.625587
last_seq = 495
current_ts = 110.643059
current_received_ts = 110.642250
current_seq = 496
count = 484
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.643059
last_received_ts = 110.642250
last_seq = 496
current_ts = 110.659721
current_received_ts = 110.658920
current_seq = 497
count = 485
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 109us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.659721
last_received_ts = 110.658920
last_seq = 497
current_ts = 110.676384
current_received_ts = 110.675583
current_seq = 498
count = 486
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.676384
last_received_ts = 110.675583
last_seq = 498
current_ts = 110.693047
current_received_ts = 110.692245
current_seq = 499
count = 487
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.693047
last_received_ts = 110.692245
last_seq = 499
current_ts = 110.709709
current_received_ts = 110.708908
current_seq = 500
count = 488
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.709709
last_received_ts = 110.708908
last_seq = 500
current_ts = 110.726372
current_received_ts = 110.725571
current_seq = 501
count = 489
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.726372
last_received_ts = 110.725571
last_seq = 501
current_ts = 110.743042
current_received_ts = 110.742226
current_seq = 502
count = 490
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.743042
last_received_ts = 110.742226
last_seq = 502
current_ts = 110.759697
current_received_ts = 110.758888
current_seq = 503
count = 491
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.759697
last_received_ts = 110.758888
last_seq = 503
current_ts = 110.776367
current_received_ts = 110.775558
current_seq = 504
count = 492
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.776367
last_received_ts = 110.775558
last_seq = 504
current_ts = 110.793030
current_received_ts = 110.792221
current_seq = 505
count = 493
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.793030
last_received_ts = 110.792221
last_seq = 505
current_ts = 110.809692
current_received_ts = 110.808884
current_seq = 506
count = 494
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 59us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.809692
last_received_ts = 110.808884
last_seq = 506
current_ts = 110.826355
current_received_ts = 110.825546
current_seq = 507
count = 495
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.826355
last_received_ts = 110.825546
last_seq = 507
current_ts = 110.843018
current_received_ts = 110.842201
current_seq = 508
count = 496
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 59us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.843018
last_received_ts = 110.842201
last_seq = 508
current_ts = 110.859680
current_received_ts = 110.858864
current_seq = 509
count = 497
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 45us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.859680
last_received_ts = 110.858864
last_seq = 509
current_ts = 110.876343
current_received_ts = 110.875526
current_seq = 510
count = 498
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.876343
last_received_ts = 110.875526
last_seq = 510
current_ts = 110.893013
current_received_ts = 110.892189
current_seq = 511
count = 499
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 59us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.893013
last_received_ts = 110.892189
last_seq = 511
current_ts = 110.909676
current_received_ts = 110.908859
current_seq = 512
count = 500
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.909676
last_received_ts = 110.908859
last_seq = 512
current_ts = 110.926338
current_received_ts = 110.925529
current_seq = 513
count = 501
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.926338
last_received_ts = 110.925529
last_seq = 513
current_ts = 110.943001
current_received_ts = 110.942184
current_seq = 514
count = 502
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.943001
last_received_ts = 110.942184
last_seq = 514
current_ts = 110.959663
current_received_ts = 110.958855
current_seq = 515
count = 503
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.959663
last_received_ts = 110.958855
last_seq = 515
current_ts = 110.976326
current_received_ts = 110.975525
current_seq = 516
count = 504
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.976326
last_received_ts = 110.975525
last_seq = 516
current_ts = 110.992996
current_received_ts = 110.992172
current_seq = 517
count = 505
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 59us
(kms_flip:3952) DEBUG: name = flip
last_ts = 110.992996
last_received_ts = 110.992172
last_seq = 517
current_ts = 111.009651
current_received_ts = 111.008842
current_seq = 518
count = 506
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.009651
last_received_ts = 111.008842
last_seq = 518
current_ts = 111.026314
current_received_ts = 111.025513
current_seq = 519
count = 507
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.026314
last_received_ts = 111.025513
last_seq = 519
current_ts = 111.042984
current_received_ts = 111.042175
current_seq = 520
count = 508
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.042984
last_received_ts = 111.042175
last_seq = 520
current_ts = 111.059647
current_received_ts = 111.058830
current_seq = 521
count = 509
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.059647
last_received_ts = 111.058830
last_seq = 521
current_ts = 111.076309
current_received_ts = 111.075500
current_seq = 522
count = 510
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.076309
last_received_ts = 111.075500
last_seq = 522
current_ts = 111.092972
current_received_ts = 111.092163
current_seq = 523
count = 511
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.092972
last_received_ts = 111.092163
last_seq = 523
current_ts = 111.109634
current_received_ts = 111.108818
current_seq = 524
count = 512
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.109634
last_received_ts = 111.108818
last_seq = 524
current_ts = 111.126297
current_received_ts = 111.125496
current_seq = 525
count = 513
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 64us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.126297
last_received_ts = 111.125496
last_seq = 525
current_ts = 111.142967
current_received_ts = 111.142151
current_seq = 526
count = 514
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.142967
last_received_ts = 111.142151
last_seq = 526
current_ts = 111.159622
current_received_ts = 111.158821
current_seq = 527
count = 515
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.159622
last_received_ts = 111.158821
last_seq = 527
current_ts = 111.176292
current_received_ts = 111.175484
current_seq = 528
count = 516
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.176292
last_received_ts = 111.175484
last_seq = 528
current_ts = 111.192955
current_received_ts = 111.192139
current_seq = 529
count = 517
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.192955
last_received_ts = 111.192139
last_seq = 529
current_ts = 111.209618
current_received_ts = 111.208809
current_seq = 530
count = 518
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 59us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.209618
last_received_ts = 111.208809
last_seq = 530
current_ts = 111.226280
current_received_ts = 111.225471
current_seq = 531
count = 519
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.226280
last_received_ts = 111.225471
last_seq = 531
current_ts = 111.242950
current_received_ts = 111.242126
current_seq = 532
count = 520
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 59us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.242950
last_received_ts = 111.242126
last_seq = 532
current_ts = 111.259605
current_received_ts = 111.258797
current_seq = 533
count = 521
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 59us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.259605
last_received_ts = 111.258797
last_seq = 533
current_ts = 111.276268
current_received_ts = 111.275467
current_seq = 534
count = 522
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.276268
last_received_ts = 111.275467
last_seq = 534
current_ts = 111.292938
current_received_ts = 111.292130
current_seq = 535
count = 523
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.292938
last_received_ts = 111.292130
last_seq = 535
current_ts = 111.309601
current_received_ts = 111.308784
current_seq = 536
count = 524
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.309601
last_received_ts = 111.308784
last_seq = 536
current_ts = 111.326263
current_received_ts = 111.325439
current_seq = 537
count = 525
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.326263
last_received_ts = 111.325439
last_seq = 537
current_ts = 111.342926
current_received_ts = 111.342125
current_seq = 538
count = 526
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.342926
last_received_ts = 111.342125
last_seq = 538
current_ts = 111.359589
current_received_ts = 111.358780
current_seq = 539
count = 527
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 84us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.359589
last_received_ts = 111.358780
last_seq = 539
current_ts = 111.376251
current_received_ts = 111.375450
current_seq = 540
count = 528
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 59us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.376251
last_received_ts = 111.375450
last_seq = 540
current_ts = 111.392914
current_received_ts = 111.392105
current_seq = 541
count = 529
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.392914
last_received_ts = 111.392105
last_seq = 541
current_ts = 111.409576
current_received_ts = 111.408775
current_seq = 542
count = 530
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.409576
last_received_ts = 111.408775
last_seq = 542
current_ts = 111.426247
current_received_ts = 111.425430
current_seq = 543
count = 531
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 62us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.426247
last_received_ts = 111.425430
last_seq = 543
current_ts = 111.442909
current_received_ts = 111.442093
current_seq = 544
count = 532
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.442909
last_received_ts = 111.442093
last_seq = 544
current_ts = 111.459572
current_received_ts = 111.458763
current_seq = 545
count = 533
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.459572
last_received_ts = 111.458763
last_seq = 545
current_ts = 111.476242
current_received_ts = 111.475426
current_seq = 546
count = 534
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.476242
last_received_ts = 111.475426
last_seq = 546
current_ts = 111.492897
current_received_ts = 111.492088
current_seq = 547
count = 535
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.492897
last_received_ts = 111.492088
last_seq = 547
current_ts = 111.509560
current_received_ts = 111.508759
current_seq = 548
count = 536
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.509560
last_received_ts = 111.508759
last_seq = 548
current_ts = 111.526230
current_received_ts = 111.525414
current_seq = 549
count = 537
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.526230
last_received_ts = 111.525414
last_seq = 549
current_ts = 111.542892
current_received_ts = 111.542076
current_seq = 550
count = 538
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.542892
last_received_ts = 111.542076
last_seq = 550
current_ts = 111.559555
current_received_ts = 111.558739
current_seq = 551
count = 539
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 65us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.559555
last_received_ts = 111.558739
last_seq = 551
current_ts = 111.576218
current_received_ts = 111.575394
current_seq = 552
count = 540
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.576218
last_received_ts = 111.575394
last_seq = 552
current_ts = 111.592880
current_received_ts = 111.592079
current_seq = 553
count = 541
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.592880
last_received_ts = 111.592079
last_seq = 553
current_ts = 111.609543
current_received_ts = 111.608734
current_seq = 554
count = 542
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 85us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.609543
last_received_ts = 111.608734
last_seq = 554
current_ts = 111.626205
current_received_ts = 111.625389
current_seq = 555
count = 543
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.626205
last_received_ts = 111.625389
last_seq = 555
current_ts = 111.642868
current_received_ts = 111.642059
current_seq = 556
count = 544
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.642868
last_received_ts = 111.642059
last_seq = 556
current_ts = 111.659531
current_received_ts = 111.658722
current_seq = 557
count = 545
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.659531
last_received_ts = 111.658722
last_seq = 557
current_ts = 111.676201
current_received_ts = 111.675377
current_seq = 558
count = 546
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.676201
last_received_ts = 111.675377
last_seq = 558
current_ts = 111.692863
current_received_ts = 111.692047
current_seq = 559
count = 547
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.692863
last_received_ts = 111.692047
last_seq = 559
current_ts = 111.709526
current_received_ts = 111.708717
current_seq = 560
count = 548
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 61us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.709526
last_received_ts = 111.708717
last_seq = 560
current_ts = 111.726189
current_received_ts = 111.725380
current_seq = 561
count = 549
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.726189
last_received_ts = 111.725380
last_seq = 561
current_ts = 111.742851
current_received_ts = 111.742043
current_seq = 562
count = 550
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.742851
last_received_ts = 111.742043
last_seq = 562
current_ts = 111.759514
current_received_ts = 111.758713
current_seq = 563
count = 551
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.759514
last_received_ts = 111.758713
last_seq = 563
current_ts = 111.776176
current_received_ts = 111.775368
current_seq = 564
count = 552
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.776176
last_received_ts = 111.775368
last_seq = 564
current_ts = 111.792847
current_received_ts = 111.792053
current_seq = 565
count = 553
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 66us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.792847
last_received_ts = 111.792053
last_seq = 565
current_ts = 111.809509
current_received_ts = 111.808693
current_seq = 566
count = 554
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 60us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.809509
last_received_ts = 111.808693
last_seq = 566
current_ts = 111.826172
current_received_ts = 111.825371
current_seq = 567
count = 555
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 56us
(kms_flip:3952) DEBUG: name = flip
last_ts = 111.826172
last_received_ts = 111.825371
last_seq = 567
current_ts = 111.842834
current_received_ts = 111.842064
current_seq = 568
count = 556
seq_step = 1
(kms_flip:3952) DEBUG: Vblank took 1635us
(kms_flip:3952) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:3952) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3952) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:3952) igt_core-INFO: Stack trace:
(kms_flip:3952) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:3952) igt_core-INFO:   #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0()
(kms_flip:3952) igt_core-INFO:   #2 ../tests/kms_flip.c:1891 run_test()
(kms_flip:3952) igt_core-INFO:   #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047()
(kms_flip:3952) igt_core-INFO:   #4 ../tests/kms_flip.c:2047 main()
(kms_flip:3952) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3952) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3952) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (10.534s)

Dmesg

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

<7> [101.395024] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:433]

<7> [101.395422] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:434]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [101.467442] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0

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

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

<7> [101.467660] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [101.467732] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [101.467802] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [101.467892] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0

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

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

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

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

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

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

<7> [101.468842] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz

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

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

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

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

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

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

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

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

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

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

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

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

<7> [101.471111] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [101.764639] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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