igt@kms_flip@flip-vs-expired-vblank@a-edp1 on shard-lnl@xe-5137-5390f2273d45bb259d88508828018c0fbbb79d32 Test details

Detail	Value
Duration	10.61 seconds
Hostname	shard-lnl-7
Igt-Version	IGT-Version: 2.4-gb024a3b67 (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-5137-5390f2273d45bb259-debug+ x86_64)
Out	Using IGT_SRANDOM=1779903817 for randomisation Opened device: /dev/dri/card0 Using monotonic timestamps Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2106 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-eDP1: FAIL (10.609s)
Err	Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 [268.718257] (kms_flip:7041) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [268.718333] (kms_flip:7041) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest A-eDP1 failed. ** DEBUG [266.700897] (kms_flip:7041) DEBUG: name = flip last_ts = 267.812988 last_received_ts = 267.812439 last_seq = 3522 current_ts = 267.829651 current_received_ts = 267.829071 current_seq = 3523 count = 432 seq_step = 1 [266.700965] (kms_flip:7041) DEBUG: Vblank took 61us [266.717575] (kms_flip:7041) DEBUG: name = flip last_ts = 267.829651 last_received_ts = 267.829071 last_seq = 3523 current_ts = 267.846313 current_received_ts = 267.845764 current_seq = 3524 count = 433 seq_step = 1 [266.717645] (kms_flip:7041) DEBUG: Vblank took 63us [266.734217] (kms_flip:7041) DEBUG: name = flip last_ts = 267.846313 last_received_ts = 267.845764 last_seq = 3524 current_ts = 267.862976 current_received_ts = 267.862396 current_seq = 3525 count = 434 seq_step = 1 [266.734354] (kms_flip:7041) DEBUG: Vblank took 130us [266.750885] (kms_flip:7041) DEBUG: name = flip last_ts = 267.862976 last_received_ts = 267.862396 last_seq = 3525 current_ts = 267.879639 current_received_ts = 267.879059 current_seq = 3526 count = 435 seq_step = 1 [266.750955] (kms_flip:7041) DEBUG: Vblank took 62us [266.767542] (kms_flip:7041) DEBUG: name = flip last_ts = 267.879639 last_received_ts = 267.879059 last_seq = 3526 current_ts = 267.896301 current_received_ts = 267.895721 current_seq = 3527 count = 436 seq_step = 1 [266.767609] (kms_flip:7041) DEBUG: Vblank took 59us [266.784208] (kms_flip:7041) DEBUG: name = flip last_ts = 267.896301 last_received_ts = 267.895721 last_seq = 3527 current_ts = 267.912964 current_received_ts = 267.912384 current_seq = 3528 count = 437 seq_step = 1 [266.784340] (kms_flip:7041) DEBUG: Vblank took 125us [266.800879] (kms_flip:7041) DEBUG: name = flip last_ts = 267.912964 last_received_ts = 267.912384 last_seq = 3528 current_ts = 267.929626 current_received_ts = 267.929047 current_seq = 3529 count = 438 seq_step = 1 [266.800949] (kms_flip:7041) DEBUG: Vblank took 62us [266.817531] (kms_flip:7041) DEBUG: name = flip last_ts = 267.929626 last_received_ts = 267.929047 last_seq = 3529 current_ts = 267.946289 current_received_ts = 267.945709 current_seq = 3530 count = 439 seq_step = 1 [266.817602] (kms_flip:7041) DEBUG: Vblank took 64us [266.834210] (kms_flip:7041) DEBUG: name = flip last_ts = 267.946289 last_received_ts = 267.945709 last_seq = 3530 current_ts = 267.962921 current_received_ts = 267.962372 current_seq = 3531 count = 440 seq_step = 1 [266.834346] (kms_flip:7041) DEBUG: Vblank took 129us [266.850878] (kms_flip:7041) DEBUG: name = flip last_ts = 267.962921 last_received_ts = 267.962372 last_seq = 3531 current_ts = 267.979584 current_received_ts = 267.979034 current_seq = 3532 count = 441 seq_step = 1 [266.850946] (kms_flip:7041) DEBUG: Vblank took 60us [266.867523] (kms_flip:7041) DEBUG: name = flip last_ts = 267.979584 last_received_ts = 267.979034 last_seq = 3532 current_ts = 267.996246 current_received_ts = 267.995667 current_seq = 3533 count = 442 seq_step = 1 [266.867590] (kms_flip:7041) DEBUG: Vblank took 59us [266.884224] (kms_flip:7041) DEBUG: name = flip last_ts = 267.996246 last_received_ts = 267.995667 last_seq = 3533 current_ts = 268.012909 current_received_ts = 268.012360 current_seq = 3534 count = 443 seq_step = 1 [266.884352] (kms_flip:7041) DEBUG: Vblank took 120us [266.900889] (kms_flip:7041) DEBUG: name = flip last_ts = 268.012909 last_received_ts = 268.012360 last_seq = 3534 current_ts = 268.029572 current_received_ts = 268.029022 current_seq = 3535 count = 444 seq_step = 1 [266.900959] (kms_flip:7041) DEBUG: Vblank took 62us [266.917524] (kms_flip:7041) DEBUG: name = flip last_ts = 268.029572 last_received_ts = 268.029022 last_seq = 3535 current_ts = 268.046234 current_received_ts = 268.045654 current_seq = 3536 count = 445 seq_step = 1 [266.917600] (kms_flip:7041) DEBUG: Vblank took 68us [266.934209] (kms_flip:7041) DEBUG: name = flip last_ts = 268.046234 last_received_ts = 268.045654 last_seq = 3536 current_ts = 268.062897 current_received_ts = 268.062347 current_seq = 3537 count = 446 seq_step = 1 [266.934333] (kms_flip:7041) DEBUG: Vblank took 117us [266.950882] (kms_flip:7041) DEBUG: name = flip last_ts = 268.062897 last_received_ts = 268.062347 last_seq = 3537 current_ts = 268.079559 current_received_ts = 268.079010 current_seq = 3538 count = 447 seq_step = 1 [266.951009] (kms_flip:7041) DEBUG: Vblank took 118us [266.967531] (kms_flip:7041) DEBUG: name = flip last_ts = 268.079559 last_received_ts = 268.079010 last_seq = 3538 current_ts = 268.096222 current_received_ts = 268.095673 current_seq = 3539 count = 448 seq_step = 1 [266.967598] (kms_flip:7041) DEBUG: Vblank took 60us [266.984193] (kms_flip:7041) DEBUG: name = flip last_ts = 268.096222 last_received_ts = 268.095673 last_seq = 3539 current_ts = 268.112885 current_received_ts = 268.112335 current_seq = 3540 count = 449 seq_step = 1 [266.984313] (kms_flip:7041) DEBUG: Vblank took 113us [267.000845] (kms_flip:7041) DEBUG: name = flip last_ts = 268.112885 last_received_ts = 268.112335 last_seq = 3540 current_ts = 268.129547 current_received_ts = 268.128967 current_seq = 3541 count = 450 seq_step = 1 [267.000941] (kms_flip:7041) DEBUG: Vblank took 87us [267.017518] (kms_flip:7041) DEBUG: name = flip last_ts = 268.129547 last_received_ts = 268.128967 last_seq = 3541 current_ts = 268.146210 current_received_ts = 268.145630 current_seq = 3542 count = 451 seq_step = 1 [267.017588] (kms_flip:7041) DEBUG: Vblank took 62us [267.034157] (kms_flip:7041) DEBUG: name = flip last_ts = 268.146210 last_received_ts = 268.145630 last_seq = 3542 current_ts = 268.162872 current_received_ts = 268.162292 current_seq = 3543 count = 452 seq_step = 1 [267.034266] (kms_flip:7041) DEBUG: Vblank took 101us [267.050845] (kms_flip:7041) DEBUG: name = flip last_ts = 268.162872 last_received_ts = 268.162292 last_seq = 3543 current_ts = 268.179535 current_received_ts = 268.178955 current_seq = 3544 count = 453 seq_step = 1 [267.050944] (kms_flip:7041) DEBUG: Vblank took 91us [267.067513] (kms_flip:7041) DEBUG: name = flip last_ts = 268.179535 last_received_ts = 268.178955 last_seq = 3544 current_ts = 268.196198 current_received_ts = 268.195618 current_seq = 3545 count = 454 seq_step = 1 [267.067589] (kms_flip:7041) DEBUG: Vblank took 68us [267.084162] (kms_flip:7041) DEBUG: name = flip last_ts = 268.196198 last_received_ts = 268.195618 last_seq = 3545 current_ts = 268.212860 current_received_ts = 268.212280 current_seq = 3546 count = 455 seq_step = 1 [267.084229] (kms_flip:7041) DEBUG: Vblank took 58us [267.100837] (kms_flip:7041) DEBUG: name = flip last_ts = 268.212860 last_received_ts = 268.212280 last_seq = 3546 current_ts = 268.229523 current_received_ts = 268.228943 current_seq = 3547 count = 456 seq_step = 1 [267.100928] (kms_flip:7041) DEBUG: Vblank took 83us [267.117493] (kms_flip:7041) DEBUG: name = flip last_ts = 268.229523 last_received_ts = 268.228943 last_seq = 3547 current_ts = 268.246155 current_received_ts = 268.245605 current_seq = 3548 count = 457 seq_step = 1 [267.117562] (kms_flip:7041) DEBUG: Vblank took 62us [267.134167] (kms_flip:7041) DEBUG: name = flip last_ts = 268.246155 last_received_ts = 268.245605 last_seq = 3548 current_ts = 268.262817 current_received_ts = 268.262268 current_seq = 3549 count = 458 seq_step = 1 [267.134275] (kms_flip:7041) DEBUG: Vblank took 99us [267.150818] (kms_flip:7041) DEBUG: name = flip last_ts = 268.262817 last_received_ts = 268.262268 last_seq = 3549 current_ts = 268.279480 current_received_ts = 268.278931 current_seq = 3550 count = 459 seq_step = 1 [267.150919] (kms_flip:7041) DEBUG: Vblank took 92us [267.167477] (kms_flip:7041) DEBUG: name = flip last_ts = 268.279480 last_received_ts = 268.278931 last_seq = 3550 current_ts = 268.296143 current_received_ts = 268.295593 current_seq = 3551 count = 460 seq_step = 1 [267.167544] (kms_flip:7041) DEBUG: Vblank took 59us [267.184080] (kms_flip:7041) DEBUG: name = flip last_ts = 268.296143 last_received_ts = 268.295593 last_seq = 3551 current_ts = 268.312836 current_received_ts = 268.312164 current_seq = 3552 count = 461 seq_step = 1 [267.184150] (kms_flip:7041) DEBUG: Vblank took 63us [267.200822] (kms_flip:7041) DEBUG: name = flip last_ts = 268.312836 last_received_ts = 268.312164 last_seq = 3552 current_ts = 268.329468 current_received_ts = 268.328918 current_seq = 3553 count = 462 seq_step = 1 [267.200924] (kms_flip:7041) DEBUG: Vblank took 94us [267.217476] (kms_flip:7041) DEBUG: name = flip last_ts = 268.329468 last_received_ts = 268.328918 last_seq = 3553 current_ts = 268.346130 current_received_ts = 268.345581 current_seq = 3554 count = 463 seq_step = 1 [267.217544] (kms_flip:7041) DEBUG: Vblank took 60us [267.234143] (kms_flip:7041) DEBUG: name = flip last_ts = 268.346130 last_received_ts = 268.345581 last_seq = 3554 current_ts = 268.362793 current_received_ts = 268.362244 current_seq = 3555 count = 464 seq_step = 1 [267.234262] (kms_flip:7041) DEBUG: Vblank took 111us [267.250813] (kms_flip:7041) DEBUG: name = flip last_ts = 268.362793 last_received_ts = 268.362244 last_seq = 3555 current_ts = 268.379456 current_received_ts = 268.378906 current_seq = 3556 count = 465 seq_step = 1 [267.250883] (kms_flip:7041) DEBUG: Vblank took 63us [267.267452] (kms_flip:7041) DEBUG: name = flip last_ts = 268.379456 last_received_ts = 268.378906 last_seq = 3556 current_ts = 268.396118 current_received_ts = 268.395538 current_seq = 3557 count = 466 seq_step = 1 [267.267584] (kms_flip:7041) DEBUG: Vblank took 125us [267.284111] (kms_flip:7041) DEBUG: name = flip last_ts = 268.396118 last_received_ts = 268.395538 last_seq = 3557 current_ts = 268.412781 current_received_ts = 268.412201 current_seq = 3558 count = 467 seq_step = 1 [267.284248] (kms_flip:7041) DEBUG: Vblank took 131us [267.300804] (kms_flip:7041) DEBUG: name = flip last_ts = 268.412781 last_received_ts = 268.412201 last_seq = 3558 current_ts = 268.429443 current_received_ts = 268.428894 current_seq = 3559 count = 468 seq_step = 1 [267.300874] (kms_flip:7041) DEBUG: Vblank took 62us [267.317448] (kms_flip:7041) DEBUG: name = flip last_ts = 268.429443 last_received_ts = 268.428894 last_seq = 3559 current_ts = 268.446106 current_received_ts = 268.445526 current_seq = 3560 count = 469 seq_step = 1 [267.317574] (kms_flip:7041) DEBUG: Vblank took 118us [267.334102] (kms_flip:7041) DEBUG: name = flip last_ts = 268.446106 last_received_ts = 268.445526 last_seq = 3560 current_ts = 268.462769 current_received_ts = 268.462189 current_seq = 3561 count = 470 seq_step = 1 [267.334168] (kms_flip:7041) DEBUG: Vblank took 59us [267.350790] (kms_flip:7041) DEBUG: name = flip last_ts = 268.462769 last_received_ts = 268.462189 last_seq = 3561 current_ts = 268.479431 current_received_ts = 268.478851 current_seq = 3562 count = 471 seq_step = 1 [267.350860] (kms_flip:7041) DEBUG: Vblank took 62us [267.367434] (kms_flip:7041) DEBUG: name = flip last_ts = 268.479431 last_received_ts = 268.478851 last_seq = 3562 current_ts = 268.496094 current_received_ts = 268.495514 current_seq = 3563 count = 472 seq_step = 1 [267.367504] (kms_flip:7041) DEBUG: Vblank took 62us [267.384099] (kms_flip:7041) DEBUG: name = flip last_ts = 268.496094 last_received_ts = 268.495514 last_seq = 3563 current_ts = 268.512756 current_received_ts = 268.512146 current_seq = 3564 count = 473 seq_step = 1 [267.384169] (kms_flip:7041) DEBUG: Vblank took 62us [267.400770] (kms_flip:7041) DEBUG: name = flip last_ts = 268.512756 last_received_ts = 268.512146 last_seq = 3564 current_ts = 268.529419 current_received_ts = 268.528839 current_seq = 3565 count = 474 seq_step = 1 [267.400837] (kms_flip:7041) DEBUG: Vblank took 60us [267.417407] (kms_flip:7041) DEBUG: name = flip last_ts = 268.529419 last_received_ts = 268.528839 last_seq = 3565 current_ts = 268.546082 current_received_ts = 268.545471 current_seq = 3566 count = 475 seq_step = 1 [267.417547] (kms_flip:7041) DEBUG: Vblank took 131us [267.434118] (kms_flip:7041) DEBUG: name = flip last_ts = 268.546082 last_received_ts = 268.545471 last_seq = 3566 current_ts = 268.562744 current_received_ts = 268.562164 current_seq = 3567 count = 476 seq_step = 1 [267.434189] (kms_flip:7041) DEBUG: Vblank took 63us [267.450773] (kms_flip:7041) DEBUG: name = flip last_ts = 268.562744 last_received_ts = 268.562164 last_seq = 3567 current_ts = 268.579407 current_received_ts = 268.578827 current_seq = 3568 count = 477 seq_step = 1 [267.450934] (kms_flip:7041) DEBUG: Vblank took 117us [267.467427] (kms_flip:7041) DEBUG: name = flip last_ts = 268.579407 last_received_ts = 268.578827 last_seq = 3568 current_ts = 268.596069 current_received_ts = 268.595459 current_seq = 3569 count = 478 seq_step = 1 [267.467559] (kms_flip:7041) DEBUG: Vblank took 124us [267.484111] (kms_flip:7041) DEBUG: name = flip last_ts = 268.596069 last_received_ts = 268.595459 last_seq = 3569 current_ts = 268.612701 current_received_ts = 268.612152 current_seq = 3570 count = 479 seq_step = 1 [267.484184] (kms_flip:7041) DEBUG: Vblank took 65us [267.500784] (kms_flip:7041) DEBUG: name = flip last_ts = 268.612701 last_received_ts = 268.612152 last_seq = 3570 current_ts = 268.629364 current_received_ts = 268.628815 current_seq = 3571 count = 480 seq_step = 1 [267.500854] (kms_flip:7041) DEBUG: Vblank took 62us [267.517412] (kms_flip:7041) DEBUG: name = flip last_ts = 268.629364 last_received_ts = 268.628815 last_seq = 3571 current_ts = 268.646027 current_received_ts = 268.645447 current_seq = 3572 count = 481 seq_step = 1 [267.517544] (kms_flip:7041) DEBUG: Vblank took 124us [267.534099] (kms_flip:7041) DEBUG: name = flip last_ts = 268.646027 last_received_ts = 268.645447 last_seq = 3572 current_ts = 268.662689 current_received_ts = 268.662140 current_seq = 3573 count = 482 seq_step = 1 [267.534171] (kms_flip:7041) DEBUG: Vblank took 65us [267.550762] (kms_flip:7041) DEBUG: name = flip last_ts = 268.662689 last_received_ts = 268.662140 last_seq = 3573 current_ts = 268.679352 current_received_ts = 268.678802 current_seq = 3574 count = 483 seq_step = 1 [267.550831] (kms_flip:7041) DEBUG: Vblank took 62us [267.567427] (kms_flip:7041) DEBUG: name = flip last_ts = 268.679352 last_received_ts = 268.678802 last_seq = 3574 current_ts = 268.696014 current_received_ts = 268.695465 current_seq = 3575 count = 484 seq_step = 1 [267.567542] (kms_flip:7041) DEBUG: Vblank took 107us [267.584093] (kms_flip:7041) DEBUG: name = flip last_ts = 268.696014 last_received_ts = 268.695465 last_seq = 3575 current_ts = 268.712677 current_received_ts = 268.712128 current_seq = 3576 count = 485 seq_step = 1 [267.584165] (kms_flip:7041) DEBUG: Vblank took 63us [267.600748] (kms_flip:7041) DEBUG: name = flip last_ts = 268.712677 last_received_ts = 268.712128 last_seq = 3576 current_ts = 268.729340 current_received_ts = 268.728760 current_seq = 3577 count = 486 seq_step = 1 [267.600824] (kms_flip:7041) DEBUG: Vblank took 68us [267.617399] (kms_flip:7041) DEBUG: name = flip last_ts = 268.729340 last_received_ts = 268.728760 last_seq = 3577 current_ts = 268.746002 current_received_ts = 268.745422 current_seq = 3578 count = 487 seq_step = 1 [267.617470] (kms_flip:7041) DEBUG: Vblank took 63us [267.634075] (kms_flip:7041) DEBUG: name = flip last_ts = 268.746002 last_received_ts = 268.745422 last_seq = 3578 current_ts = 268.762665 current_received_ts = 268.762085 current_seq = 3579 count = 488 seq_step = 1 [267.634146] (kms_flip:7041) DEBUG: Vblank took 62us [267.650746] (kms_flip:7041) DEBUG: name = flip last_ts = 268.762665 last_received_ts = 268.762085 last_seq = 3579 current_ts = 268.779327 current_received_ts = 268.778748 current_seq = 3580 count = 489 seq_step = 1 [267.650816] (kms_flip:7041) DEBUG: Vblank took 62us [267.667389] (kms_flip:7041) DEBUG: name = flip last_ts = 268.779327 last_received_ts = 268.778748 last_seq = 3580 current_ts = 268.795990 current_received_ts = 268.795410 current_seq = 3581 count = 490 seq_step = 1 [267.667514] (kms_flip:7041) DEBUG: Vblank took 117us [267.684077] (kms_flip:7041) DEBUG: name = flip last_ts = 268.795990 last_received_ts = 268.795410 last_seq = 3581 current_ts = 268.812653 current_received_ts = 268.812073 current_seq = 3582 count = 491 seq_step = 1 [267.684144] (kms_flip:7041) DEBUG: Vblank took 60us [267.700736] (kms_flip:7041) DEBUG: name = flip last_ts = 268.812653 last_received_ts = 268.812073 last_seq = 3582 current_ts = 268.829315 current_received_ts = 268.828735 current_seq = 3583 count = 492 seq_step = 1 [267.700806] (kms_flip:7041) DEBUG: Vblank took 63us [267.717415] (kms_flip:7041) DEBUG: name = flip last_ts = 268.829315 last_received_ts = 268.828735 last_seq = 3583 current_ts = 268.845978 current_received_ts = 268.845428 current_seq = 3584 count = 493 seq_step = 1 [267.717539] (kms_flip:7041) DEBUG: Vblank took 115us [267.734079] (kms_flip:7041) DEBUG: name = flip last_ts = 268.845978 last_received_ts = 268.845428 last_seq = 3584 current_ts = 268.862640 current_received_ts = 268.862061 current_seq = 3585 count = 494 seq_step = 1 [267.734152] (kms_flip:7041) DEBUG: Vblank took 64us [267.750739] (kms_flip:7041) DEBUG: name = flip last_ts = 268.862640 last_received_ts = 268.862061 last_seq = 3585 current_ts = 268.879303 current_received_ts = 268.878723 current_seq = 3586 count = 495 seq_step = 1 [267.750809] (kms_flip:7041) DEBUG: Vblank took 60us [267.767373] (kms_flip:7041) DEBUG: name = flip last_ts = 268.879303 last_received_ts = 268.878723 last_seq = 3586 current_ts = 268.895935 current_received_ts = 268.895355 current_seq = 3587 count = 496 seq_step = 1 [267.767492] (kms_flip:7041) DEBUG: Vblank took 112us [267.784071] (kms_flip:7041) DEBUG: name = flip last_ts = 268.895935 last_received_ts = 268.895355 last_seq = 3587 current_ts = 268.912598 current_received_ts = 268.912048 current_seq = 3588 count = 497 seq_step = 1 [267.784144] (kms_flip:7041) DEBUG: Vblank took 65us [267.800715] (kms_flip:7041) DEBUG: name = flip last_ts = 268.912598 last_received_ts = 268.912048 last_seq = 3588 current_ts = 268.929260 current_received_ts = 268.928711 current_seq = 3589 count = 498 seq_step = 1 [267.800785] (kms_flip:7041) DEBUG: Vblank took 62us [267.817389] (kms_flip:7041) DEBUG: name = flip last_ts = 268.929260 last_received_ts = 268.928711 last_seq = 3589 current_ts = 268.945923 current_received_ts = 268.945374 current_seq = 3590 count = 499 seq_step = 1 [267.817532] (kms_flip:7041) DEBUG: Vblank took 135us [267.834075] (kms_flip:7041) DEBUG: name = flip last_ts = 268.945923 last_received_ts = 268.945374 last_seq = 3590 current_ts = 268.962585 current_received_ts = 268.962067 current_seq = 3591 count = 500 seq_step = 1 [267.834145] (kms_flip:7041) DEBUG: Vblank took 63us [267.850713] (kms_flip:7041) DEBUG: name = flip last_ts = 268.962585 last_received_ts = 268.962067 last_seq = 3591 current_ts = 268.979248 current_received_ts = 268.978699 current_seq = 3592 count = 501 seq_step = 1 [267.850785] (kms_flip:7041) DEBUG: Vblank took 63us [267.867350] (kms_flip:7041) DEBUG: name = flip last_ts = 268.979248 last_received_ts = 268.978699 last_seq = 3592 current_ts = 268.995911 current_received_ts = 268.995331 current_seq = 3593 count = 502 seq_step = 1 [267.867490] (kms_flip:7041) DEBUG: Vblank took 132us [267.884068] (kms_flip:7041) DEBUG: name = flip last_ts = 268.995911 last_received_ts = 268.995331 last_seq = 3593 current_ts = 269.012573 current_received_ts = 269.012024 current_seq = 3594 count = 503 seq_step = 1 [267.884139] (kms_flip:7041) DEBUG: Vblank took 63us [267.900706] (kms_flip:7041) DEBUG: name = flip last_ts = 269.012573 last_received_ts = 269.012024 last_seq = 3594 current_ts = 269.029236 current_received_ts = 269.028687 current_seq = 3595 count = 504 seq_step = 1 [267.900844] (kms_flip:7041) DEBUG: Vblank took 131us [267.917349] (kms_flip:7041) DEBUG: name = flip last_ts = 269.029236 last_received_ts = 269.028687 last_seq = 3595 current_ts = 269.045898 current_received_ts = 269.045319 current_seq = 3596 count = 505 seq_step = 1 [267.917419] (kms_flip:7041) DEBUG: Vblank took 62us [267.934086] (kms_flip:7041) DEBUG: name = flip last_ts = 269.045898 last_received_ts = 269.045319 last_seq = 3596 current_ts = 269.062561 current_received_ts = 269.062042 current_seq = 3597 count = 506 seq_step = 1 [267.934224] (kms_flip:7041) DEBUG: Vblank took 130us [267.950703] (kms_flip:7041) DEBUG: name = flip last_ts = 269.062561 last_received_ts = 269.062042 last_seq = 3597 current_ts = 269.079224 current_received_ts = 269.078674 current_seq = 3598 count = 507 seq_step = 1 [267.950769] (kms_flip:7041) DEBUG: Vblank took 59us [267.967393] (kms_flip:7041) DEBUG: name = flip last_ts = 269.079224 last_received_ts = 269.078674 last_seq = 3598 current_ts = 269.095886 current_received_ts = 269.095337 current_seq = 3599 count = 508 seq_step = 1 [267.967536] (kms_flip:7041) DEBUG: Vblank took 135us [267.984023] (kms_flip:7041) DEBUG: name = flip last_ts = 269.095886 last_received_ts = 269.095337 last_seq = 3599 current_ts = 269.112549 current_received_ts = 269.111969 current_seq = 3600 count = 509 seq_step = 1 [267.984117] (kms_flip:7041) DEBUG: Vblank took 84us [268.000693] (kms_flip:7041) DEBUG: name = flip last_ts = 269.112549 last_received_ts = 269.111969 last_seq = 3600 current_ts = 269.129211 current_received_ts = 269.128632 current_seq = 3601 count = 510 seq_step = 1 [268.000822] (kms_flip:7041) DEBUG: Vblank took 122us [268.017331] (kms_flip:7041) DEBUG: name = flip last_ts = 269.129211 last_received_ts = 269.128632 last_seq = 3601 current_ts = 269.145874 current_received_ts = 269.145264 current_seq = 3602 count = 511 seq_step = 1 [268.017427] (kms_flip:7041) DEBUG: Vblank took 89us [268.034004] (kms_flip:7041) DEBUG: name = flip last_ts = 269.145874 last_received_ts = 269.145264 last_seq = 3602 current_ts = 269.162537 current_received_ts = 269.161957 current_seq = 3603 count = 512 seq_step = 1 [268.034090] (kms_flip:7041) DEBUG: Vblank took 79us [268.050669] (kms_flip:7041) DEBUG: name = flip last_ts = 269.162537 last_received_ts = 269.161957 last_seq = 3603 current_ts = 269.179199 current_received_ts = 269.178619 current_seq = 3604 count = 513 seq_step = 1 [268.050740] (kms_flip:7041) DEBUG: Vblank took 62us [268.067322] (kms_flip:7041) DEBUG: name = flip last_ts = 269.179199 last_received_ts = 269.178619 last_seq = 3604 current_ts = 269.195862 current_received_ts = 269.195251 current_seq = 3605 count = 514 seq_step = 1 [268.067436] (kms_flip:7041) DEBUG: Vblank took 106us [268.084015] (kms_flip:7041) DEBUG: name = flip last_ts = 269.195862 last_received_ts = 269.195251 last_seq = 3605 current_ts = 269.212524 current_received_ts = 269.211945 current_seq = 3606 count = 515 seq_step = 1 [268.084107] (kms_flip:7041) DEBUG: Vblank took 84us [268.100653] (kms_flip:7041) DEBUG: name = flip last_ts = 269.212524 last_received_ts = 269.211945 last_seq = 3606 current_ts = 269.229156 current_received_ts = 269.228577 current_seq = 3607 count = 516 seq_step = 1 [268.100720] (kms_flip:7041) DEBUG: Vblank took 59us [268.117309] (kms_flip:7041) DEBUG: name = flip last_ts = 269.229156 last_received_ts = 269.228577 last_seq = 3607 current_ts = 269.245819 current_received_ts = 269.245239 current_seq = 3608 count = 517 seq_step = 1 [268.117439] (kms_flip:7041) DEBUG: Vblank took 122us [268.134014] (kms_flip:7041) DEBUG: name = flip last_ts = 269.245819 last_received_ts = 269.245239 last_seq = 3608 current_ts = 269.262482 current_received_ts = 269.261932 current_seq = 3609 count = 518 seq_step = 1 [268.134111] (kms_flip:7041) DEBUG: Vblank took 88us [268.150638] (kms_flip:7041) DEBUG: name = flip last_ts = 269.262482 last_received_ts = 269.261932 last_seq = 3609 current_ts = 269.279144 current_received_ts = 269.278564 current_seq = 3610 count = 519 seq_step = 1 [268.150701] (kms_flip:7041) DEBUG: Vblank took 52us [268.167343] (kms_flip:7041) DEBUG: name = flip last_ts = 269.279144 last_received_ts = 269.278564 last_seq = 3610 current_ts = 269.295807 current_received_ts = 269.295258 current_seq = 3611 count = 520 seq_step = 1 [268.167451] (kms_flip:7041) DEBUG: Vblank took 101us [268.183994] (kms_flip:7041) DEBUG: name = flip last_ts = 269.295807 last_received_ts = 269.295258 last_seq = 3611 current_ts = 269.312469 current_received_ts = 269.311920 current_seq = 3612 count = 521 seq_step = 1 [268.184064] (kms_flip:7041) DEBUG: Vblank took 62us [268.200655] (kms_flip:7041) DEBUG: name = flip last_ts = 269.312469 last_received_ts = 269.311920 last_seq = 3612 current_ts = 269.329132 current_received_ts = 269.328583 current_seq = 3613 count = 522 seq_step = 1 [268.200722] (kms_flip:7041) DEBUG: Vblank took 60us [268.217326] (kms_flip:7041) DEBUG: name = flip last_ts = 269.329132 last_received_ts = 269.328583 last_seq = 3613 current_ts = 269.345795 current_received_ts = 269.345245 current_seq = 3614 count = 523 seq_step = 1 [268.217442] (kms_flip:7041) DEBUG: Vblank took 109us [268.233975] (kms_flip:7041) DEBUG: name = flip last_ts = 269.345795 last_received_ts = 269.345245 last_seq = 3614 current_ts = 269.362457 current_received_ts = 269.361877 current_seq = 3615 count = 524 seq_step = 1 [268.234042] (kms_flip:7041) DEBUG: Vblank took 59us [268.250633] (kms_flip:7041) DEBUG: name = flip last_ts = 269.362457 last_received_ts = 269.361877 last_seq = 3615 current_ts = 269.379120 current_received_ts = 269.378540 current_seq = 3616 count = 525 seq_step = 1 [268.250700] (kms_flip:7041) DEBUG: Vblank took 59us [268.267298] (kms_flip:7041) DEBUG: name = flip last_ts = 269.379120 last_received_ts = 269.378540 last_seq = 3616 current_ts = 269.395782 current_received_ts = 269.395203 current_seq = 3617 count = 526 seq_step = 1 [268.267441] (kms_flip:7041) DEBUG: Vblank took 135us [268.283971] (kms_flip:7041) DEBUG: name = flip last_ts = 269.395782 last_received_ts = 269.395203 last_seq = 3617 current_ts = 269.412445 current_received_ts = 269.411865 current_seq = 3618 count = 527 seq_step = 1 [268.284041] (kms_flip:7041) DEBUG: Vblank took 62us [268.300614] (kms_flip:7041) DEBUG: name = flip last_ts = 269.412445 last_received_ts = 269.411865 last_seq = 3618 current_ts = 269.429108 current_received_ts = 269.428497 current_seq = 3619 count = 528 seq_step = 1 [268.300752] (kms_flip:7041) DEBUG: Vblank took 130us [268.317301] (kms_flip:7041) DEBUG: name = flip last_ts = 269.429108 last_received_ts = 269.428497 last_seq = 3619 current_ts = 269.445770 current_received_ts = 269.445190 current_seq = 3620 count = 529 seq_step = 1 [268.317444] (kms_flip:7041) DEBUG: Vblank took 135us [268.333966] (kms_flip:7041) DEBUG: name = flip last_ts = 269.445770 last_received_ts = 269.445190 last_seq = 3620 current_ts = 269.462433 current_received_ts = 269.461853 current_seq = 3621 count = 530 seq_step = 1 [268.334036] (kms_flip:7041) DEBUG: Vblank took 61us [268.350610] (kms_flip:7041) DEBUG: name = flip last_ts = 269.462433 last_received_ts = 269.461853 last_seq = 3621 current_ts = 269.479095 current_received_ts = 269.478485 current_seq = 3622 count = 531 seq_step = 1 [268.350745] (kms_flip:7041) DEBUG: Vblank took 127us [268.367303] (kms_flip:7041) DEBUG: name = flip last_ts = 269.479095 last_received_ts = 269.478485 last_seq = 3622 current_ts = 269.495758 current_received_ts = 269.495178 current_seq = 3623 count = 532 seq_step = 1 [268.367374] (kms_flip:7041) DEBUG: Vblank took 63us [268.383962] (kms_flip:7041) DEBUG: name = flip last_ts = 269.495758 last_received_ts = 269.495178 last_seq = 3623 current_ts = 269.512421 current_received_ts = 269.511841 current_seq = 3624 count = 533 seq_step = 1 [268.384038] (kms_flip:7041) DEBUG: Vblank took 68us [268.400608] (kms_flip:7041) DEBUG: name = flip last_ts = 269.512421 last_received_ts = 269.511841 last_seq = 3624 current_ts = 269.529053 current_received_ts = 269.528473 current_seq = 3625 count = 534 seq_step = 1 [268.400742] (kms_flip:7041) DEBUG: Vblank took 126us [268.417299] (kms_flip:7041) DEBUG: name = flip last_ts = 269.529053 last_received_ts = 269.528473 last_seq = 3625 current_ts = 269.545746 current_received_ts = 269.545166 current_seq = 3626 count = 535 seq_step = 1 [268.417366] (kms_flip:7041) DEBUG: Vblank took 59us [268.433935] (kms_flip:7041) DEBUG: name = flip last_ts = 269.545746 last_received_ts = 269.545166 last_seq = 3626 current_ts = 269.562378 current_received_ts = 269.561798 current_seq = 3627 count = 536 seq_step = 1 [268.434009] (kms_flip:7041) DEBUG: Vblank took 65us [268.450603] (kms_flip:7041) DEBUG: name = flip last_ts = 269.562378 last_received_ts = 269.561798 last_seq = 3627 current_ts = 269.579041 current_received_ts = 269.578461 current_seq = 3628 count = 537 seq_step = 1 [268.450731] (kms_flip:7041) DEBUG: Vblank took 121us [268.467281] (kms_flip:7041) DEBUG: name = flip last_ts = 269.579041 last_received_ts = 269.578461 last_seq = 3628 current_ts = 269.595703 current_received_ts = 269.595154 current_seq = 3629 count = 538 seq_step = 1 [268.467347] (kms_flip:7041) DEBUG: Vblank took 59us [268.483948] (kms_flip:7041) DEBUG: name = flip last_ts = 269.595703 last_received_ts = 269.595154 last_seq = 3629 current_ts = 269.612366 current_received_ts = 269.611816 current_seq = 3630 count = 539 seq_step = 1 [268.484018] (kms_flip:7041) DEBUG: Vblank took 62us [268.500586] (kms_flip:7041) DEBUG: name = flip last_ts = 269.612366 last_received_ts = 269.611816 last_seq = 3630 current_ts = 269.629028 current_received_ts = 269.628448 current_seq = 3631 count = 540 seq_step = 1 [268.500714] (kms_flip:7041) DEBUG: Vblank took 121us [268.517283] (kms_flip:7041) DEBUG: name = flip last_ts = 269.629028 last_received_ts = 269.628448 last_seq = 3631 current_ts = 269.645691 current_received_ts = 269.645142 current_seq = 3632 count = 541 seq_step = 1 [268.517350] (kms_flip:7041) DEBUG: Vblank took 60us [268.533946] (kms_flip:7041) DEBUG: name = flip last_ts = 269.645691 last_received_ts = 269.645142 last_seq = 3632 current_ts = 269.662354 current_received_ts = 269.661804 current_seq = 3633 count = 542 seq_step = 1 [268.534016] (kms_flip:7041) DEBUG: Vblank took 62us [268.550594] (kms_flip:7041) DEBUG: name = flip last_ts = 269.662354 last_received_ts = 269.661804 last_seq = 3633 current_ts = 269.679016 current_received_ts = 269.678436 current_seq = 3634 count = 543 seq_step = 1 [268.550720] (kms_flip:7041) DEBUG: Vblank took 118us [268.567275] (kms_flip:7041) DEBUG: name = flip last_ts = 269.679016 last_received_ts = 269.678436 last_seq = 3634 current_ts = 269.695679 current_received_ts = 269.695129 current_seq = 3635 count = 544 seq_step = 1 [268.567347] (kms_flip:7041) DEBUG: Vblank took 64us [268.583933] (kms_flip:7041) DEBUG: name = flip last_ts = 269.695679 last_received_ts = 269.695129 last_seq = 3635 current_ts = 269.712341 current_received_ts = 269.711761 current_seq = 3636 count = 545 seq_step = 1 [268.584000] (kms_flip:7041) DEBUG: Vblank took 59us [268.600593] (kms_flip:7041) DEBUG: name = flip last_ts = 269.712341 last_received_ts = 269.711761 last_seq = 3636 current_ts = 269.729004 current_received_ts = 269.728424 current_seq = 3637 count = 546 seq_step = 1 [268.600731] (kms_flip:7041) DEBUG: Vblank took 130us [268.617251] (kms_flip:7041) DEBUG: name = flip last_ts = 269.729004 last_received_ts = 269.728424 last_seq = 3637 current_ts = 269.745667 current_received_ts = 269.745087 current_seq = 3638 count = 547 seq_step = 1 [268.617317] (kms_flip:7041) DEBUG: Vblank took 59us [268.633925] (kms_flip:7041) DEBUG: name = flip last_ts = 269.745667 last_received_ts = 269.745087 last_seq = 3638 current_ts = 269.762329 current_received_ts = 269.761749 current_seq = 3639 count = 548 seq_step = 1 [268.634055] (kms_flip:7041) DEBUG: Vblank took 122us [268.650577] (kms_flip:7041) DEBUG: name = flip last_ts = 269.762329 last_received_ts = 269.761749 last_seq = 3639 current_ts = 269.778992 current_received_ts = 269.778412 current_seq = 3640 count = 549 seq_step = 1 [268.650698] (kms_flip:7041) DEBUG: Vblank took 113us [268.667248] (kms_flip:7041) DEBUG: name = flip last_ts = 269.778992 last_received_ts = 269.778412 last_seq = 3640 current_ts = 269.795624 current_received_ts = 269.795074 current_seq = 3641 count = 550 seq_step = 1 [268.667316] (kms_flip:7041) DEBUG: Vblank took 59us [268.683911] (kms_flip:7041) DEBUG: name = flip last_ts = 269.795624 last_received_ts = 269.795074 last_seq = 3641 current_ts = 269.812317 current_received_ts = 269.811737 current_seq = 3642 count = 551 seq_step = 1 [268.683982] (kms_flip:7041) DEBUG: Vblank took 62us [268.700567] (kms_flip:7041) DEBUG: name = flip last_ts = 269.812317 last_received_ts = 269.811737 last_seq = 3642 current_ts = 269.828949 current_received_ts = 269.828400 current_seq = 3643 count = 552 seq_step = 1 [268.700705] (kms_flip:7041) DEBUG: Vblank took 130us [268.717227] (kms_flip:7041) DEBUG: name = flip last_ts = 269.828949 last_received_ts = 269.828400 last_seq = 3643 current_ts = 269.845612 current_received_ts = 269.845032 current_seq = 3644 count = 553 seq_step = 1 [268.718253] (kms_flip:7041) DEBUG: Vblank took 1018us [268.718257] (kms_flip:7041) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [268.718333] (kms_flip:7041) CRITICAL: Failed assertion: end - start < 500 [268.739174] (kms_flip:7041) igt_core-INFO: Stack trace: [268.749971] (kms_flip:7041) igt_core-INFO: #0 ../lib/igt_core.c:2106 __igt_fail_assert() [268.751241] (kms_flip:7041) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [268.751327] (kms_flip:7041) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [268.751365] (kms_flip:7041) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() [268.751406] (kms_flip:7041) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [268.755252] (kms_flip:7041) igt_core-INFO: #5 [__libc_init_first+0x8a] [268.756091] (kms_flip:7041) igt_core-INFO: #6 [__libc_start_main+0x8b] [268.756804] (kms_flip:7041) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-eDP1: FAIL (10.609s)
Dmesg	<6> [274.631513] Console: switching to colour dummy device 80x25 <6> [274.631827] [IGT] kms_flip: executing <7> [274.638062] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [274.638072] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [274.638225] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [274.638335] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [274.638630] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [274.638634] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [274.638765] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [274.638852] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [274.639053] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [274.639056] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [274.639167] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [274.639251] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <7> [274.639562] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] <7> [274.639566] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:393:eDP-1] <7> [274.640033] xe 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [xe]] DSC DPCD: 00 11 00 76 0b 01 01 80 00 01 06 66 08 00 00 00 <7> [274.640351] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000 <7> [274.640465] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [274.640576] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [274.640700] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Supported Monitor Refresh rate range is 40 Hz - 120 Hz <5> [274.640704] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [274.640706] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [274.640707] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00 <7> [274.640709] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc. <5> [274.640710] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [274.640712] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor <5> [274.640714] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [274.640715] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0 <5> [274.640717] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [274.640728] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes <7> [274.640821] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps <7> [274.640912] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no <5> [274.641225] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [274.641227] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [274.641229] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [274.641289] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes: <7> [274.641294] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [274.641298] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 120 695310 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [274.641311] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [274.642168] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [274.642310] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [274.642333] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [274.642336] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [274.642479] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [274.642489] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [274.642492] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [274.642628] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <6> [274.643228] [IGT] kms_flip: starting subtest flip-vs-expired-vblank <6> [274.644854] [IGT] kms_flip: starting dynamic subtest A-eDP1 <7> [274.645512] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431] <7> [274.646038] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [274.723653] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [274.723884] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [274.724201] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [274.724497] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [274.724765] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [274.725026] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [274.725285] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [274.725621] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [274.725885] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [274.726172] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [274.726450] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [274.726713] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [274.726983] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [274.727302] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [274.727624] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [274.727904] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [274.728180] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [274.728479] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [274.728788] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [274.729070] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [274.729363] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [274.729631] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [274.729919] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [274.730181] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [274.730505] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [274.730761] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [274.731017] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [274.731294] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [274.731613] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [274.731872] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [274.732124] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [274.732377] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [274.732654] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [274.732903] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [274.733146] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [274.733461] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [274.733687] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [274.733917] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [274.734141] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [274.734380] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [274.734618] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [274.734941] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [274.735153] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [274.735377] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0 <7> [274.735541] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [274.735695] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm <7> [274.735847] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 1, 13, 13, 13, 13, 13, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [274.735994] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 24, 313, 313, 313, 313, 313, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [274.736131] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 28, 346, 346, 346, 346, 346, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [274.736300] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [274.736547] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400 <7> [274.736753] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400 <7> [274.736948] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [274.737137] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [274.737358] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [274.737544] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [274.737748] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [274.737950] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [274.738137] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [274.738298] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [274.738517] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [274.738697] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [274.738849] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [274.738998] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [274.739149] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [274.739297] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [274.739459] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [274.739662] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [274.739815] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [274.740004] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [274.748910] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [274.749064] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [274.952572] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [274.953169] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [274.964736] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [274.965036] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [274.965182] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [274.965330] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [274.965561] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [275.017724] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [275.018062] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [275.026275] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [275.026639] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [275.026718] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [275.027053] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [275.029088] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [275.029526] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [275.029908] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [275.030159] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [275.030408] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [275.030646] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [275.030883] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [275.031122] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [275.031350] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [275.031601] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [275.031810] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [275.032015] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [275.032215] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [275.032429] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [275.032640] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [275.032853] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [275.033142] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [275.033348] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [275.033590] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [275.034008] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [275.034284] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [275.034668] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [275.034925] 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> [275.035233] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [275.035504] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [275.036288] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [275.036628] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [275.036888] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [275.036948] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [275.037103] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [275.037433] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:151:pipe A] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [275.037735] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [275.038040] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [275.038339] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:151:pipe A] <7> [275.038703] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [275.038986] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [275.039252] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [275.039537] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [275.039810] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [275.040058] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [275.040284] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [275.040535] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [275.040743] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [275.040947] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [275.041142] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [275.041328] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [275.041532] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [275.041745] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [275.041933] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [275.042104] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [275.042274] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [275.042483] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [275.042644] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [275.042801] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [275.042957] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [275.043125] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [275.043276] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [275.043444] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [275.043593] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [275.043738] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [275.043878] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [275.044017] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [275.044151] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [275.044302] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [275.044471] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [275.044601] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [275.044725] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [275.044846] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [275.044967] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [275.045079] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [275.045193] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [275.045314] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 0, found 432000) <7> [275.045463] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [275.045624] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [275.045710] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x1 <7> [275.045820] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [275.045901] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [275.045978] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [275.046053] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [275.046125] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [275.046201] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [275.046300] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1 <7> [275.046447] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [275.046554] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [275.046656] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [275.046755] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [275.046850] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [275.046944] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 0 kHz -> 173855 kHz <7> [275.047055] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [275.047152] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [275.047242] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [275.047334] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [275.047453] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0 <7> [275.047550] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0 <7> [275.047666] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: yes [modeset] <7> [275.047788] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [275.047880] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: A, pipe bpp: 30, dithering: 0 <7> [275.047963] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [275.048044] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [275.048125] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [275.048205] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [275.048284] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [275.048373] 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> [275.048472] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [275.048573] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [275.048675] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [275.048768] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [275.048848] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [275.048929] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [275.049008] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [275.049086] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [275.049164] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [275.049240] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [275.049317] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [275.049429] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [275.049530] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [275.049631] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [275.049721] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [275.049797] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [275.049874] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [275.049950] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [275.050027] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [275.050102] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [275.050179] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [275.050255] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0 <7> [275.050333] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [275.050431] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [275.050536] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [275.050639] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [275.050742] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [275.050824] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [275.050901] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [275.050978] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [275.051055] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [275.051131] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [275.051208] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [275.051284] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [275.051359] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [275.051470] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [275.051576] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [275.051688] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [275.051794] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [275.051871] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [275.051946] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [275.052022] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [275.052098] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [275.052172] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [275.052247] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [275.052321] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [275.052402] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [275.052499] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [275.052594] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [275.052690] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [275.052783] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [FB:431] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [275.052870] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [275.052954] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [275.053039] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [275.053113] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [275.053187] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [275.053262] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [275.053335] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [275.053631] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A <7> [275.053797] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xa8000000) <7> [275.053898] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [275.053991] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [275.054078] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [275.054165] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [275.054236] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [275.054305] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [275.054384] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [275.054471] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [275.054561] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [275.054648] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [275.054730] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [275.054799] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [275.054863] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [275.054926] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [275.054990] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [275.055053] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [275.055137] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [275.055296] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [275.055359] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [275.055497] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [275.056420] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A] <7> [275.056541] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [275.057679] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [275.057778] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [275.057866] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [275.057982] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [275.058556] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [275.058658] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (468 ms remaining) <7> [275.528692] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [275.579734] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [275.580065] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [275.580337] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [275.616851] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [275.617177] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [275.617452] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [275.617882] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [275.672581] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [275.672665] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [275.672737] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [275.787510] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [275.787876] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [275.788154] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [275.790179] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [275.791656] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [275.792350] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [275.793442] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [275.794821] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [275.795957] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [275.796307] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [275.798960] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [275.799419] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [275.800291] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A <7> [275.800833] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [275.801202] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A <7> [275.801621] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [275.834577] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [275.836128] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [275.836505] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [278.361105] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off <7> [278.361680] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [285.102147] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [285.102572] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [285.102885] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [285.254500] [IGT] kms_flip: finished subtest A-eDP1, FAIL

