igt@kms_flip@flip-vs-expired-vblank@c-edp1 on re-lnl-7@xe-3827-690ed0728a0e31e6b2a309029af5ba224981ff60 Test details

Detail	Value
Duration	3.25 seconds
Igt-Version	IGT-Version: 2.1-g162a06a82 (x86_64) (Linux: 6.17.0-rc7-lgci-xe-xe-3827-690ed0728a0e31e6b+ x86_64)
Out	Starting dynamic subtest: C-eDP1 2560x1600: 240 1071010 2560 2608 2640 2720 1600 1610 1615 1640 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1884 run_test() #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040() #4 ../tests/kms_flip.c:2040 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest C-eDP1: FAIL (3.245s)
Err	Starting dynamic subtest: C-eDP1 (kms_flip:2765) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2765) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest C-eDP1 failed. ** DEBUG (kms_flip:2765) DEBUG: name = flip last_ts = 247.644730 last_received_ts = 247.644989 last_seq = 5471 current_ts = 247.648895 current_received_ts = 247.649170 current_seq = 5472 count = 331 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 80us (kms_flip:2765) DEBUG: name = flip last_ts = 247.648895 last_received_ts = 247.649170 last_seq = 5472 current_ts = 247.653061 current_received_ts = 247.653290 current_seq = 5473 count = 332 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 80us (kms_flip:2765) DEBUG: name = flip last_ts = 247.653061 last_received_ts = 247.653290 last_seq = 5473 current_ts = 247.657227 current_received_ts = 247.657455 current_seq = 5474 count = 333 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 82us (kms_flip:2765) DEBUG: name = flip last_ts = 247.657227 last_received_ts = 247.657455 last_seq = 5474 current_ts = 247.661392 current_received_ts = 247.661667 current_seq = 5475 count = 334 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 93us (kms_flip:2765) DEBUG: name = flip last_ts = 247.661392 last_received_ts = 247.661667 last_seq = 5475 current_ts = 247.665558 current_received_ts = 247.665833 current_seq = 5476 count = 335 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.665558 last_received_ts = 247.665833 last_seq = 5476 current_ts = 247.669724 current_received_ts = 247.670029 current_seq = 5477 count = 336 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 55us (kms_flip:2765) DEBUG: name = flip last_ts = 247.669724 last_received_ts = 247.670029 last_seq = 5477 current_ts = 247.673889 current_received_ts = 247.674164 current_seq = 5478 count = 337 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.673889 last_received_ts = 247.674164 last_seq = 5478 current_ts = 247.678040 current_received_ts = 247.678314 current_seq = 5479 count = 338 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.678040 last_received_ts = 247.678314 last_seq = 5479 current_ts = 247.682205 current_received_ts = 247.682358 current_seq = 5480 count = 339 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 92us (kms_flip:2765) DEBUG: name = flip last_ts = 247.682205 last_received_ts = 247.682358 last_seq = 5480 current_ts = 247.686371 current_received_ts = 247.686646 current_seq = 5481 count = 340 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 101us (kms_flip:2765) DEBUG: name = flip last_ts = 247.686371 last_received_ts = 247.686646 last_seq = 5481 current_ts = 247.690536 current_received_ts = 247.690842 current_seq = 5482 count = 341 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 100us (kms_flip:2765) DEBUG: name = flip last_ts = 247.690536 last_received_ts = 247.690842 last_seq = 5482 current_ts = 247.694702 current_received_ts = 247.695023 current_seq = 5483 count = 342 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 100us (kms_flip:2765) DEBUG: name = flip last_ts = 247.694702 last_received_ts = 247.695023 last_seq = 5483 current_ts = 247.698868 current_received_ts = 247.699188 current_seq = 5484 count = 343 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 87us (kms_flip:2765) DEBUG: name = flip last_ts = 247.698868 last_received_ts = 247.699188 last_seq = 5484 current_ts = 247.703033 current_received_ts = 247.703293 current_seq = 5485 count = 344 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 101us (kms_flip:2765) DEBUG: name = flip last_ts = 247.703033 last_received_ts = 247.703293 last_seq = 5485 current_ts = 247.707199 current_received_ts = 247.707520 current_seq = 5486 count = 345 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 99us (kms_flip:2765) DEBUG: name = flip last_ts = 247.707199 last_received_ts = 247.707520 last_seq = 5486 current_ts = 247.711365 current_received_ts = 247.711655 current_seq = 5487 count = 346 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.711365 last_received_ts = 247.711655 last_seq = 5487 current_ts = 247.715530 current_received_ts = 247.715820 current_seq = 5488 count = 347 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 84us (kms_flip:2765) DEBUG: name = flip last_ts = 247.715530 last_received_ts = 247.715820 last_seq = 5488 current_ts = 247.719696 current_received_ts = 247.719986 current_seq = 5489 count = 348 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 82us (kms_flip:2765) DEBUG: name = flip last_ts = 247.719696 last_received_ts = 247.719986 last_seq = 5489 current_ts = 247.723862 current_received_ts = 247.724152 current_seq = 5490 count = 349 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.723862 last_received_ts = 247.724152 last_seq = 5490 current_ts = 247.728027 current_received_ts = 247.728302 current_seq = 5491 count = 350 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 56us (kms_flip:2765) DEBUG: name = flip last_ts = 247.728027 last_received_ts = 247.728302 last_seq = 5491 current_ts = 247.732193 current_received_ts = 247.732437 current_seq = 5492 count = 351 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 247.732193 last_received_ts = 247.732437 last_seq = 5492 current_ts = 247.736359 current_received_ts = 247.736633 current_seq = 5493 count = 352 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 92us (kms_flip:2765) DEBUG: name = flip last_ts = 247.736359 last_received_ts = 247.736633 last_seq = 5493 current_ts = 247.740524 current_received_ts = 247.740814 current_seq = 5494 count = 353 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 247.740524 last_received_ts = 247.740814 last_seq = 5494 current_ts = 247.744690 current_received_ts = 247.744965 current_seq = 5495 count = 354 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 119us (kms_flip:2765) DEBUG: name = flip last_ts = 247.744690 last_received_ts = 247.744965 last_seq = 5495 current_ts = 247.748856 current_received_ts = 247.749176 current_seq = 5496 count = 355 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 82us (kms_flip:2765) DEBUG: name = flip last_ts = 247.748856 last_received_ts = 247.749176 last_seq = 5496 current_ts = 247.753021 current_received_ts = 247.753220 current_seq = 5497 count = 356 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.753021 last_received_ts = 247.753220 last_seq = 5497 current_ts = 247.757187 current_received_ts = 247.757446 current_seq = 5498 count = 357 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.757187 last_received_ts = 247.757446 last_seq = 5498 current_ts = 247.761353 current_received_ts = 247.761627 current_seq = 5499 count = 358 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.761353 last_received_ts = 247.761627 last_seq = 5499 current_ts = 247.765518 current_received_ts = 247.765793 current_seq = 5500 count = 359 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 87us (kms_flip:2765) DEBUG: name = flip last_ts = 247.765518 last_received_ts = 247.765793 last_seq = 5500 current_ts = 247.769684 current_received_ts = 247.769958 current_seq = 5501 count = 360 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 101us (kms_flip:2765) DEBUG: name = flip last_ts = 247.769684 last_received_ts = 247.769958 last_seq = 5501 current_ts = 247.773849 current_received_ts = 247.774124 current_seq = 5502 count = 361 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.773849 last_received_ts = 247.774124 last_seq = 5502 current_ts = 247.778015 current_received_ts = 247.778214 current_seq = 5503 count = 362 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 80us (kms_flip:2765) DEBUG: name = flip last_ts = 247.778015 last_received_ts = 247.778214 last_seq = 5503 current_ts = 247.782181 current_received_ts = 247.782425 current_seq = 5504 count = 363 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 80us (kms_flip:2765) DEBUG: name = flip last_ts = 247.782181 last_received_ts = 247.782425 last_seq = 5504 current_ts = 247.786346 current_received_ts = 247.786621 current_seq = 5505 count = 364 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.786346 last_received_ts = 247.786621 last_seq = 5505 current_ts = 247.790512 current_received_ts = 247.790787 current_seq = 5506 count = 365 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.790512 last_received_ts = 247.790787 last_seq = 5506 current_ts = 247.794678 current_received_ts = 247.794937 current_seq = 5507 count = 366 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 103us (kms_flip:2765) DEBUG: name = flip last_ts = 247.794678 last_received_ts = 247.794937 last_seq = 5507 current_ts = 247.798843 current_received_ts = 247.799149 current_seq = 5508 count = 367 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 85us (kms_flip:2765) DEBUG: name = flip last_ts = 247.798843 last_received_ts = 247.799149 last_seq = 5508 current_ts = 247.803009 current_received_ts = 247.803192 current_seq = 5509 count = 368 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 55us (kms_flip:2765) DEBUG: name = flip last_ts = 247.803009 last_received_ts = 247.803192 last_seq = 5509 current_ts = 247.807175 current_received_ts = 247.807388 current_seq = 5510 count = 369 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.807175 last_received_ts = 247.807388 last_seq = 5510 current_ts = 247.811340 current_received_ts = 247.811600 current_seq = 5511 count = 370 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 88us (kms_flip:2765) DEBUG: name = flip last_ts = 247.811340 last_received_ts = 247.811600 last_seq = 5511 current_ts = 247.815506 current_received_ts = 247.815796 current_seq = 5512 count = 371 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.815506 last_received_ts = 247.815796 last_seq = 5512 current_ts = 247.819656 current_received_ts = 247.819962 current_seq = 5513 count = 372 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 89us (kms_flip:2765) DEBUG: name = flip last_ts = 247.819656 last_received_ts = 247.819962 last_seq = 5513 current_ts = 247.823822 current_received_ts = 247.824142 current_seq = 5514 count = 373 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 87us (kms_flip:2765) DEBUG: name = flip last_ts = 247.823822 last_received_ts = 247.824142 last_seq = 5514 current_ts = 247.827988 current_received_ts = 247.828201 current_seq = 5515 count = 374 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 100us (kms_flip:2765) DEBUG: name = flip last_ts = 247.827988 last_received_ts = 247.828201 last_seq = 5515 current_ts = 247.832153 current_received_ts = 247.832397 current_seq = 5516 count = 375 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 100us (kms_flip:2765) DEBUG: name = flip last_ts = 247.832153 last_received_ts = 247.832397 last_seq = 5516 current_ts = 247.836319 current_received_ts = 247.836624 current_seq = 5517 count = 376 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 87us (kms_flip:2765) DEBUG: name = flip last_ts = 247.836319 last_received_ts = 247.836624 last_seq = 5517 current_ts = 247.840485 current_received_ts = 247.840790 current_seq = 5518 count = 377 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 100us (kms_flip:2765) DEBUG: name = flip last_ts = 247.840485 last_received_ts = 247.840790 last_seq = 5518 current_ts = 247.844650 current_received_ts = 247.844955 current_seq = 5519 count = 378 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 106us (kms_flip:2765) DEBUG: name = flip last_ts = 247.844650 last_received_ts = 247.844955 last_seq = 5519 current_ts = 247.848816 current_received_ts = 247.849152 current_seq = 5520 count = 379 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 87us (kms_flip:2765) DEBUG: name = flip last_ts = 247.848816 last_received_ts = 247.849152 last_seq = 5520 current_ts = 247.852982 current_received_ts = 247.853195 current_seq = 5521 count = 380 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 100us (kms_flip:2765) DEBUG: name = flip last_ts = 247.852982 last_received_ts = 247.853195 last_seq = 5521 current_ts = 247.857147 current_received_ts = 247.857391 current_seq = 5522 count = 381 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 93us (kms_flip:2765) DEBUG: name = flip last_ts = 247.857147 last_received_ts = 247.857391 last_seq = 5522 current_ts = 247.861313 current_received_ts = 247.861618 current_seq = 5523 count = 382 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 100us (kms_flip:2765) DEBUG: name = flip last_ts = 247.861313 last_received_ts = 247.861618 last_seq = 5523 current_ts = 247.865479 current_received_ts = 247.865768 current_seq = 5524 count = 383 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.865479 last_received_ts = 247.865768 last_seq = 5524 current_ts = 247.869644 current_received_ts = 247.869934 current_seq = 5525 count = 384 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 105us (kms_flip:2765) DEBUG: name = flip last_ts = 247.869644 last_received_ts = 247.869934 last_seq = 5525 current_ts = 247.873810 current_received_ts = 247.874115 current_seq = 5526 count = 385 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 87us (kms_flip:2765) DEBUG: name = flip last_ts = 247.873810 last_received_ts = 247.874115 last_seq = 5526 current_ts = 247.877975 current_received_ts = 247.878174 current_seq = 5527 count = 386 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 80us (kms_flip:2765) DEBUG: name = flip last_ts = 247.877975 last_received_ts = 247.878174 last_seq = 5527 current_ts = 247.882141 current_received_ts = 247.882355 current_seq = 5528 count = 387 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 247.882141 last_received_ts = 247.882355 last_seq = 5528 current_ts = 247.886307 current_received_ts = 247.886581 current_seq = 5529 count = 388 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 56us (kms_flip:2765) DEBUG: name = flip last_ts = 247.886307 last_received_ts = 247.886581 last_seq = 5529 current_ts = 247.890472 current_received_ts = 247.890762 current_seq = 5530 count = 389 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 92us (kms_flip:2765) DEBUG: name = flip last_ts = 247.890472 last_received_ts = 247.890762 last_seq = 5530 current_ts = 247.894638 current_received_ts = 247.894913 current_seq = 5531 count = 390 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 102us (kms_flip:2765) DEBUG: name = flip last_ts = 247.894638 last_received_ts = 247.894913 last_seq = 5531 current_ts = 247.898804 current_received_ts = 247.899109 current_seq = 5532 count = 391 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 80us (kms_flip:2765) DEBUG: name = flip last_ts = 247.898804 last_received_ts = 247.899109 last_seq = 5532 current_ts = 247.902969 current_received_ts = 247.903168 current_seq = 5533 count = 392 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 247.902969 last_received_ts = 247.903168 last_seq = 5533 current_ts = 247.907135 current_received_ts = 247.907349 current_seq = 5534 count = 393 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 88us (kms_flip:2765) DEBUG: name = flip last_ts = 247.907135 last_received_ts = 247.907349 last_seq = 5534 current_ts = 247.911301 current_received_ts = 247.911575 current_seq = 5535 count = 394 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.911301 last_received_ts = 247.911575 last_seq = 5535 current_ts = 247.915466 current_received_ts = 247.915741 current_seq = 5536 count = 395 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.915466 last_received_ts = 247.915741 last_seq = 5536 current_ts = 247.919632 current_received_ts = 247.919907 current_seq = 5537 count = 396 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 105us (kms_flip:2765) DEBUG: name = flip last_ts = 247.919632 last_received_ts = 247.919907 last_seq = 5537 current_ts = 247.923798 current_received_ts = 247.924088 current_seq = 5538 count = 397 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.923798 last_received_ts = 247.924088 last_seq = 5538 current_ts = 247.927963 current_received_ts = 247.928162 current_seq = 5539 count = 398 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 80us (kms_flip:2765) DEBUG: name = flip last_ts = 247.927963 last_received_ts = 247.928162 last_seq = 5539 current_ts = 247.932129 current_received_ts = 247.932343 current_seq = 5540 count = 399 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 92us (kms_flip:2765) DEBUG: name = flip last_ts = 247.932129 last_received_ts = 247.932343 last_seq = 5540 current_ts = 247.936295 current_received_ts = 247.936569 current_seq = 5541 count = 400 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 92us (kms_flip:2765) DEBUG: name = flip last_ts = 247.936295 last_received_ts = 247.936569 last_seq = 5541 current_ts = 247.940460 current_received_ts = 247.940720 current_seq = 5542 count = 401 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 59us (kms_flip:2765) DEBUG: name = flip last_ts = 247.940460 last_received_ts = 247.940720 last_seq = 5542 current_ts = 247.944626 current_received_ts = 247.944885 current_seq = 5543 count = 402 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 82us (kms_flip:2765) DEBUG: name = flip last_ts = 247.944626 last_received_ts = 247.944885 last_seq = 5543 current_ts = 247.948792 current_received_ts = 247.949066 current_seq = 5544 count = 403 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.948792 last_received_ts = 247.949066 last_seq = 5544 current_ts = 247.952957 current_received_ts = 247.953171 current_seq = 5545 count = 404 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 247.952957 last_received_ts = 247.953171 last_seq = 5545 current_ts = 247.957123 current_received_ts = 247.957352 current_seq = 5546 count = 405 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 80us (kms_flip:2765) DEBUG: name = flip last_ts = 247.957123 last_received_ts = 247.957352 last_seq = 5546 current_ts = 247.961273 current_received_ts = 247.961533 current_seq = 5547 count = 406 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 247.961273 last_received_ts = 247.961533 last_seq = 5547 current_ts = 247.965439 current_received_ts = 247.965714 current_seq = 5548 count = 407 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.965439 last_received_ts = 247.965714 last_seq = 5548 current_ts = 247.969604 current_received_ts = 247.969894 current_seq = 5549 count = 408 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 117us (kms_flip:2765) DEBUG: name = flip last_ts = 247.969604 last_received_ts = 247.969894 last_seq = 5549 current_ts = 247.973770 current_received_ts = 247.974060 current_seq = 5550 count = 409 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 89us (kms_flip:2765) DEBUG: name = flip last_ts = 247.973770 last_received_ts = 247.974060 last_seq = 5550 current_ts = 247.977936 current_received_ts = 247.978180 current_seq = 5551 count = 410 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 247.977936 last_received_ts = 247.978180 last_seq = 5551 current_ts = 247.982101 current_received_ts = 247.982346 current_seq = 5552 count = 411 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.982101 last_received_ts = 247.982346 last_seq = 5552 current_ts = 247.986267 current_received_ts = 247.986526 current_seq = 5553 count = 412 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 92us (kms_flip:2765) DEBUG: name = flip last_ts = 247.986267 last_received_ts = 247.986526 last_seq = 5553 current_ts = 247.990433 current_received_ts = 247.990707 current_seq = 5554 count = 413 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 247.990433 last_received_ts = 247.990707 last_seq = 5554 current_ts = 247.994598 current_received_ts = 247.994873 current_seq = 5555 count = 414 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 60us (kms_flip:2765) DEBUG: name = flip last_ts = 247.994598 last_received_ts = 247.994873 last_seq = 5555 current_ts = 247.998764 current_received_ts = 247.999069 current_seq = 5556 count = 415 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 247.998764 last_received_ts = 247.999069 last_seq = 5556 current_ts = 248.002930 current_received_ts = 248.003189 current_seq = 5557 count = 416 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 80us (kms_flip:2765) DEBUG: name = flip last_ts = 248.002930 last_received_ts = 248.003189 last_seq = 5557 current_ts = 248.007095 current_received_ts = 248.007339 current_seq = 5558 count = 417 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 248.007095 last_received_ts = 248.007339 last_seq = 5558 current_ts = 248.011261 current_received_ts = 248.011505 current_seq = 5559 count = 418 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 55us (kms_flip:2765) DEBUG: name = flip last_ts = 248.011261 last_received_ts = 248.011505 last_seq = 5559 current_ts = 248.015427 current_received_ts = 248.015701 current_seq = 5560 count = 419 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 86us (kms_flip:2765) DEBUG: name = flip last_ts = 248.015427 last_received_ts = 248.015701 last_seq = 5560 current_ts = 248.019592 current_received_ts = 248.019867 current_seq = 5561 count = 420 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 87us (kms_flip:2765) DEBUG: name = flip last_ts = 248.019592 last_received_ts = 248.019867 last_seq = 5561 current_ts = 248.023758 current_received_ts = 248.024063 current_seq = 5562 count = 421 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 90us (kms_flip:2765) DEBUG: name = flip last_ts = 248.023758 last_received_ts = 248.024063 last_seq = 5562 current_ts = 248.027924 current_received_ts = 248.028183 current_seq = 5563 count = 422 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 80us (kms_flip:2765) DEBUG: name = flip last_ts = 248.027924 last_received_ts = 248.028183 last_seq = 5563 current_ts = 248.032089 current_received_ts = 248.032364 current_seq = 5564 count = 423 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 92us (kms_flip:2765) DEBUG: name = flip last_ts = 248.032089 last_received_ts = 248.032364 last_seq = 5564 current_ts = 248.036255 current_received_ts = 248.036530 current_seq = 5565 count = 424 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 100us (kms_flip:2765) DEBUG: name = flip last_ts = 248.036255 last_received_ts = 248.036530 last_seq = 5565 current_ts = 248.040421 current_received_ts = 248.040680 current_seq = 5566 count = 425 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 248.040421 last_received_ts = 248.040680 last_seq = 5566 current_ts = 248.044586 current_received_ts = 248.044891 current_seq = 5567 count = 426 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 118us (kms_flip:2765) DEBUG: name = flip last_ts = 248.044586 last_received_ts = 248.044891 last_seq = 5567 current_ts = 248.048752 current_received_ts = 248.049042 current_seq = 5568 count = 427 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 90us (kms_flip:2765) DEBUG: name = flip last_ts = 248.048752 last_received_ts = 248.049042 last_seq = 5568 current_ts = 248.052917 current_received_ts = 248.053177 current_seq = 5569 count = 428 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 93us (kms_flip:2765) DEBUG: name = flip last_ts = 248.052917 last_received_ts = 248.053177 last_seq = 5569 current_ts = 248.057083 current_received_ts = 248.057312 current_seq = 5570 count = 429 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 248.057083 last_received_ts = 248.057312 last_seq = 5570 current_ts = 248.061249 current_received_ts = 248.061478 current_seq = 5571 count = 430 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 84us (kms_flip:2765) DEBUG: name = flip last_ts = 248.061249 last_received_ts = 248.061478 last_seq = 5571 current_ts = 248.065414 current_received_ts = 248.065689 current_seq = 5572 count = 431 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 55us (kms_flip:2765) DEBUG: name = flip last_ts = 248.065414 last_received_ts = 248.065689 last_seq = 5572 current_ts = 248.069580 current_received_ts = 248.069855 current_seq = 5573 count = 432 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 248.069580 last_received_ts = 248.069855 last_seq = 5573 current_ts = 248.073746 current_received_ts = 248.074051 current_seq = 5574 count = 433 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 80us (kms_flip:2765) DEBUG: name = flip last_ts = 248.073746 last_received_ts = 248.074051 last_seq = 5574 current_ts = 248.077911 current_received_ts = 248.078171 current_seq = 5575 count = 434 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 248.077911 last_received_ts = 248.078171 last_seq = 5575 current_ts = 248.082077 current_received_ts = 248.082321 current_seq = 5576 count = 435 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 248.082077 last_received_ts = 248.082321 last_seq = 5576 current_ts = 248.086243 current_received_ts = 248.086472 current_seq = 5577 count = 436 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 248.086243 last_received_ts = 248.086472 last_seq = 5577 current_ts = 248.090408 current_received_ts = 248.090683 current_seq = 5578 count = 437 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 248.090408 last_received_ts = 248.090683 last_seq = 5578 current_ts = 248.094559 current_received_ts = 248.094864 current_seq = 5579 count = 438 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 248.094559 last_received_ts = 248.094864 last_seq = 5579 current_ts = 248.098740 current_received_ts = 248.099060 current_seq = 5580 count = 439 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 79us (kms_flip:2765) DEBUG: name = flip last_ts = 248.098740 last_received_ts = 248.099060 last_seq = 5580 current_ts = 248.102890 current_received_ts = 248.103165 current_seq = 5581 count = 440 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 248.102890 last_received_ts = 248.103165 last_seq = 5581 current_ts = 248.107056 current_received_ts = 248.107315 current_seq = 5582 count = 441 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 91us (kms_flip:2765) DEBUG: name = flip last_ts = 248.107056 last_received_ts = 248.107315 last_seq = 5582 current_ts = 248.111221 current_received_ts = 248.111450 current_seq = 5583 count = 442 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 84us (kms_flip:2765) DEBUG: name = flip last_ts = 248.111221 last_received_ts = 248.111450 last_seq = 5583 current_ts = 248.115387 current_received_ts = 248.115692 current_seq = 5584 count = 443 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 248.115387 last_received_ts = 248.115692 last_seq = 5584 current_ts = 248.119553 current_received_ts = 248.119843 current_seq = 5585 count = 444 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 92us (kms_flip:2765) DEBUG: name = flip last_ts = 248.119553 last_received_ts = 248.119843 last_seq = 5585 current_ts = 248.123718 current_received_ts = 248.124023 current_seq = 5586 count = 445 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 95us (kms_flip:2765) DEBUG: name = flip last_ts = 248.123718 last_received_ts = 248.124023 last_seq = 5586 current_ts = 248.127884 current_received_ts = 248.128204 current_seq = 5587 count = 446 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 248.127884 last_received_ts = 248.128204 last_seq = 5587 current_ts = 248.132050 current_received_ts = 248.132278 current_seq = 5588 count = 447 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 60us (kms_flip:2765) DEBUG: name = flip last_ts = 248.132050 last_received_ts = 248.132278 last_seq = 5588 current_ts = 248.136215 current_received_ts = 248.136444 current_seq = 5589 count = 448 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 248.136215 last_received_ts = 248.136444 last_seq = 5589 current_ts = 248.140381 current_received_ts = 248.140656 current_seq = 5590 count = 449 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 81us (kms_flip:2765) DEBUG: name = flip last_ts = 248.140381 last_received_ts = 248.140656 last_seq = 5590 current_ts = 248.144547 current_received_ts = 248.144836 current_seq = 5591 count = 450 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 93us (kms_flip:2765) DEBUG: name = flip last_ts = 248.144547 last_received_ts = 248.144836 last_seq = 5591 current_ts = 248.148712 current_received_ts = 248.149078 current_seq = 5592 count = 451 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 90us (kms_flip:2765) DEBUG: name = flip last_ts = 248.148712 last_received_ts = 248.149078 last_seq = 5592 current_ts = 248.152878 current_received_ts = 248.153198 current_seq = 5593 count = 452 seq_step = 1 (kms_flip:2765) DEBUG: Vblank took 710us (kms_flip:2765) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2765) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2765) igt_core-INFO: Stack trace: (kms_flip:2765) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2765) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:2765) igt_core-INFO: #2 ../tests/kms_flip.c:1884 run_test() (kms_flip:2765) igt_core-INFO: #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040() (kms_flip:2765) igt_core-INFO: #4 ../tests/kms_flip.c:2040 main() (kms_flip:2765) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2765) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2765) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest C-eDP1: FAIL (3.245s)
Dmesg	<6> [244.929230] [IGT] kms_flip: starting dynamic subtest C-eDP1 <7> [244.931066] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:206] <7> [244.932263] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:241] <7> [244.941137] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [244.941559] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [244.941886] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [245.012950] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:88:pipe A] <7> [245.013346] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [245.013693] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [245.014316] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B] <7> [245.014532] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [245.014757] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [245.014938] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1) <7> [245.015140] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in lane_count (expected 4, found 0) <7> [245.015350] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in dp_m_n (expected tu 64 data 8318780/8388608 link 693231/524288, found tu 0, data 0/0 link 0/0) <7> [245.015546] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [245.015736] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [245.015914] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2560, found 0) <7> [245.016108] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2720, found 0) <7> [245.016296] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2560, found 0) <7> [245.016458] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2720, found 0) <7> [245.016606] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2608, found 0) <7> [245.016750] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2640, found 0) <7> [245.016895] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1600, found 0) <7> [245.017048] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1600, found 0) <7> [245.017215] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1610, found 0) <7> [245.017381] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1615, found 0) <7> [245.017532] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1640, found 0) <7> [245.017680] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1640, found 0) <7> [245.017823] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2560, found 0) <7> [245.017974] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2720, found 0) <7> [245.018139] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2560, found 0) <7> [245.018301] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2720, found 0) <7> [245.018442] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2608, found 0) <7> [245.018562] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2640, found 0) <7> [245.018680] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1600, found 0) <7> [245.018798] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1600, found 0) <7> [245.018912] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1610, found 0) <7> [245.019026] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1615, found 0) <7> [245.019198] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1640, found 0) <7> [245.019316] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1640, found 0) <7> [245.019425] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [245.019531] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [245.019636] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [245.019738] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [245.019841] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [245.019943] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 1071009, found 0) <7> [245.020044] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 1071009, found 0) <7> [245.020153] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in port_clock (expected 810000, found 0) <7> [245.020255] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in min_voltage_level (expected 1, found 0) <7> [245.020359] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:145:pipe B] fastset requirement not met, forcing full modeset <7> [245.020511] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [245.020618] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:145:pipe B] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x2 -> 0x0 <7> [245.020737] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:140:cursor B] ddb (3955 - 4096) -> ( 0 - 0), size 141 -> 0 <7> [245.020849] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via crawling and squashing <7> [245.020968] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [245.021100] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 0, actual 0 <7> [245.021244] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:145:pipe B] enable: no [modeset] <7> [245.021352] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:90:plane 1B] fb: [NOFB], visible: no <7> [245.021456] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:100:plane 2B] fb: [NOFB], visible: no <7> [245.021559] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:110:plane 3B] fb: [NOFB], visible: no <7> [245.021661] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:120:plane 4B] fb: [NOFB], visible: no <7> [245.021766] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:130:plane 5B] fb: [NOFB], visible: no <7> [245.021874] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:140:cursor B] fb: [NOFB], visible: no <7> [245.022172] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [245.022290] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [245.230146] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 0 <7> [245.230921] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe B <7> [245.232386] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power off <7> [245.232825] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power off time <7> [245.233319] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [245.294030] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [245.294552] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [245.295133] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A] <7> [245.295507] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1] <7> [245.295852] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A] <7> [245.296220] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B] <7> [245.296558] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C] <7> [245.296887] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2] <7> [245.297247] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A] <7> [245.297578] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B] <7> [245.297905] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C] <7> [245.298271] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3] <7> [245.298604] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A] <7> [245.298935] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B] <7> [245.299296] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C] <7> [245.299631] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1] <7> [245.300033] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [245.300401] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [245.300719] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [245.301288] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_B <7> [245.301765] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_2 <7> [245.302304] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:145:pipe B] <7> [245.302718] 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> [245.303248] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [245.303657] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [245.304293] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C] <7> [245.304809] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C] <7> [245.304930] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:205:eDP-1] <7> [245.305291] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:205:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [245.305836] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:204:DDI A/PHY A][CRTC:202:pipe C] DP link limits: pixel clock 1071010 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 max link_bpp 30.0000 <7> [245.306312] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 810000 bpp input 24 compressed 0.0000 link rate required 3213030 available 3240000 <7> [245.306758] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:202:pipe C] hw max bpp: 30, pipe bpp: 24, dithering: 0 <7> [245.307248] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:204:DDI A/PHY A] [CRTC:202:pipe C] <7> [245.307670] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [245.308061] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [245.308473] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [245.308834] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [245.309207] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 8318780/8388608 link 693231/524288) <7> [245.309538] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [245.309853] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [245.310184] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2560) <7> [245.310470] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2720) <7> [245.310732] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2560) <7> [245.311001] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2720) <7> [245.311279] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2608) <7> [245.311538] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2640) <7> [245.311779] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1600) <7> [245.312017] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1600) <7> [245.312268] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1610) <7> [245.312502] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1615) <7> [245.312715] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1640) <7> [245.312926] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1640) <7> [245.313139] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2560) <7> [245.313336] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2720) <7> [245.313516] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2560) <7> [245.313702] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2720) <7> [245.313880] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2608) <7> [245.314055] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2640) <7> [245.314266] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1600) <7> [245.314447] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1600) <7> [245.314604] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1610) <7> [245.314764] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1615) <7> [245.314912] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1640) <7> [245.315051] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1640) <7> [245.315216] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [245.315366] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [245.315512] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [245.315654] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [245.315799] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in dpll_hw_state.cx0pll C20 <7> [245.315934] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] expected: <7> [245.316097] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c20pll_hw_state: <7> [245.316248] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000 <7> [245.316386] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [245.316519] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[0] = 0x108c <7> [245.316643] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[1] = 0x2108 <7> [245.316766] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[2] = 0xcc9c <7> [245.316874] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[3] = 0xbfc1 <7> [245.316980] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[4] = 0x4b9a <7> [245.317108] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[5] = 0x3f81 <7> [245.317238] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[6] = 0x2000 <7> [245.317346] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[7] = 0x0001 <7> [245.317451] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[8] = 0x5000 <7> [245.317554] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[9] = 0x0000 <7> [245.317663] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[10] = 0x0000 <7> [245.317772] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] found: <7> [245.317873] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_hw_state: fracen: yes, <7> [245.317979] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] quot: 61440, rem: 0, den: 1, <7> [245.318093] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] multiplier: 210, tx_clk_div: 0. <7> [245.318201] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_rawhw_state: <7> [245.318300] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx: 0x10, cmn: 0x21 <7> [245.318399] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[0] = 0x34, pll[1] = 0x0, pll[2] = 0x84, pll[3] = 0x1 <7> [245.318498] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [245.318599] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [245.318700] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[12] = 0xf0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x0 <7> [245.318802] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[16] = 0x84, pll[17] = 0xf, pll[18] = 0xe5, pll[19] = 0x23 <7> [245.318910] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [245.319016] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 1071009) <7> [245.319136] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 1071009) <7> [245.319241] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in port_clock (expected 0, found 810000) <7> [245.319341] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in min_voltage_level (expected 0, found 1) <7> [245.319440] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:202:pipe C] fastset requirement not met, forcing full modeset <7> [245.319596] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no <7> [245.319708] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:202:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4 <7> [245.319700] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [245.319799] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - long <7> [245.319825] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:147:plane 1C] ddb ( 0 - 0) -> ( 0 - 1907), size 0 -> 1907 <7> [245.319878] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [245.319903] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:197:cursor C] ddb ( 0 - 0) -> (1907 - 2048), size 0 -> 141 <7> [245.319961] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:204:DDI A/PHY A] <7> [245.319978] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7,twm,swm,*stwm <7> [245.320052] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 42, 42, 42, 42, 42, 0, 0, 0, 8, 0 <7> [245.320141] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 82, 852, 852, 852, 852, 852, 0, 0, 177, 163, 177 <7> [245.320218] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 163, 973, 973, 973, 973, 973, 0, 0, 178, 244, 244 <7> [245.320317] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:202:pipe C] data rate 4284036 num active planes 1 <7> [245.320430] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 4499 qgv_peak_bw: 38400 <7> [245.320544] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 4499 qgv_peak_bw: 38400 <7> [245.320657] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 4499 qgv_peak_bw: 38400 <7> [245.320767] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 4499 qgv_peak_bw: 38400 <7> [245.320872] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 4499 <7> [245.320996] xe 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [xe]] [PLANE:147:plane 1C] min cdclk (535505 kHz) > [CRTC:202:pipe C] min cdclk (0 kHz) <7> [245.321092] xe 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [xe]] new bandwidth min cdclk (83673 kHz) > old min cdclk (0 kHz) <7> [245.321207] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via crawling and squashing <7> [245.321317] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 556800 kHz, actual 556800 kHz <7> [245.321428] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 2, actual 2 <7> [245.321580] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:202:pipe C] enable: yes [modeset] <7> [245.321701] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [245.321811] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: C, pipe bpp: 24, dithering: 0 <7> [245.321918] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [245.322024] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [245.322088] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [245.322140] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [245.322243] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [245.322249] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [245.322355] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 8318780, data_n: 8388608, link_m: 693231, link_n: 524288, tu: 64 <7> [245.322362] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [245.322460] 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> [245.322499] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [245.322565] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled <7> [245.322670] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [245.322778] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: disabled, panel replay: disabled, selective fetch: disabled <7> [245.322892] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [245.323000] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [245.323116] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 2, length 8 <7> [245.323228] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [245.323333] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [245.323436] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [245.323539] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [245.323644] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [245.323751] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [245.323861] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0 <7> [245.323975] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1640, vmax: 1640, flipline: 1640, pipeline full: 0, guardband: 40 vsync start: 30, vsync end: 25 <7> [245.324107] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1600, vmax vblank: 1600, vmin vtotal: 1640, vmax vtotal: 1640 <7> [245.324228] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2560x1600": 240 1071010 2560 2608 2640 2720 1600 1610 1615 1640 0x48 0xa <7> [245.324345] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2560x1600": 240 1071010 2560 2608 2640 2720 1600 1610 1615 1640 0x48 0xa <7> [245.324462] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=1071009, hd=2560 hb=2560-2720 hs=2608-2640 ht=2720, vd=1600 vb=1600-1640 vs=1610-1615 vt=1640, flags=0xa <7> [245.324581] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2560x1600": 240 1071009 2560 2608 2640 2720 1600 1610 1615 1640 0x40 0xa <7> [245.324699] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=1071009, hd=2560 hb=2560-2720 hs=2608-2640 ht=2720, vd=1600 vb=1600-1640 vs=1610-1615 vt=1640, flags=0xa <7> [245.324820] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 810000, pipe src: 2560x1600+0+0, pixel rate 1071009 <7> [245.324942] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 21, ips linetime: 0 <7> [245.325081] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [245.325214] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [245.325341] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [245.325470] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0xc5c10, dpll_md: 0x342110, fp0: 0x184, fp1: 0x1000000 <7> [245.325596] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [245.325722] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [245.325846] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [245.325965] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [245.326097] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [245.326222] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [245.326342] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [245.326467] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [245.326594] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [245.326720] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [245.326846] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [245.326973] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [245.327108] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:147:plane 1C] fb: [FB:206] 2560x1600 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [245.327236] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [245.327353] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2560.000000x1600.000000+0.000000+0.000000 dst: 2560x1600+0+0 <7> [245.327469] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:157:plane 2C] fb: [NOFB], visible: no <7> [245.327587] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:167:plane 3C] fb: [NOFB], visible: no <7> [245.327704] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:177:plane 4C] fb: [NOFB], visible: no <7> [245.327827] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:187:plane 5C] fb: [NOFB], visible: no <7> [245.327947] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:197:cursor C] fb: [NOFB], visible: no <7> [245.328470] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [245.328584] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [245.328850] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [245.329016] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [245.329208] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_C <7> [245.329497] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 556800 kHz, VCO 1113600 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 2 <7> [245.329672] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [245.329792] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=1392 <7> [245.329908] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A] <7> [245.330008] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1] <7> [245.330121] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A] <7> [245.330217] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B] <7> [245.330310] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C] <7> [245.330402] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2] <7> [245.330494] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A] <7> [245.330586] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B] <7> [245.330675] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C] <7> [245.330763] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3] <7> [245.330850] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A] <7> [245.330934] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B] <7> [245.331019] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C] <7> [245.331170] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xd <7> [245.331359] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [245.331489] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [245.332836] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power on <7> [245.332927] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power cycle (462 ms remaining) <7> [245.798394] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [245.875764] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [245.876456] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power on <7> [245.876974] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [246.014320] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [246.014748] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - long <7> [246.015127] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [246.015613] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:204:DDI A/PHY A] <7> [246.084917] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [246.087170] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD on <7> [246.087594] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [246.091538] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e c4 01 00 00 01 c0 02 00 00 00 00 09 80 <7> [246.092937] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [246.094417] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 00 <7> [246.096439] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [246.097789] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [246.099442] xe 0000:00:02.0: [drm:intel_dp_get_adjust_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing request: 1/1/1/1, pre-emphasis request: 0/0/0/0 <7> [246.099928] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 1/1/1/1, pre-emphasis levels: 0/0/0/0 <7> [246.102896] xe 0000:00:02.0: [drm:intel_dp_get_adjust_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing request: 2/2/2/2, pre-emphasis request: 0/0/0/0 <7> [246.103410] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 2/2/2/2, pre-emphasis levels: 0/0/0/0 <7> [246.106303] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Clock recovery OK <7> [246.106769] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8.1 Gbps link rate without sink TPS4 support <7> [246.107283] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS3 <7> [246.109423] xe 0000:00:02.0: [drm:intel_dp_get_adjust_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing request: 2/2/2/2, pre-emphasis request: 0/0/0/0 <7> [246.109693] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 2/2/2/2, pre-emphasis levels: 0/0/0/0 <7> [246.112766] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [246.113090] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Link Training passed at link rate = 810000, lane count = 4 <7> [246.114004] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe C <7> [246.114493] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [246.114732] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe C <7> [246.114949] xe 0000:00:02.0: [drm:intel_dp_wait_source_oui [xe]] [CONNECTOR:205:eDP-1] Performing OUI wait (0 ms) <7> [246.115572] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 13818 <7> [246.117071] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] reserved 13107200 bytes of contiguous stolen space for FBC, limit: 2 <7> [246.117462] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] Enabling FBC on [PLANE:147:plane 1C] <7> [246.118855] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR1 <7> [246.120809] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1] <7> [246.121292] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:202:pipe C] <6> [248.175336] [IGT] kms_flip: finished subtest C-eDP1, FAIL

Detail

Value

Duration

3.25 seconds

Igt-Version

IGT-Version: 2.1-g162a06a82 (x86_64) (Linux: 6.17.0-rc7-lgci-xe-xe-3827-690ed0728a0e31e6b+ x86_64)

Out

Starting dynamic subtest: C-eDP1
  2560x1600: 240 1071010 2560 2608 2640 2720 1600 1610 1615 1640 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1884 run_test()
  #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-eDP1: FAIL (3.245s)

Err

Starting dynamic subtest: C-eDP1
(kms_flip:2765) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2765) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.644730
last_received_ts = 247.644989
last_seq = 5471
current_ts = 247.648895
current_received_ts = 247.649170
current_seq = 5472
count = 331
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 80us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.648895
last_received_ts = 247.649170
last_seq = 5472
current_ts = 247.653061
current_received_ts = 247.653290
current_seq = 5473
count = 332
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 80us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.653061
last_received_ts = 247.653290
last_seq = 5473
current_ts = 247.657227
current_received_ts = 247.657455
current_seq = 5474
count = 333
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 82us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.657227
last_received_ts = 247.657455
last_seq = 5474
current_ts = 247.661392
current_received_ts = 247.661667
current_seq = 5475
count = 334
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 93us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.661392
last_received_ts = 247.661667
last_seq = 5475
current_ts = 247.665558
current_received_ts = 247.665833
current_seq = 5476
count = 335
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.665558
last_received_ts = 247.665833
last_seq = 5476
current_ts = 247.669724
current_received_ts = 247.670029
current_seq = 5477
count = 336
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 55us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.669724
last_received_ts = 247.670029
last_seq = 5477
current_ts = 247.673889
current_received_ts = 247.674164
current_seq = 5478
count = 337
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.673889
last_received_ts = 247.674164
last_seq = 5478
current_ts = 247.678040
current_received_ts = 247.678314
current_seq = 5479
count = 338
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.678040
last_received_ts = 247.678314
last_seq = 5479
current_ts = 247.682205
current_received_ts = 247.682358
current_seq = 5480
count = 339
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 92us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.682205
last_received_ts = 247.682358
last_seq = 5480
current_ts = 247.686371
current_received_ts = 247.686646
current_seq = 5481
count = 340
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 101us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.686371
last_received_ts = 247.686646
last_seq = 5481
current_ts = 247.690536
current_received_ts = 247.690842
current_seq = 5482
count = 341
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 100us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.690536
last_received_ts = 247.690842
last_seq = 5482
current_ts = 247.694702
current_received_ts = 247.695023
current_seq = 5483
count = 342
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 100us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.694702
last_received_ts = 247.695023
last_seq = 5483
current_ts = 247.698868
current_received_ts = 247.699188
current_seq = 5484
count = 343
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 87us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.698868
last_received_ts = 247.699188
last_seq = 5484
current_ts = 247.703033
current_received_ts = 247.703293
current_seq = 5485
count = 344
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 101us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.703033
last_received_ts = 247.703293
last_seq = 5485
current_ts = 247.707199
current_received_ts = 247.707520
current_seq = 5486
count = 345
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 99us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.707199
last_received_ts = 247.707520
last_seq = 5486
current_ts = 247.711365
current_received_ts = 247.711655
current_seq = 5487
count = 346
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.711365
last_received_ts = 247.711655
last_seq = 5487
current_ts = 247.715530
current_received_ts = 247.715820
current_seq = 5488
count = 347
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 84us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.715530
last_received_ts = 247.715820
last_seq = 5488
current_ts = 247.719696
current_received_ts = 247.719986
current_seq = 5489
count = 348
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 82us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.719696
last_received_ts = 247.719986
last_seq = 5489
current_ts = 247.723862
current_received_ts = 247.724152
current_seq = 5490
count = 349
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.723862
last_received_ts = 247.724152
last_seq = 5490
current_ts = 247.728027
current_received_ts = 247.728302
current_seq = 5491
count = 350
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 56us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.728027
last_received_ts = 247.728302
last_seq = 5491
current_ts = 247.732193
current_received_ts = 247.732437
current_seq = 5492
count = 351
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.732193
last_received_ts = 247.732437
last_seq = 5492
current_ts = 247.736359
current_received_ts = 247.736633
current_seq = 5493
count = 352
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 92us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.736359
last_received_ts = 247.736633
last_seq = 5493
current_ts = 247.740524
current_received_ts = 247.740814
current_seq = 5494
count = 353
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.740524
last_received_ts = 247.740814
last_seq = 5494
current_ts = 247.744690
current_received_ts = 247.744965
current_seq = 5495
count = 354
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 119us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.744690
last_received_ts = 247.744965
last_seq = 5495
current_ts = 247.748856
current_received_ts = 247.749176
current_seq = 5496
count = 355
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 82us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.748856
last_received_ts = 247.749176
last_seq = 5496
current_ts = 247.753021
current_received_ts = 247.753220
current_seq = 5497
count = 356
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.753021
last_received_ts = 247.753220
last_seq = 5497
current_ts = 247.757187
current_received_ts = 247.757446
current_seq = 5498
count = 357
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.757187
last_received_ts = 247.757446
last_seq = 5498
current_ts = 247.761353
current_received_ts = 247.761627
current_seq = 5499
count = 358
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.761353
last_received_ts = 247.761627
last_seq = 5499
current_ts = 247.765518
current_received_ts = 247.765793
current_seq = 5500
count = 359
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 87us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.765518
last_received_ts = 247.765793
last_seq = 5500
current_ts = 247.769684
current_received_ts = 247.769958
current_seq = 5501
count = 360
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 101us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.769684
last_received_ts = 247.769958
last_seq = 5501
current_ts = 247.773849
current_received_ts = 247.774124
current_seq = 5502
count = 361
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.773849
last_received_ts = 247.774124
last_seq = 5502
current_ts = 247.778015
current_received_ts = 247.778214
current_seq = 5503
count = 362
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 80us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.778015
last_received_ts = 247.778214
last_seq = 5503
current_ts = 247.782181
current_received_ts = 247.782425
current_seq = 5504
count = 363
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 80us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.782181
last_received_ts = 247.782425
last_seq = 5504
current_ts = 247.786346
current_received_ts = 247.786621
current_seq = 5505
count = 364
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.786346
last_received_ts = 247.786621
last_seq = 5505
current_ts = 247.790512
current_received_ts = 247.790787
current_seq = 5506
count = 365
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.790512
last_received_ts = 247.790787
last_seq = 5506
current_ts = 247.794678
current_received_ts = 247.794937
current_seq = 5507
count = 366
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 103us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.794678
last_received_ts = 247.794937
last_seq = 5507
current_ts = 247.798843
current_received_ts = 247.799149
current_seq = 5508
count = 367
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 85us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.798843
last_received_ts = 247.799149
last_seq = 5508
current_ts = 247.803009
current_received_ts = 247.803192
current_seq = 5509
count = 368
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 55us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.803009
last_received_ts = 247.803192
last_seq = 5509
current_ts = 247.807175
current_received_ts = 247.807388
current_seq = 5510
count = 369
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.807175
last_received_ts = 247.807388
last_seq = 5510
current_ts = 247.811340
current_received_ts = 247.811600
current_seq = 5511
count = 370
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 88us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.811340
last_received_ts = 247.811600
last_seq = 5511
current_ts = 247.815506
current_received_ts = 247.815796
current_seq = 5512
count = 371
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.815506
last_received_ts = 247.815796
last_seq = 5512
current_ts = 247.819656
current_received_ts = 247.819962
current_seq = 5513
count = 372
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 89us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.819656
last_received_ts = 247.819962
last_seq = 5513
current_ts = 247.823822
current_received_ts = 247.824142
current_seq = 5514
count = 373
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 87us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.823822
last_received_ts = 247.824142
last_seq = 5514
current_ts = 247.827988
current_received_ts = 247.828201
current_seq = 5515
count = 374
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 100us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.827988
last_received_ts = 247.828201
last_seq = 5515
current_ts = 247.832153
current_received_ts = 247.832397
current_seq = 5516
count = 375
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 100us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.832153
last_received_ts = 247.832397
last_seq = 5516
current_ts = 247.836319
current_received_ts = 247.836624
current_seq = 5517
count = 376
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 87us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.836319
last_received_ts = 247.836624
last_seq = 5517
current_ts = 247.840485
current_received_ts = 247.840790
current_seq = 5518
count = 377
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 100us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.840485
last_received_ts = 247.840790
last_seq = 5518
current_ts = 247.844650
current_received_ts = 247.844955
current_seq = 5519
count = 378
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 106us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.844650
last_received_ts = 247.844955
last_seq = 5519
current_ts = 247.848816
current_received_ts = 247.849152
current_seq = 5520
count = 379
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 87us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.848816
last_received_ts = 247.849152
last_seq = 5520
current_ts = 247.852982
current_received_ts = 247.853195
current_seq = 5521
count = 380
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 100us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.852982
last_received_ts = 247.853195
last_seq = 5521
current_ts = 247.857147
current_received_ts = 247.857391
current_seq = 5522
count = 381
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 93us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.857147
last_received_ts = 247.857391
last_seq = 5522
current_ts = 247.861313
current_received_ts = 247.861618
current_seq = 5523
count = 382
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 100us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.861313
last_received_ts = 247.861618
last_seq = 5523
current_ts = 247.865479
current_received_ts = 247.865768
current_seq = 5524
count = 383
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.865479
last_received_ts = 247.865768
last_seq = 5524
current_ts = 247.869644
current_received_ts = 247.869934
current_seq = 5525
count = 384
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 105us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.869644
last_received_ts = 247.869934
last_seq = 5525
current_ts = 247.873810
current_received_ts = 247.874115
current_seq = 5526
count = 385
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 87us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.873810
last_received_ts = 247.874115
last_seq = 5526
current_ts = 247.877975
current_received_ts = 247.878174
current_seq = 5527
count = 386
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 80us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.877975
last_received_ts = 247.878174
last_seq = 5527
current_ts = 247.882141
current_received_ts = 247.882355
current_seq = 5528
count = 387
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.882141
last_received_ts = 247.882355
last_seq = 5528
current_ts = 247.886307
current_received_ts = 247.886581
current_seq = 5529
count = 388
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 56us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.886307
last_received_ts = 247.886581
last_seq = 5529
current_ts = 247.890472
current_received_ts = 247.890762
current_seq = 5530
count = 389
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 92us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.890472
last_received_ts = 247.890762
last_seq = 5530
current_ts = 247.894638
current_received_ts = 247.894913
current_seq = 5531
count = 390
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 102us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.894638
last_received_ts = 247.894913
last_seq = 5531
current_ts = 247.898804
current_received_ts = 247.899109
current_seq = 5532
count = 391
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 80us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.898804
last_received_ts = 247.899109
last_seq = 5532
current_ts = 247.902969
current_received_ts = 247.903168
current_seq = 5533
count = 392
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.902969
last_received_ts = 247.903168
last_seq = 5533
current_ts = 247.907135
current_received_ts = 247.907349
current_seq = 5534
count = 393
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 88us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.907135
last_received_ts = 247.907349
last_seq = 5534
current_ts = 247.911301
current_received_ts = 247.911575
current_seq = 5535
count = 394
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.911301
last_received_ts = 247.911575
last_seq = 5535
current_ts = 247.915466
current_received_ts = 247.915741
current_seq = 5536
count = 395
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.915466
last_received_ts = 247.915741
last_seq = 5536
current_ts = 247.919632
current_received_ts = 247.919907
current_seq = 5537
count = 396
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 105us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.919632
last_received_ts = 247.919907
last_seq = 5537
current_ts = 247.923798
current_received_ts = 247.924088
current_seq = 5538
count = 397
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.923798
last_received_ts = 247.924088
last_seq = 5538
current_ts = 247.927963
current_received_ts = 247.928162
current_seq = 5539
count = 398
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 80us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.927963
last_received_ts = 247.928162
last_seq = 5539
current_ts = 247.932129
current_received_ts = 247.932343
current_seq = 5540
count = 399
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 92us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.932129
last_received_ts = 247.932343
last_seq = 5540
current_ts = 247.936295
current_received_ts = 247.936569
current_seq = 5541
count = 400
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 92us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.936295
last_received_ts = 247.936569
last_seq = 5541
current_ts = 247.940460
current_received_ts = 247.940720
current_seq = 5542
count = 401
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 59us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.940460
last_received_ts = 247.940720
last_seq = 5542
current_ts = 247.944626
current_received_ts = 247.944885
current_seq = 5543
count = 402
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 82us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.944626
last_received_ts = 247.944885
last_seq = 5543
current_ts = 247.948792
current_received_ts = 247.949066
current_seq = 5544
count = 403
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.948792
last_received_ts = 247.949066
last_seq = 5544
current_ts = 247.952957
current_received_ts = 247.953171
current_seq = 5545
count = 404
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.952957
last_received_ts = 247.953171
last_seq = 5545
current_ts = 247.957123
current_received_ts = 247.957352
current_seq = 5546
count = 405
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 80us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.957123
last_received_ts = 247.957352
last_seq = 5546
current_ts = 247.961273
current_received_ts = 247.961533
current_seq = 5547
count = 406
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.961273
last_received_ts = 247.961533
last_seq = 5547
current_ts = 247.965439
current_received_ts = 247.965714
current_seq = 5548
count = 407
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.965439
last_received_ts = 247.965714
last_seq = 5548
current_ts = 247.969604
current_received_ts = 247.969894
current_seq = 5549
count = 408
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 117us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.969604
last_received_ts = 247.969894
last_seq = 5549
current_ts = 247.973770
current_received_ts = 247.974060
current_seq = 5550
count = 409
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 89us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.973770
last_received_ts = 247.974060
last_seq = 5550
current_ts = 247.977936
current_received_ts = 247.978180
current_seq = 5551
count = 410
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.977936
last_received_ts = 247.978180
last_seq = 5551
current_ts = 247.982101
current_received_ts = 247.982346
current_seq = 5552
count = 411
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.982101
last_received_ts = 247.982346
last_seq = 5552
current_ts = 247.986267
current_received_ts = 247.986526
current_seq = 5553
count = 412
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 92us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.986267
last_received_ts = 247.986526
last_seq = 5553
current_ts = 247.990433
current_received_ts = 247.990707
current_seq = 5554
count = 413
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.990433
last_received_ts = 247.990707
last_seq = 5554
current_ts = 247.994598
current_received_ts = 247.994873
current_seq = 5555
count = 414
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 60us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.994598
last_received_ts = 247.994873
last_seq = 5555
current_ts = 247.998764
current_received_ts = 247.999069
current_seq = 5556
count = 415
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 247.998764
last_received_ts = 247.999069
last_seq = 5556
current_ts = 248.002930
current_received_ts = 248.003189
current_seq = 5557
count = 416
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 80us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.002930
last_received_ts = 248.003189
last_seq = 5557
current_ts = 248.007095
current_received_ts = 248.007339
current_seq = 5558
count = 417
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.007095
last_received_ts = 248.007339
last_seq = 5558
current_ts = 248.011261
current_received_ts = 248.011505
current_seq = 5559
count = 418
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 55us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.011261
last_received_ts = 248.011505
last_seq = 5559
current_ts = 248.015427
current_received_ts = 248.015701
current_seq = 5560
count = 419
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 86us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.015427
last_received_ts = 248.015701
last_seq = 5560
current_ts = 248.019592
current_received_ts = 248.019867
current_seq = 5561
count = 420
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 87us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.019592
last_received_ts = 248.019867
last_seq = 5561
current_ts = 248.023758
current_received_ts = 248.024063
current_seq = 5562
count = 421
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 90us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.023758
last_received_ts = 248.024063
last_seq = 5562
current_ts = 248.027924
current_received_ts = 248.028183
current_seq = 5563
count = 422
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 80us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.027924
last_received_ts = 248.028183
last_seq = 5563
current_ts = 248.032089
current_received_ts = 248.032364
current_seq = 5564
count = 423
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 92us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.032089
last_received_ts = 248.032364
last_seq = 5564
current_ts = 248.036255
current_received_ts = 248.036530
current_seq = 5565
count = 424
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 100us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.036255
last_received_ts = 248.036530
last_seq = 5565
current_ts = 248.040421
current_received_ts = 248.040680
current_seq = 5566
count = 425
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.040421
last_received_ts = 248.040680
last_seq = 5566
current_ts = 248.044586
current_received_ts = 248.044891
current_seq = 5567
count = 426
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 118us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.044586
last_received_ts = 248.044891
last_seq = 5567
current_ts = 248.048752
current_received_ts = 248.049042
current_seq = 5568
count = 427
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 90us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.048752
last_received_ts = 248.049042
last_seq = 5568
current_ts = 248.052917
current_received_ts = 248.053177
current_seq = 5569
count = 428
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 93us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.052917
last_received_ts = 248.053177
last_seq = 5569
current_ts = 248.057083
current_received_ts = 248.057312
current_seq = 5570
count = 429
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.057083
last_received_ts = 248.057312
last_seq = 5570
current_ts = 248.061249
current_received_ts = 248.061478
current_seq = 5571
count = 430
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 84us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.061249
last_received_ts = 248.061478
last_seq = 5571
current_ts = 248.065414
current_received_ts = 248.065689
current_seq = 5572
count = 431
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 55us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.065414
last_received_ts = 248.065689
last_seq = 5572
current_ts = 248.069580
current_received_ts = 248.069855
current_seq = 5573
count = 432
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.069580
last_received_ts = 248.069855
last_seq = 5573
current_ts = 248.073746
current_received_ts = 248.074051
current_seq = 5574
count = 433
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 80us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.073746
last_received_ts = 248.074051
last_seq = 5574
current_ts = 248.077911
current_received_ts = 248.078171
current_seq = 5575
count = 434
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.077911
last_received_ts = 248.078171
last_seq = 5575
current_ts = 248.082077
current_received_ts = 248.082321
current_seq = 5576
count = 435
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.082077
last_received_ts = 248.082321
last_seq = 5576
current_ts = 248.086243
current_received_ts = 248.086472
current_seq = 5577
count = 436
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.086243
last_received_ts = 248.086472
last_seq = 5577
current_ts = 248.090408
current_received_ts = 248.090683
current_seq = 5578
count = 437
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.090408
last_received_ts = 248.090683
last_seq = 5578
current_ts = 248.094559
current_received_ts = 248.094864
current_seq = 5579
count = 438
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.094559
last_received_ts = 248.094864
last_seq = 5579
current_ts = 248.098740
current_received_ts = 248.099060
current_seq = 5580
count = 439
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 79us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.098740
last_received_ts = 248.099060
last_seq = 5580
current_ts = 248.102890
current_received_ts = 248.103165
current_seq = 5581
count = 440
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.102890
last_received_ts = 248.103165
last_seq = 5581
current_ts = 248.107056
current_received_ts = 248.107315
current_seq = 5582
count = 441
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 91us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.107056
last_received_ts = 248.107315
last_seq = 5582
current_ts = 248.111221
current_received_ts = 248.111450
current_seq = 5583
count = 442
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 84us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.111221
last_received_ts = 248.111450
last_seq = 5583
current_ts = 248.115387
current_received_ts = 248.115692
current_seq = 5584
count = 443
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.115387
last_received_ts = 248.115692
last_seq = 5584
current_ts = 248.119553
current_received_ts = 248.119843
current_seq = 5585
count = 444
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 92us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.119553
last_received_ts = 248.119843
last_seq = 5585
current_ts = 248.123718
current_received_ts = 248.124023
current_seq = 5586
count = 445
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 95us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.123718
last_received_ts = 248.124023
last_seq = 5586
current_ts = 248.127884
current_received_ts = 248.128204
current_seq = 5587
count = 446
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.127884
last_received_ts = 248.128204
last_seq = 5587
current_ts = 248.132050
current_received_ts = 248.132278
current_seq = 5588
count = 447
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 60us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.132050
last_received_ts = 248.132278
last_seq = 5588
current_ts = 248.136215
current_received_ts = 248.136444
current_seq = 5589
count = 448
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.136215
last_received_ts = 248.136444
last_seq = 5589
current_ts = 248.140381
current_received_ts = 248.140656
current_seq = 5590
count = 449
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 81us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.140381
last_received_ts = 248.140656
last_seq = 5590
current_ts = 248.144547
current_received_ts = 248.144836
current_seq = 5591
count = 450
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 93us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.144547
last_received_ts = 248.144836
last_seq = 5591
current_ts = 248.148712
current_received_ts = 248.149078
current_seq = 5592
count = 451
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 90us
(kms_flip:2765) DEBUG: name = flip
last_ts = 248.148712
last_received_ts = 248.149078
last_seq = 5592
current_ts = 248.152878
current_received_ts = 248.153198
current_seq = 5593
count = 452
seq_step = 1
(kms_flip:2765) DEBUG: Vblank took 710us
(kms_flip:2765) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2765) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2765) igt_core-INFO: Stack trace:
(kms_flip:2765) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2765) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:2765) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:2765) igt_core-INFO:   #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
(kms_flip:2765) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:2765) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2765) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2765) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (3.245s)