Detail

Value

Duration

10.61 seconds

Hostname

shard-lnl-7

Igt-Version

IGT-Version: 2.4-gb024a3b67 (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-5137-5390f2273d45bb259-debug+ x86_64)

Out

Using IGT_SRANDOM=1779903817 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2106 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (10.609s)

Err

Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
[268.718257] (kms_flip:7041) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[268.718333] (kms_flip:7041) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
[266.700897] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.812988
last_received_ts = 267.812439
last_seq = 3522
current_ts = 267.829651
current_received_ts = 267.829071
current_seq = 3523
count = 432
seq_step = 1
[266.700965] (kms_flip:7041) DEBUG: Vblank took 61us
[266.717575] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.829651
last_received_ts = 267.829071
last_seq = 3523
current_ts = 267.846313
current_received_ts = 267.845764
current_seq = 3524
count = 433
seq_step = 1
[266.717645] (kms_flip:7041) DEBUG: Vblank took 63us
[266.734217] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.846313
last_received_ts = 267.845764
last_seq = 3524
current_ts = 267.862976
current_received_ts = 267.862396
current_seq = 3525
count = 434
seq_step = 1
[266.734354] (kms_flip:7041) DEBUG: Vblank took 130us
[266.750885] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.862976
last_received_ts = 267.862396
last_seq = 3525
current_ts = 267.879639
current_received_ts = 267.879059
current_seq = 3526
count = 435
seq_step = 1
[266.750955] (kms_flip:7041) DEBUG: Vblank took 62us
[266.767542] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.879639
last_received_ts = 267.879059
last_seq = 3526
current_ts = 267.896301
current_received_ts = 267.895721
current_seq = 3527
count = 436
seq_step = 1
[266.767609] (kms_flip:7041) DEBUG: Vblank took 59us
[266.784208] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.896301
last_received_ts = 267.895721
last_seq = 3527
current_ts = 267.912964
current_received_ts = 267.912384
current_seq = 3528
count = 437
seq_step = 1
[266.784340] (kms_flip:7041) DEBUG: Vblank took 125us
[266.800879] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.912964
last_received_ts = 267.912384
last_seq = 3528
current_ts = 267.929626
current_received_ts = 267.929047
current_seq = 3529
count = 438
seq_step = 1
[266.800949] (kms_flip:7041) DEBUG: Vblank took 62us
[266.817531] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.929626
last_received_ts = 267.929047
last_seq = 3529
current_ts = 267.946289
current_received_ts = 267.945709
current_seq = 3530
count = 439
seq_step = 1
[266.817602] (kms_flip:7041) DEBUG: Vblank took 64us
[266.834210] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.946289
last_received_ts = 267.945709
last_seq = 3530
current_ts = 267.962921
current_received_ts = 267.962372
current_seq = 3531
count = 440
seq_step = 1
[266.834346] (kms_flip:7041) DEBUG: Vblank took 129us
[266.850878] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.962921
last_received_ts = 267.962372
last_seq = 3531
current_ts = 267.979584
current_received_ts = 267.979034
current_seq = 3532
count = 441
seq_step = 1
[266.850946] (kms_flip:7041) DEBUG: Vblank took 60us
[266.867523] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.979584
last_received_ts = 267.979034
last_seq = 3532
current_ts = 267.996246
current_received_ts = 267.995667
current_seq = 3533
count = 442
seq_step = 1
[266.867590] (kms_flip:7041) DEBUG: Vblank took 59us
[266.884224] (kms_flip:7041) DEBUG: name = flip
last_ts = 267.996246
last_received_ts = 267.995667
last_seq = 3533
current_ts = 268.012909
current_received_ts = 268.012360
current_seq = 3534
count = 443
seq_step = 1
[266.884352] (kms_flip:7041) DEBUG: Vblank took 120us
[266.900889] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.012909
last_received_ts = 268.012360
last_seq = 3534
current_ts = 268.029572
current_received_ts = 268.029022
current_seq = 3535
count = 444
seq_step = 1
[266.900959] (kms_flip:7041) DEBUG: Vblank took 62us
[266.917524] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.029572
last_received_ts = 268.029022
last_seq = 3535
current_ts = 268.046234
current_received_ts = 268.045654
current_seq = 3536
count = 445
seq_step = 1
[266.917600] (kms_flip:7041) DEBUG: Vblank took 68us
[266.934209] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.046234
last_received_ts = 268.045654
last_seq = 3536
current_ts = 268.062897
current_received_ts = 268.062347
current_seq = 3537
count = 446
seq_step = 1
[266.934333] (kms_flip:7041) DEBUG: Vblank took 117us
[266.950882] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.062897
last_received_ts = 268.062347
last_seq = 3537
current_ts = 268.079559
current_received_ts = 268.079010
current_seq = 3538
count = 447
seq_step = 1
[266.951009] (kms_flip:7041) DEBUG: Vblank took 118us
[266.967531] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.079559
last_received_ts = 268.079010
last_seq = 3538
current_ts = 268.096222
current_received_ts = 268.095673
current_seq = 3539
count = 448
seq_step = 1
[266.967598] (kms_flip:7041) DEBUG: Vblank took 60us
[266.984193] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.096222
last_received_ts = 268.095673
last_seq = 3539
current_ts = 268.112885
current_received_ts = 268.112335
current_seq = 3540
count = 449
seq_step = 1
[266.984313] (kms_flip:7041) DEBUG: Vblank took 113us
[267.000845] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.112885
last_received_ts = 268.112335
last_seq = 3540
current_ts = 268.129547
current_received_ts = 268.128967
current_seq = 3541
count = 450
seq_step = 1
[267.000941] (kms_flip:7041) DEBUG: Vblank took 87us
[267.017518] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.129547
last_received_ts = 268.128967
last_seq = 3541
current_ts = 268.146210
current_received_ts = 268.145630
current_seq = 3542
count = 451
seq_step = 1
[267.017588] (kms_flip:7041) DEBUG: Vblank took 62us
[267.034157] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.146210
last_received_ts = 268.145630
last_seq = 3542
current_ts = 268.162872
current_received_ts = 268.162292
current_seq = 3543
count = 452
seq_step = 1
[267.034266] (kms_flip:7041) DEBUG: Vblank took 101us
[267.050845] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.162872
last_received_ts = 268.162292
last_seq = 3543
current_ts = 268.179535
current_received_ts = 268.178955
current_seq = 3544
count = 453
seq_step = 1
[267.050944] (kms_flip:7041) DEBUG: Vblank took 91us
[267.067513] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.179535
last_received_ts = 268.178955
last_seq = 3544
current_ts = 268.196198
current_received_ts = 268.195618
current_seq = 3545
count = 454
seq_step = 1
[267.067589] (kms_flip:7041) DEBUG: Vblank took 68us
[267.084162] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.196198
last_received_ts = 268.195618
last_seq = 3545
current_ts = 268.212860
current_received_ts = 268.212280
current_seq = 3546
count = 455
seq_step = 1
[267.084229] (kms_flip:7041) DEBUG: Vblank took 58us
[267.100837] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.212860
last_received_ts = 268.212280
last_seq = 3546
current_ts = 268.229523
current_received_ts = 268.228943
current_seq = 3547
count = 456
seq_step = 1
[267.100928] (kms_flip:7041) DEBUG: Vblank took 83us
[267.117493] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.229523
last_received_ts = 268.228943
last_seq = 3547
current_ts = 268.246155
current_received_ts = 268.245605
current_seq = 3548
count = 457
seq_step = 1
[267.117562] (kms_flip:7041) DEBUG: Vblank took 62us
[267.134167] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.246155
last_received_ts = 268.245605
last_seq = 3548
current_ts = 268.262817
current_received_ts = 268.262268
current_seq = 3549
count = 458
seq_step = 1
[267.134275] (kms_flip:7041) DEBUG: Vblank took 99us
[267.150818] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.262817
last_received_ts = 268.262268
last_seq = 3549
current_ts = 268.279480
current_received_ts = 268.278931
current_seq = 3550
count = 459
seq_step = 1
[267.150919] (kms_flip:7041) DEBUG: Vblank took 92us
[267.167477] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.279480
last_received_ts = 268.278931
last_seq = 3550
current_ts = 268.296143
current_received_ts = 268.295593
current_seq = 3551
count = 460
seq_step = 1
[267.167544] (kms_flip:7041) DEBUG: Vblank took 59us
[267.184080] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.296143
last_received_ts = 268.295593
last_seq = 3551
current_ts = 268.312836
current_received_ts = 268.312164
current_seq = 3552
count = 461
seq_step = 1
[267.184150] (kms_flip:7041) DEBUG: Vblank took 63us
[267.200822] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.312836
last_received_ts = 268.312164
last_seq = 3552
current_ts = 268.329468
current_received_ts = 268.328918
current_seq = 3553
count = 462
seq_step = 1
[267.200924] (kms_flip:7041) DEBUG: Vblank took 94us
[267.217476] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.329468
last_received_ts = 268.328918
last_seq = 3553
current_ts = 268.346130
current_received_ts = 268.345581
current_seq = 3554
count = 463
seq_step = 1
[267.217544] (kms_flip:7041) DEBUG: Vblank took 60us
[267.234143] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.346130
last_received_ts = 268.345581
last_seq = 3554
current_ts = 268.362793
current_received_ts = 268.362244
current_seq = 3555
count = 464
seq_step = 1
[267.234262] (kms_flip:7041) DEBUG: Vblank took 111us
[267.250813] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.362793
last_received_ts = 268.362244
last_seq = 3555
current_ts = 268.379456
current_received_ts = 268.378906
current_seq = 3556
count = 465
seq_step = 1
[267.250883] (kms_flip:7041) DEBUG: Vblank took 63us
[267.267452] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.379456
last_received_ts = 268.378906
last_seq = 3556
current_ts = 268.396118
current_received_ts = 268.395538
current_seq = 3557
count = 466
seq_step = 1
[267.267584] (kms_flip:7041) DEBUG: Vblank took 125us
[267.284111] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.396118
last_received_ts = 268.395538
last_seq = 3557
current_ts = 268.412781
current_received_ts = 268.412201
current_seq = 3558
count = 467
seq_step = 1
[267.284248] (kms_flip:7041) DEBUG: Vblank took 131us
[267.300804] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.412781
last_received_ts = 268.412201
last_seq = 3558
current_ts = 268.429443
current_received_ts = 268.428894
current_seq = 3559
count = 468
seq_step = 1
[267.300874] (kms_flip:7041) DEBUG: Vblank took 62us
[267.317448] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.429443
last_received_ts = 268.428894
last_seq = 3559
current_ts = 268.446106
current_received_ts = 268.445526
current_seq = 3560
count = 469
seq_step = 1
[267.317574] (kms_flip:7041) DEBUG: Vblank took 118us
[267.334102] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.446106
last_received_ts = 268.445526
last_seq = 3560
current_ts = 268.462769
current_received_ts = 268.462189
current_seq = 3561
count = 470
seq_step = 1
[267.334168] (kms_flip:7041) DEBUG: Vblank took 59us
[267.350790] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.462769
last_received_ts = 268.462189
last_seq = 3561
current_ts = 268.479431
current_received_ts = 268.478851
current_seq = 3562
count = 471
seq_step = 1
[267.350860] (kms_flip:7041) DEBUG: Vblank took 62us
[267.367434] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.479431
last_received_ts = 268.478851
last_seq = 3562
current_ts = 268.496094
current_received_ts = 268.495514
current_seq = 3563
count = 472
seq_step = 1
[267.367504] (kms_flip:7041) DEBUG: Vblank took 62us
[267.384099] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.496094
last_received_ts = 268.495514
last_seq = 3563
current_ts = 268.512756
current_received_ts = 268.512146
current_seq = 3564
count = 473
seq_step = 1
[267.384169] (kms_flip:7041) DEBUG: Vblank took 62us
[267.400770] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.512756
last_received_ts = 268.512146
last_seq = 3564
current_ts = 268.529419
current_received_ts = 268.528839
current_seq = 3565
count = 474
seq_step = 1
[267.400837] (kms_flip:7041) DEBUG: Vblank took 60us
[267.417407] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.529419
last_received_ts = 268.528839
last_seq = 3565
current_ts = 268.546082
current_received_ts = 268.545471
current_seq = 3566
count = 475
seq_step = 1
[267.417547] (kms_flip:7041) DEBUG: Vblank took 131us
[267.434118] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.546082
last_received_ts = 268.545471
last_seq = 3566
current_ts = 268.562744
current_received_ts = 268.562164
current_seq = 3567
count = 476
seq_step = 1
[267.434189] (kms_flip:7041) DEBUG: Vblank took 63us
[267.450773] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.562744
last_received_ts = 268.562164
last_seq = 3567
current_ts = 268.579407
current_received_ts = 268.578827
current_seq = 3568
count = 477
seq_step = 1
[267.450934] (kms_flip:7041) DEBUG: Vblank took 117us
[267.467427] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.579407
last_received_ts = 268.578827
last_seq = 3568
current_ts = 268.596069
current_received_ts = 268.595459
current_seq = 3569
count = 478
seq_step = 1
[267.467559] (kms_flip:7041) DEBUG: Vblank took 124us
[267.484111] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.596069
last_received_ts = 268.595459
last_seq = 3569
current_ts = 268.612701
current_received_ts = 268.612152
current_seq = 3570
count = 479
seq_step = 1
[267.484184] (kms_flip:7041) DEBUG: Vblank took 65us
[267.500784] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.612701
last_received_ts = 268.612152
last_seq = 3570
current_ts = 268.629364
current_received_ts = 268.628815
current_seq = 3571
count = 480
seq_step = 1
[267.500854] (kms_flip:7041) DEBUG: Vblank took 62us
[267.517412] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.629364
last_received_ts = 268.628815
last_seq = 3571
current_ts = 268.646027
current_received_ts = 268.645447
current_seq = 3572
count = 481
seq_step = 1
[267.517544] (kms_flip:7041) DEBUG: Vblank took 124us
[267.534099] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.646027
last_received_ts = 268.645447
last_seq = 3572
current_ts = 268.662689
current_received_ts = 268.662140
current_seq = 3573
count = 482
seq_step = 1
[267.534171] (kms_flip:7041) DEBUG: Vblank took 65us
[267.550762] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.662689
last_received_ts = 268.662140
last_seq = 3573
current_ts = 268.679352
current_received_ts = 268.678802
current_seq = 3574
count = 483
seq_step = 1
[267.550831] (kms_flip:7041) DEBUG: Vblank took 62us
[267.567427] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.679352
last_received_ts = 268.678802
last_seq = 3574
current_ts = 268.696014
current_received_ts = 268.695465
current_seq = 3575
count = 484
seq_step = 1
[267.567542] (kms_flip:7041) DEBUG: Vblank took 107us
[267.584093] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.696014
last_received_ts = 268.695465
last_seq = 3575
current_ts = 268.712677
current_received_ts = 268.712128
current_seq = 3576
count = 485
seq_step = 1
[267.584165] (kms_flip:7041) DEBUG: Vblank took 63us
[267.600748] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.712677
last_received_ts = 268.712128
last_seq = 3576
current_ts = 268.729340
current_received_ts = 268.728760
current_seq = 3577
count = 486
seq_step = 1
[267.600824] (kms_flip:7041) DEBUG: Vblank took 68us
[267.617399] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.729340
last_received_ts = 268.728760
last_seq = 3577
current_ts = 268.746002
current_received_ts = 268.745422
current_seq = 3578
count = 487
seq_step = 1
[267.617470] (kms_flip:7041) DEBUG: Vblank took 63us
[267.634075] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.746002
last_received_ts = 268.745422
last_seq = 3578
current_ts = 268.762665
current_received_ts = 268.762085
current_seq = 3579
count = 488
seq_step = 1
[267.634146] (kms_flip:7041) DEBUG: Vblank took 62us
[267.650746] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.762665
last_received_ts = 268.762085
last_seq = 3579
current_ts = 268.779327
current_received_ts = 268.778748
current_seq = 3580
count = 489
seq_step = 1
[267.650816] (kms_flip:7041) DEBUG: Vblank took 62us
[267.667389] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.779327
last_received_ts = 268.778748
last_seq = 3580
current_ts = 268.795990
current_received_ts = 268.795410
current_seq = 3581
count = 490
seq_step = 1
[267.667514] (kms_flip:7041) DEBUG: Vblank took 117us
[267.684077] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.795990
last_received_ts = 268.795410
last_seq = 3581
current_ts = 268.812653
current_received_ts = 268.812073
current_seq = 3582
count = 491
seq_step = 1
[267.684144] (kms_flip:7041) DEBUG: Vblank took 60us
[267.700736] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.812653
last_received_ts = 268.812073
last_seq = 3582
current_ts = 268.829315
current_received_ts = 268.828735
current_seq = 3583
count = 492
seq_step = 1
[267.700806] (kms_flip:7041) DEBUG: Vblank took 63us
[267.717415] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.829315
last_received_ts = 268.828735
last_seq = 3583
current_ts = 268.845978
current_received_ts = 268.845428
current_seq = 3584
count = 493
seq_step = 1
[267.717539] (kms_flip:7041) DEBUG: Vblank took 115us
[267.734079] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.845978
last_received_ts = 268.845428
last_seq = 3584
current_ts = 268.862640
current_received_ts = 268.862061
current_seq = 3585
count = 494
seq_step = 1
[267.734152] (kms_flip:7041) DEBUG: Vblank took 64us
[267.750739] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.862640
last_received_ts = 268.862061
last_seq = 3585
current_ts = 268.879303
current_received_ts = 268.878723
current_seq = 3586
count = 495
seq_step = 1
[267.750809] (kms_flip:7041) DEBUG: Vblank took 60us
[267.767373] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.879303
last_received_ts = 268.878723
last_seq = 3586
current_ts = 268.895935
current_received_ts = 268.895355
current_seq = 3587
count = 496
seq_step = 1
[267.767492] (kms_flip:7041) DEBUG: Vblank took 112us
[267.784071] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.895935
last_received_ts = 268.895355
last_seq = 3587
current_ts = 268.912598
current_received_ts = 268.912048
current_seq = 3588
count = 497
seq_step = 1
[267.784144] (kms_flip:7041) DEBUG: Vblank took 65us
[267.800715] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.912598
last_received_ts = 268.912048
last_seq = 3588
current_ts = 268.929260
current_received_ts = 268.928711
current_seq = 3589
count = 498
seq_step = 1
[267.800785] (kms_flip:7041) DEBUG: Vblank took 62us
[267.817389] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.929260
last_received_ts = 268.928711
last_seq = 3589
current_ts = 268.945923
current_received_ts = 268.945374
current_seq = 3590
count = 499
seq_step = 1
[267.817532] (kms_flip:7041) DEBUG: Vblank took 135us
[267.834075] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.945923
last_received_ts = 268.945374
last_seq = 3590
current_ts = 268.962585
current_received_ts = 268.962067
current_seq = 3591
count = 500
seq_step = 1
[267.834145] (kms_flip:7041) DEBUG: Vblank took 63us
[267.850713] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.962585
last_received_ts = 268.962067
last_seq = 3591
current_ts = 268.979248
current_received_ts = 268.978699
current_seq = 3592
count = 501
seq_step = 1
[267.850785] (kms_flip:7041) DEBUG: Vblank took 63us
[267.867350] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.979248
last_received_ts = 268.978699
last_seq = 3592
current_ts = 268.995911
current_received_ts = 268.995331
current_seq = 3593
count = 502
seq_step = 1
[267.867490] (kms_flip:7041) DEBUG: Vblank took 132us
[267.884068] (kms_flip:7041) DEBUG: name = flip
last_ts = 268.995911
last_received_ts = 268.995331
last_seq = 3593
current_ts = 269.012573
current_received_ts = 269.012024
current_seq = 3594
count = 503
seq_step = 1
[267.884139] (kms_flip:7041) DEBUG: Vblank took 63us
[267.900706] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.012573
last_received_ts = 269.012024
last_seq = 3594
current_ts = 269.029236
current_received_ts = 269.028687
current_seq = 3595
count = 504
seq_step = 1
[267.900844] (kms_flip:7041) DEBUG: Vblank took 131us
[267.917349] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.029236
last_received_ts = 269.028687
last_seq = 3595
current_ts = 269.045898
current_received_ts = 269.045319
current_seq = 3596
count = 505
seq_step = 1
[267.917419] (kms_flip:7041) DEBUG: Vblank took 62us
[267.934086] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.045898
last_received_ts = 269.045319
last_seq = 3596
current_ts = 269.062561
current_received_ts = 269.062042
current_seq = 3597
count = 506
seq_step = 1
[267.934224] (kms_flip:7041) DEBUG: Vblank took 130us
[267.950703] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.062561
last_received_ts = 269.062042
last_seq = 3597
current_ts = 269.079224
current_received_ts = 269.078674
current_seq = 3598
count = 507
seq_step = 1
[267.950769] (kms_flip:7041) DEBUG: Vblank took 59us
[267.967393] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.079224
last_received_ts = 269.078674
last_seq = 3598
current_ts = 269.095886
current_received_ts = 269.095337
current_seq = 3599
count = 508
seq_step = 1
[267.967536] (kms_flip:7041) DEBUG: Vblank took 135us
[267.984023] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.095886
last_received_ts = 269.095337
last_seq = 3599
current_ts = 269.112549
current_received_ts = 269.111969
current_seq = 3600
count = 509
seq_step = 1
[267.984117] (kms_flip:7041) DEBUG: Vblank took 84us
[268.000693] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.112549
last_received_ts = 269.111969
last_seq = 3600
current_ts = 269.129211
current_received_ts = 269.128632
current_seq = 3601
count = 510
seq_step = 1
[268.000822] (kms_flip:7041) DEBUG: Vblank took 122us
[268.017331] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.129211
last_received_ts = 269.128632
last_seq = 3601
current_ts = 269.145874
current_received_ts = 269.145264
current_seq = 3602
count = 511
seq_step = 1
[268.017427] (kms_flip:7041) DEBUG: Vblank took 89us
[268.034004] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.145874
last_received_ts = 269.145264
last_seq = 3602
current_ts = 269.162537
current_received_ts = 269.161957
current_seq = 3603
count = 512
seq_step = 1
[268.034090] (kms_flip:7041) DEBUG: Vblank took 79us
[268.050669] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.162537
last_received_ts = 269.161957
last_seq = 3603
current_ts = 269.179199
current_received_ts = 269.178619
current_seq = 3604
count = 513
seq_step = 1
[268.050740] (kms_flip:7041) DEBUG: Vblank took 62us
[268.067322] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.179199
last_received_ts = 269.178619
last_seq = 3604
current_ts = 269.195862
current_received_ts = 269.195251
current_seq = 3605
count = 514
seq_step = 1
[268.067436] (kms_flip:7041) DEBUG: Vblank took 106us
[268.084015] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.195862
last_received_ts = 269.195251
last_seq = 3605
current_ts = 269.212524
current_received_ts = 269.211945
current_seq = 3606
count = 515
seq_step = 1
[268.084107] (kms_flip:7041) DEBUG: Vblank took 84us
[268.100653] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.212524
last_received_ts = 269.211945
last_seq = 3606
current_ts = 269.229156
current_received_ts = 269.228577
current_seq = 3607
count = 516
seq_step = 1
[268.100720] (kms_flip:7041) DEBUG: Vblank took 59us
[268.117309] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.229156
last_received_ts = 269.228577
last_seq = 3607
current_ts = 269.245819
current_received_ts = 269.245239
current_seq = 3608
count = 517
seq_step = 1
[268.117439] (kms_flip:7041) DEBUG: Vblank took 122us
[268.134014] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.245819
last_received_ts = 269.245239
last_seq = 3608
current_ts = 269.262482
current_received_ts = 269.261932
current_seq = 3609
count = 518
seq_step = 1
[268.134111] (kms_flip:7041) DEBUG: Vblank took 88us
[268.150638] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.262482
last_received_ts = 269.261932
last_seq = 3609
current_ts = 269.279144
current_received_ts = 269.278564
current_seq = 3610
count = 519
seq_step = 1
[268.150701] (kms_flip:7041) DEBUG: Vblank took 52us
[268.167343] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.279144
last_received_ts = 269.278564
last_seq = 3610
current_ts = 269.295807
current_received_ts = 269.295258
current_seq = 3611
count = 520
seq_step = 1
[268.167451] (kms_flip:7041) DEBUG: Vblank took 101us
[268.183994] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.295807
last_received_ts = 269.295258
last_seq = 3611
current_ts = 269.312469
current_received_ts = 269.311920
current_seq = 3612
count = 521
seq_step = 1
[268.184064] (kms_flip:7041) DEBUG: Vblank took 62us
[268.200655] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.312469
last_received_ts = 269.311920
last_seq = 3612
current_ts = 269.329132
current_received_ts = 269.328583
current_seq = 3613
count = 522
seq_step = 1
[268.200722] (kms_flip:7041) DEBUG: Vblank took 60us
[268.217326] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.329132
last_received_ts = 269.328583
last_seq = 3613
current_ts = 269.345795
current_received_ts = 269.345245
current_seq = 3614
count = 523
seq_step = 1
[268.217442] (kms_flip:7041) DEBUG: Vblank took 109us
[268.233975] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.345795
last_received_ts = 269.345245
last_seq = 3614
current_ts = 269.362457
current_received_ts = 269.361877
current_seq = 3615
count = 524
seq_step = 1
[268.234042] (kms_flip:7041) DEBUG: Vblank took 59us
[268.250633] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.362457
last_received_ts = 269.361877
last_seq = 3615
current_ts = 269.379120
current_received_ts = 269.378540
current_seq = 3616
count = 525
seq_step = 1
[268.250700] (kms_flip:7041) DEBUG: Vblank took 59us
[268.267298] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.379120
last_received_ts = 269.378540
last_seq = 3616
current_ts = 269.395782
current_received_ts = 269.395203
current_seq = 3617
count = 526
seq_step = 1
[268.267441] (kms_flip:7041) DEBUG: Vblank took 135us
[268.283971] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.395782
last_received_ts = 269.395203
last_seq = 3617
current_ts = 269.412445
current_received_ts = 269.411865
current_seq = 3618
count = 527
seq_step = 1
[268.284041] (kms_flip:7041) DEBUG: Vblank took 62us
[268.300614] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.412445
last_received_ts = 269.411865
last_seq = 3618
current_ts = 269.429108
current_received_ts = 269.428497
current_seq = 3619
count = 528
seq_step = 1
[268.300752] (kms_flip:7041) DEBUG: Vblank took 130us
[268.317301] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.429108
last_received_ts = 269.428497
last_seq = 3619
current_ts = 269.445770
current_received_ts = 269.445190
current_seq = 3620
count = 529
seq_step = 1
[268.317444] (kms_flip:7041) DEBUG: Vblank took 135us
[268.333966] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.445770
last_received_ts = 269.445190
last_seq = 3620
current_ts = 269.462433
current_received_ts = 269.461853
current_seq = 3621
count = 530
seq_step = 1
[268.334036] (kms_flip:7041) DEBUG: Vblank took 61us
[268.350610] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.462433
last_received_ts = 269.461853
last_seq = 3621
current_ts = 269.479095
current_received_ts = 269.478485
current_seq = 3622
count = 531
seq_step = 1
[268.350745] (kms_flip:7041) DEBUG: Vblank took 127us
[268.367303] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.479095
last_received_ts = 269.478485
last_seq = 3622
current_ts = 269.495758
current_received_ts = 269.495178
current_seq = 3623
count = 532
seq_step = 1
[268.367374] (kms_flip:7041) DEBUG: Vblank took 63us
[268.383962] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.495758
last_received_ts = 269.495178
last_seq = 3623
current_ts = 269.512421
current_received_ts = 269.511841
current_seq = 3624
count = 533
seq_step = 1
[268.384038] (kms_flip:7041) DEBUG: Vblank took 68us
[268.400608] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.512421
last_received_ts = 269.511841
last_seq = 3624
current_ts = 269.529053
current_received_ts = 269.528473
current_seq = 3625
count = 534
seq_step = 1
[268.400742] (kms_flip:7041) DEBUG: Vblank took 126us
[268.417299] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.529053
last_received_ts = 269.528473
last_seq = 3625
current_ts = 269.545746
current_received_ts = 269.545166
current_seq = 3626
count = 535
seq_step = 1
[268.417366] (kms_flip:7041) DEBUG: Vblank took 59us
[268.433935] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.545746
last_received_ts = 269.545166
last_seq = 3626
current_ts = 269.562378
current_received_ts = 269.561798
current_seq = 3627
count = 536
seq_step = 1
[268.434009] (kms_flip:7041) DEBUG: Vblank took 65us
[268.450603] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.562378
last_received_ts = 269.561798
last_seq = 3627
current_ts = 269.579041
current_received_ts = 269.578461
current_seq = 3628
count = 537
seq_step = 1
[268.450731] (kms_flip:7041) DEBUG: Vblank took 121us
[268.467281] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.579041
last_received_ts = 269.578461
last_seq = 3628
current_ts = 269.595703
current_received_ts = 269.595154
current_seq = 3629
count = 538
seq_step = 1
[268.467347] (kms_flip:7041) DEBUG: Vblank took 59us
[268.483948] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.595703
last_received_ts = 269.595154
last_seq = 3629
current_ts = 269.612366
current_received_ts = 269.611816
current_seq = 3630
count = 539
seq_step = 1
[268.484018] (kms_flip:7041) DEBUG: Vblank took 62us
[268.500586] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.612366
last_received_ts = 269.611816
last_seq = 3630
current_ts = 269.629028
current_received_ts = 269.628448
current_seq = 3631
count = 540
seq_step = 1
[268.500714] (kms_flip:7041) DEBUG: Vblank took 121us
[268.517283] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.629028
last_received_ts = 269.628448
last_seq = 3631
current_ts = 269.645691
current_received_ts = 269.645142
current_seq = 3632
count = 541
seq_step = 1
[268.517350] (kms_flip:7041) DEBUG: Vblank took 60us
[268.533946] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.645691
last_received_ts = 269.645142
last_seq = 3632
current_ts = 269.662354
current_received_ts = 269.661804
current_seq = 3633
count = 542
seq_step = 1
[268.534016] (kms_flip:7041) DEBUG: Vblank took 62us
[268.550594] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.662354
last_received_ts = 269.661804
last_seq = 3633
current_ts = 269.679016
current_received_ts = 269.678436
current_seq = 3634
count = 543
seq_step = 1
[268.550720] (kms_flip:7041) DEBUG: Vblank took 118us
[268.567275] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.679016
last_received_ts = 269.678436
last_seq = 3634
current_ts = 269.695679
current_received_ts = 269.695129
current_seq = 3635
count = 544
seq_step = 1
[268.567347] (kms_flip:7041) DEBUG: Vblank took 64us
[268.583933] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.695679
last_received_ts = 269.695129
last_seq = 3635
current_ts = 269.712341
current_received_ts = 269.711761
current_seq = 3636
count = 545
seq_step = 1
[268.584000] (kms_flip:7041) DEBUG: Vblank took 59us
[268.600593] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.712341
last_received_ts = 269.711761
last_seq = 3636
current_ts = 269.729004
current_received_ts = 269.728424
current_seq = 3637
count = 546
seq_step = 1
[268.600731] (kms_flip:7041) DEBUG: Vblank took 130us
[268.617251] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.729004
last_received_ts = 269.728424
last_seq = 3637
current_ts = 269.745667
current_received_ts = 269.745087
current_seq = 3638
count = 547
seq_step = 1
[268.617317] (kms_flip:7041) DEBUG: Vblank took 59us
[268.633925] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.745667
last_received_ts = 269.745087
last_seq = 3638
current_ts = 269.762329
current_received_ts = 269.761749
current_seq = 3639
count = 548
seq_step = 1
[268.634055] (kms_flip:7041) DEBUG: Vblank took 122us
[268.650577] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.762329
last_received_ts = 269.761749
last_seq = 3639
current_ts = 269.778992
current_received_ts = 269.778412
current_seq = 3640
count = 549
seq_step = 1
[268.650698] (kms_flip:7041) DEBUG: Vblank took 113us
[268.667248] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.778992
last_received_ts = 269.778412
last_seq = 3640
current_ts = 269.795624
current_received_ts = 269.795074
current_seq = 3641
count = 550
seq_step = 1
[268.667316] (kms_flip:7041) DEBUG: Vblank took 59us
[268.683911] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.795624
last_received_ts = 269.795074
last_seq = 3641
current_ts = 269.812317
current_received_ts = 269.811737
current_seq = 3642
count = 551
seq_step = 1
[268.683982] (kms_flip:7041) DEBUG: Vblank took 62us
[268.700567] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.812317
last_received_ts = 269.811737
last_seq = 3642
current_ts = 269.828949
current_received_ts = 269.828400
current_seq = 3643
count = 552
seq_step = 1
[268.700705] (kms_flip:7041) DEBUG: Vblank took 130us
[268.717227] (kms_flip:7041) DEBUG: name = flip
last_ts = 269.828949
last_received_ts = 269.828400
last_seq = 3643
current_ts = 269.845612
current_received_ts = 269.845032
current_seq = 3644
count = 553
seq_step = 1
[268.718253] (kms_flip:7041) DEBUG: Vblank took 1018us
[268.718257] (kms_flip:7041) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[268.718333] (kms_flip:7041) CRITICAL: Failed assertion: end - start < 500
[268.739174] (kms_flip:7041) igt_core-INFO: Stack trace:
[268.749971] (kms_flip:7041) igt_core-INFO:   #0 ../lib/igt_core.c:2106 __igt_fail_assert()
[268.751241] (kms_flip:7041) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[268.751327] (kms_flip:7041) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[268.751365] (kms_flip:7041) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
[268.751406] (kms_flip:7041) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[268.755252] (kms_flip:7041) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[268.756091] (kms_flip:7041) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[268.756804] (kms_flip:7041) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (10.609s)