Dmesg

<6> [244.929230] [IGT] kms_flip: starting dynamic subtest C-eDP1

<7> [244.931066] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:206]

<7> [244.932263] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:241]

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

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

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

<7> [245.012950] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:88:pipe A]

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

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

<7> [245.014316] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [245.020737] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:140:cursor B] ddb (3955 - 4096) -> ( 0 - 0), size 141 -> 0

<7> [245.020849] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via crawling and squashing

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

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

<7> [245.021244] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:145:pipe B] enable: no [modeset]

<7> [245.021352] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:90:plane 1B] fb: [NOFB], visible: no

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

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

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

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

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

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

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

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

<7> [245.230921] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe B

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [245.301288] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_B

<7> [245.301765] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_2

<7> [245.302304] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:145:pipe B]

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

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

<7> [245.304293] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C]

<7> [245.304809] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C]

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

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

<7> [245.305836] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:204:DDI A/PHY A][CRTC:202:pipe C] DP link limits: pixel clock 1071010 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 max link_bpp 30.0000

<7> [245.306312] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 810000 bpp input 24 compressed 0.0000 link rate required 3213030 available 3240000

<7> [245.306758] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:202:pipe C] hw max bpp: 30, pipe bpp: 24, dithering: 0

<7> [245.307248] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:204:DDI A/PHY A] [CRTC:202:pipe C]

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

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

<7> [245.308473] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2)

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

<7> [245.309207] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 8318780/8388608 link 693231/524288)

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

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

<7> [245.310184] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2560)

<7> [245.310470] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2720)

<7> [245.310732] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2560)

<7> [245.311001] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2720)

<7> [245.311279] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2608)

<7> [245.311538] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2640)

<7> [245.311779] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1600)

<7> [245.312017] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1600)

<7> [245.312268] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1610)

<7> [245.312502] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1615)

<7> [245.312715] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1640)

<7> [245.312926] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1640)

<7> [245.313139] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2560)

<7> [245.313336] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2720)

<7> [245.313516] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2560)

<7> [245.313702] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2720)

<7> [245.313880] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2608)

<7> [245.314055] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2640)

<7> [245.314266] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1600)

<7> [245.314447] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1600)

<7> [245.314604] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1610)

<7> [245.314764] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1615)

<7> [245.314912] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1640)

<7> [245.315051] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1640)

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

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

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

<7> [245.315654] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes)

<7> [245.315799] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in dpll_hw_state.cx0pll C20

<7> [245.315934] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] expected:

<7> [245.316097] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c20pll_hw_state:

<7> [245.316248] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000

<7> [245.316386] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [245.316519] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[0] = 0x108c

<7> [245.316643] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[1] = 0x2108