Dmesg

<6> [274.631513] Console: switching to colour dummy device 80x25

<6> [274.631827] [IGT] kms_flip: executing

<7> [274.638062] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

<7> [274.638072] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1]

<7> [274.638225] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [274.638335] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

<7> [274.638630] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2]

<7> [274.638634] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2]

<7> [274.638765] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [274.638852] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

<7> [274.639053] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3]

<7> [274.639056] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3]

<7> [274.639167] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [274.639251] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

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

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

<7> [274.640033] xe 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [xe]] DSC DPCD: 00 11 00 76 0b 01 01 80 00 01 06 66 08 00 00 00

<7> [274.640351] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000

<7> [274.640465] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000

<7> [274.640576] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000

<7> [274.640700] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Supported Monitor Refresh rate range is 40 Hz - 120 Hz

<5> [274.640704] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [274.640706] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [274.640707] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00

<7> [274.640709] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc.

<5> [274.640710] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [274.640712] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor

<5> [274.640714] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [274.640715] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0

<5> [274.640717] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [274.640728] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes

<7> [274.640821] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps

<7> [274.640912] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no

<5> [274.641225] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [274.641227] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [274.641229] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [274.641289] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes:

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

<7> [274.641298] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 120 695310 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa

<7> [274.641311] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

<7> [274.642168] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1]

<7> [274.642310] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

<7> [274.642333] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2]

<7> [274.642336] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2]

<7> [274.642479] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

<7> [274.642489] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3]

<7> [274.642492] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3]

<7> [274.642628] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

<6> [274.643228] [IGT] kms_flip: starting subtest flip-vs-expired-vblank

<6> [274.644854] [IGT] kms_flip: starting dynamic subtest A-eDP1

<7> [274.645512] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431]

<7> [274.646038] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [274.735994] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 24, 313, 313, 313, 313, 313, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [274.736131] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 28, 346, 346, 346, 346, 346, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [275.038040] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [275.047453] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0

<7> [275.047550] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0

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

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

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

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

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

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

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

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

<7> [275.048373] 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> [275.048472] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

<7> [275.048768] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [275.050255] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0

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

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

<7> [275.050536] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [275.053631] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A

<7> [275.053797] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xa8000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [275.056420] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [275.672581] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

<7> [275.672665] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

<7> [275.672737] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

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

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

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

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

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

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

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

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

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

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

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

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

<7> [275.800291] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A

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

<7> [275.801202] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A

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

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

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

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

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

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

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

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

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

<6> [285.254500] [IGT] kms_flip: finished subtest A-eDP1, FAIL

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