<7> [245.316766] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[2] = 0xcc9c

<7> [245.316874] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[3] = 0xbfc1

<7> [245.316980] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[4] = 0x4b9a

<7> [245.317108] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[5] = 0x3f81

<7> [245.317238] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[6] = 0x2000

<7> [245.317346] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[7] = 0x0001

<7> [245.317451] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[8] = 0x5000

<7> [245.317554] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[9] = 0x0000

<7> [245.317663] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[10] = 0x0000

<7> [245.317772] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] found:

<7> [245.317873] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_hw_state: fracen: yes,

<7> [245.317979] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] quot: 61440, rem: 0, den: 1,

<7> [245.318093] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] multiplier: 210, tx_clk_div: 0.

<7> [245.318201] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_rawhw_state:

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

<7> [245.318399] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[0] = 0x34, pll[1] = 0x0, pll[2] = 0x84, pll[3] = 0x1

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

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

<7> [245.318700] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[12] = 0xf0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x0

<7> [245.318802] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[16] = 0x84, pll[17] = 0xf, pll[18] = 0xe5, pll[19] = 0x23

<7> [245.318910] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 24)

<7> [245.319016] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 1071009)

<7> [245.319136] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 1071009)

<7> [245.319241] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in port_clock (expected 0, found 810000)

<7> [245.319341] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in min_voltage_level (expected 0, found 1)

<7> [245.319440] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:202:pipe C] fastset requirement not met, forcing full modeset

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

<7> [245.319708] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:202:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4

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

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

<7> [245.319825] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:147:plane 1C] ddb ( 0 - 0) -> ( 0 - 1907), size 0 -> 1907

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

<7> [245.319903] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:197:cursor C] ddb ( 0 - 0) -> (1907 - 2048), size 0 -> 141

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

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

<7> [245.320052] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 42, 42, 42, 42, 42, 0, 0, 0, 8, 0

<7> [245.320141] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 82, 852, 852, 852, 852, 852, 0, 0, 177, 163, 177

<7> [245.320218] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 163, 973, 973, 973, 973, 973, 0, 0, 178, 244, 244

<7> [245.320317] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:202:pipe C] data rate 4284036 num active planes 1

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

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

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

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

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

<7> [245.320996] xe 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [xe]] [PLANE:147:plane 1C] min cdclk (535505 kHz) > [CRTC:202:pipe C] min cdclk (0 kHz)

<7> [245.321092] xe 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [xe]] new bandwidth min cdclk (83673 kHz) > old min cdclk (0 kHz)

<7> [245.321207] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via crawling and squashing

<7> [245.321317] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 556800 kHz, actual 556800 kHz

<7> [245.321428] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 2, actual 2

<7> [245.321580] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:202:pipe C] enable: yes [modeset]

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

<7> [245.321811] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: C, pipe bpp: 24, dithering: 0

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

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

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

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

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

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

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

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

<7> [245.322460] 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> [245.322499] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on

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

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

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

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

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

<7> [245.323116] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 2, length 8

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

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

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

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

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

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

<7> [245.323861] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0

<7> [245.323975] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1640, vmax: 1640, flipline: 1640, pipeline full: 0, guardband: 40 vsync start: 30, vsync end: 25

<7> [245.324107] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1600, vmax vblank: 1600, vmin vtotal: 1640, vmax vtotal: 1640

<7> [245.324228] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2560x1600": 240 1071010 2560 2608 2640 2720 1600 1610 1615 1640 0x48 0xa

<7> [245.324345] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2560x1600": 240 1071010 2560 2608 2640 2720 1600 1610 1615 1640 0x48 0xa

<7> [245.324462] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=1071009, hd=2560 hb=2560-2720 hs=2608-2640 ht=2720, vd=1600 vb=1600-1640 vs=1610-1615 vt=1640, flags=0xa

<7> [245.324581] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2560x1600": 240 1071009 2560 2608 2640 2720 1600 1610 1615 1640 0x40 0xa

<7> [245.324699] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=1071009, hd=2560 hb=2560-2720 hs=2608-2640 ht=2720, vd=1600 vb=1600-1640 vs=1610-1615 vt=1640, flags=0xa

<7> [245.324820] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 810000, pipe src: 2560x1600+0+0, pixel rate 1071009

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

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

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

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

<7> [245.325470] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0xc5c10, dpll_md: 0x342110, fp0: 0x184, fp1: 0x1000000

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

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

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

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

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

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

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

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

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

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

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

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

<7> [245.327108] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:147:plane 1C] fb: [FB:206] 2560x1600 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes

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

<7> [245.327353] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2560.000000x1600.000000+0.000000+0.000000 dst: 2560x1600+0+0

<7> [245.327469] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:157:plane 2C] fb: [NOFB], visible: no

<7> [245.327587] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:167:plane 3C] fb: [NOFB], visible: no

<7> [245.327704] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:177:plane 4C] fb: [NOFB], visible: no

<7> [245.327827] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:187:plane 5C] fb: [NOFB], visible: no

<7> [245.327947] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:197:cursor C] fb: [NOFB], visible: no

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

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

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

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

<7> [245.329208] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_C

<7> [245.329497] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 556800 kHz, VCO 1113600 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 2

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [246.091538] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e c4 01 00 00 01 c0 02 00 00 00 00 09 80

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

<7> [246.094417] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 00

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

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

<7> [246.099442] xe 0000:00:02.0: [drm:intel_dp_get_adjust_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing request: 1/1/1/1, pre-emphasis request: 0/0/0/0

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

<7> [246.102896] xe 0000:00:02.0: [drm:intel_dp_get_adjust_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing request: 2/2/2/2, pre-emphasis request: 0/0/0/0

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

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

<7> [246.106769] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8.1 Gbps link rate without sink TPS4 support

<7> [246.107283] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS3

<7> [246.109423] xe 0000:00:02.0: [drm:intel_dp_get_adjust_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing request: 2/2/2/2, pre-emphasis request: 0/0/0/0

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

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

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

<7> [246.114004] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe C

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

<7> [246.114732] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe C

<7> [246.114949] xe 0000:00:02.0: [drm:intel_dp_wait_source_oui [xe]] [CONNECTOR:205:eDP-1] Performing OUI wait (0 ms)

<7> [246.115572] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 13818

<7> [246.117071] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] reserved 13107200 bytes of contiguous stolen space for FBC, limit: 2

<7> [246.117462] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] Enabling FBC on [PLANE:147:plane 1C]

<7> [246.118855] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR1

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

<7> [246.121292] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:202:pipe C]

<6> [248.175336] [IGT] kms_flip: finished subtest C-eDP1, FAIL

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