igt@kms_flip@flip-vs-expired-vblank@b-edp1 on shard-lnl@xe-4359-440d2cb5f3dfa9cbbfda4cc18a5ad8541bb1d07e Test details

Detail	Value
Duration	10.52 seconds
Hostname	shard-lnl-2
Igt-Version	IGT-Version: 2.3-g6f7cf72fa (x86_64) (Linux: 6.19.0-rc4-lgci-xe-xe-4359-440d2cb5f3dfa9cbb+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1889 run_test() #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045() #4 ../tests/kms_flip.c:2045 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (10.523s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:3693) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:3693) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:3693) DEBUG: name = flip last_ts = 158.305710 last_received_ts = 158.305176 last_seq = 429 current_ts = 158.322372 current_received_ts = 158.321854 current_seq = 430 count = 426 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.322372 last_received_ts = 158.321854 last_seq = 430 current_ts = 158.339035 current_received_ts = 158.338501 current_seq = 431 count = 427 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 101us (kms_flip:3693) DEBUG: name = flip last_ts = 158.339035 last_received_ts = 158.338501 last_seq = 431 current_ts = 158.355698 current_received_ts = 158.355164 current_seq = 432 count = 428 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 158.355698 last_received_ts = 158.355164 last_seq = 432 current_ts = 158.372360 current_received_ts = 158.371857 current_seq = 433 count = 429 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.372360 last_received_ts = 158.371857 last_seq = 433 current_ts = 158.389023 current_received_ts = 158.388458 current_seq = 434 count = 430 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 96us (kms_flip:3693) DEBUG: name = flip last_ts = 158.389023 last_received_ts = 158.388458 last_seq = 434 current_ts = 158.405685 current_received_ts = 158.405167 current_seq = 435 count = 431 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.405685 last_received_ts = 158.405167 last_seq = 435 current_ts = 158.422363 current_received_ts = 158.421814 current_seq = 436 count = 432 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 88us (kms_flip:3693) DEBUG: name = flip last_ts = 158.422363 last_received_ts = 158.421814 last_seq = 436 current_ts = 158.439026 current_received_ts = 158.438431 current_seq = 437 count = 433 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 158.439026 last_received_ts = 158.438431 last_seq = 437 current_ts = 158.455688 current_received_ts = 158.455154 current_seq = 438 count = 434 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 158.455688 last_received_ts = 158.455154 last_seq = 438 current_ts = 158.472351 current_received_ts = 158.471802 current_seq = 439 count = 435 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.472351 last_received_ts = 158.471802 last_seq = 439 current_ts = 158.489014 current_received_ts = 158.488419 current_seq = 440 count = 436 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 158.489014 last_received_ts = 158.488419 last_seq = 440 current_ts = 158.505676 current_received_ts = 158.505157 current_seq = 441 count = 437 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 158.505676 last_received_ts = 158.505157 last_seq = 441 current_ts = 158.522339 current_received_ts = 158.521820 current_seq = 442 count = 438 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 97us (kms_flip:3693) DEBUG: name = flip last_ts = 158.522339 last_received_ts = 158.521820 last_seq = 442 current_ts = 158.539001 current_received_ts = 158.538467 current_seq = 443 count = 439 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 167us (kms_flip:3693) DEBUG: name = flip last_ts = 158.539001 last_received_ts = 158.538467 last_seq = 443 current_ts = 158.555679 current_received_ts = 158.555130 current_seq = 444 count = 440 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 100us (kms_flip:3693) DEBUG: name = flip last_ts = 158.555679 last_received_ts = 158.555130 last_seq = 444 current_ts = 158.572342 current_received_ts = 158.571793 current_seq = 445 count = 441 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.572342 last_received_ts = 158.571793 last_seq = 445 current_ts = 158.589005 current_received_ts = 158.588470 current_seq = 446 count = 442 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 161us (kms_flip:3693) DEBUG: name = flip last_ts = 158.589005 last_received_ts = 158.588470 last_seq = 446 current_ts = 158.605667 current_received_ts = 158.605148 current_seq = 447 count = 443 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 100us (kms_flip:3693) DEBUG: name = flip last_ts = 158.605667 last_received_ts = 158.605148 last_seq = 447 current_ts = 158.622330 current_received_ts = 158.621796 current_seq = 448 count = 444 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 101us (kms_flip:3693) DEBUG: name = flip last_ts = 158.622330 last_received_ts = 158.621796 last_seq = 448 current_ts = 158.638992 current_received_ts = 158.638443 current_seq = 449 count = 445 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 158.638992 last_received_ts = 158.638443 last_seq = 449 current_ts = 158.655655 current_received_ts = 158.655121 current_seq = 450 count = 446 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.655655 last_received_ts = 158.655121 last_seq = 450 current_ts = 158.672318 current_received_ts = 158.671783 current_seq = 451 count = 447 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 158.672318 last_received_ts = 158.671783 last_seq = 451 current_ts = 158.688980 current_received_ts = 158.688416 current_seq = 452 count = 448 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 91us (kms_flip:3693) DEBUG: name = flip last_ts = 158.688980 last_received_ts = 158.688416 last_seq = 452 current_ts = 158.705643 current_received_ts = 158.705124 current_seq = 453 count = 449 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 158.705643 last_received_ts = 158.705124 last_seq = 453 current_ts = 158.722321 current_received_ts = 158.721771 current_seq = 454 count = 450 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.722321 last_received_ts = 158.721771 last_seq = 454 current_ts = 158.738968 current_received_ts = 158.738388 current_seq = 455 count = 451 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 158.738968 last_received_ts = 158.738388 last_seq = 455 current_ts = 158.755646 current_received_ts = 158.755112 current_seq = 456 count = 452 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.755646 last_received_ts = 158.755112 last_seq = 456 current_ts = 158.772308 current_received_ts = 158.771759 current_seq = 457 count = 453 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.772308 last_received_ts = 158.771759 last_seq = 457 current_ts = 158.788956 current_received_ts = 158.788406 current_seq = 458 count = 454 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 101us (kms_flip:3693) DEBUG: name = flip last_ts = 158.788956 last_received_ts = 158.788406 last_seq = 458 current_ts = 158.805634 current_received_ts = 158.805115 current_seq = 459 count = 455 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 158.805634 last_received_ts = 158.805115 last_seq = 459 current_ts = 158.822296 current_received_ts = 158.821747 current_seq = 460 count = 456 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 158.822296 last_received_ts = 158.821747 last_seq = 460 current_ts = 158.838959 current_received_ts = 158.838364 current_seq = 461 count = 457 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.838959 last_received_ts = 158.838364 last_seq = 461 current_ts = 158.855621 current_received_ts = 158.855103 current_seq = 462 count = 458 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.855621 last_received_ts = 158.855103 last_seq = 462 current_ts = 158.872284 current_received_ts = 158.871735 current_seq = 463 count = 459 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 158.872284 last_received_ts = 158.871735 last_seq = 463 current_ts = 158.888947 current_received_ts = 158.888351 current_seq = 464 count = 460 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.888947 last_received_ts = 158.888351 last_seq = 464 current_ts = 158.905609 current_received_ts = 158.905075 current_seq = 465 count = 461 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 92us (kms_flip:3693) DEBUG: name = flip last_ts = 158.905609 last_received_ts = 158.905075 last_seq = 465 current_ts = 158.922287 current_received_ts = 158.921738 current_seq = 466 count = 462 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 158.922287 last_received_ts = 158.921738 last_seq = 466 current_ts = 158.938950 current_received_ts = 158.938339 current_seq = 467 count = 463 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 158.938950 last_received_ts = 158.938339 last_seq = 467 current_ts = 158.955612 current_received_ts = 158.955093 current_seq = 468 count = 464 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 86us (kms_flip:3693) DEBUG: name = flip last_ts = 158.955612 last_received_ts = 158.955093 last_seq = 468 current_ts = 158.972275 current_received_ts = 158.971710 current_seq = 469 count = 465 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 158.972275 last_received_ts = 158.971710 last_seq = 469 current_ts = 158.988937 current_received_ts = 158.988388 current_seq = 470 count = 466 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 163us (kms_flip:3693) DEBUG: name = flip last_ts = 158.988937 last_received_ts = 158.988388 last_seq = 470 current_ts = 159.005600 current_received_ts = 159.005066 current_seq = 471 count = 467 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 100us (kms_flip:3693) DEBUG: name = flip last_ts = 159.005600 last_received_ts = 159.005066 last_seq = 471 current_ts = 159.022263 current_received_ts = 159.021744 current_seq = 472 count = 468 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 100us (kms_flip:3693) DEBUG: name = flip last_ts = 159.022263 last_received_ts = 159.021744 last_seq = 472 current_ts = 159.038925 current_received_ts = 159.038330 current_seq = 473 count = 469 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.038925 last_received_ts = 159.038330 last_seq = 473 current_ts = 159.055588 current_received_ts = 159.055069 current_seq = 474 count = 470 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 97us (kms_flip:3693) DEBUG: name = flip last_ts = 159.055588 last_received_ts = 159.055069 last_seq = 474 current_ts = 159.072266 current_received_ts = 159.071716 current_seq = 475 count = 471 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 159.072266 last_received_ts = 159.071716 last_seq = 475 current_ts = 159.088913 current_received_ts = 159.088318 current_seq = 476 count = 472 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 92us (kms_flip:3693) DEBUG: name = flip last_ts = 159.088913 last_received_ts = 159.088318 last_seq = 476 current_ts = 159.105576 current_received_ts = 159.105057 current_seq = 477 count = 473 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 96us (kms_flip:3693) DEBUG: name = flip last_ts = 159.105576 last_received_ts = 159.105057 last_seq = 477 current_ts = 159.122238 current_received_ts = 159.121719 current_seq = 478 count = 474 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 159.122238 last_received_ts = 159.121719 last_seq = 478 current_ts = 159.138916 current_received_ts = 159.138367 current_seq = 479 count = 475 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 159.138916 last_received_ts = 159.138367 last_seq = 479 current_ts = 159.155579 current_received_ts = 159.155060 current_seq = 480 count = 476 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 159.155579 last_received_ts = 159.155060 last_seq = 480 current_ts = 159.172241 current_received_ts = 159.171600 current_seq = 481 count = 477 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.172241 last_received_ts = 159.171600 last_seq = 481 current_ts = 159.188904 current_received_ts = 159.188354 current_seq = 482 count = 478 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 100us (kms_flip:3693) DEBUG: name = flip last_ts = 159.188904 last_received_ts = 159.188354 last_seq = 482 current_ts = 159.205566 current_received_ts = 159.205048 current_seq = 483 count = 479 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 159.205566 last_received_ts = 159.205048 last_seq = 483 current_ts = 159.222229 current_received_ts = 159.221588 current_seq = 484 count = 480 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 159.222229 last_received_ts = 159.221588 last_seq = 484 current_ts = 159.238892 current_received_ts = 159.238373 current_seq = 485 count = 481 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 159.238892 last_received_ts = 159.238373 last_seq = 485 current_ts = 159.255554 current_received_ts = 159.255035 current_seq = 486 count = 482 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 159.255554 last_received_ts = 159.255035 last_seq = 486 current_ts = 159.272217 current_received_ts = 159.271683 current_seq = 487 count = 483 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.272217 last_received_ts = 159.271683 last_seq = 487 current_ts = 159.288879 current_received_ts = 159.288300 current_seq = 488 count = 484 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 96us (kms_flip:3693) DEBUG: name = flip last_ts = 159.288879 last_received_ts = 159.288300 last_seq = 488 current_ts = 159.305557 current_received_ts = 159.305038 current_seq = 489 count = 485 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 97us (kms_flip:3693) DEBUG: name = flip last_ts = 159.305557 last_received_ts = 159.305038 last_seq = 489 current_ts = 159.322220 current_received_ts = 159.321701 current_seq = 490 count = 486 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 92us (kms_flip:3693) DEBUG: name = flip last_ts = 159.322220 last_received_ts = 159.321701 last_seq = 490 current_ts = 159.338882 current_received_ts = 159.338333 current_seq = 491 count = 487 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 86us (kms_flip:3693) DEBUG: name = flip last_ts = 159.338882 last_received_ts = 159.338333 last_seq = 491 current_ts = 159.355545 current_received_ts = 159.355042 current_seq = 492 count = 488 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 159.355545 last_received_ts = 159.355042 last_seq = 492 current_ts = 159.372208 current_received_ts = 159.371536 current_seq = 493 count = 489 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 94us (kms_flip:3693) DEBUG: name = flip last_ts = 159.372208 last_received_ts = 159.371536 last_seq = 493 current_ts = 159.388870 current_received_ts = 159.388336 current_seq = 494 count = 490 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 96us (kms_flip:3693) DEBUG: name = flip last_ts = 159.388870 last_received_ts = 159.388336 last_seq = 494 current_ts = 159.405533 current_received_ts = 159.405045 current_seq = 495 count = 491 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 159.405533 last_received_ts = 159.405045 last_seq = 495 current_ts = 159.422195 current_received_ts = 159.421661 current_seq = 496 count = 492 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 95us (kms_flip:3693) DEBUG: name = flip last_ts = 159.422195 last_received_ts = 159.421661 last_seq = 496 current_ts = 159.438858 current_received_ts = 159.438278 current_seq = 497 count = 493 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.438858 last_received_ts = 159.438278 last_seq = 497 current_ts = 159.455521 current_received_ts = 159.454971 current_seq = 498 count = 494 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 131us (kms_flip:3693) DEBUG: name = flip last_ts = 159.455521 last_received_ts = 159.454971 last_seq = 498 current_ts = 159.472198 current_received_ts = 159.471649 current_seq = 499 count = 495 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 159.472198 last_received_ts = 159.471649 last_seq = 499 current_ts = 159.488846 current_received_ts = 159.488205 current_seq = 500 count = 496 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 117us (kms_flip:3693) DEBUG: name = flip last_ts = 159.488846 last_received_ts = 159.488205 last_seq = 500 current_ts = 159.505524 current_received_ts = 159.504974 current_seq = 501 count = 497 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 100us (kms_flip:3693) DEBUG: name = flip last_ts = 159.505524 last_received_ts = 159.504974 last_seq = 501 current_ts = 159.522186 current_received_ts = 159.521667 current_seq = 502 count = 498 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.522186 last_received_ts = 159.521667 last_seq = 502 current_ts = 159.538849 current_received_ts = 159.538223 current_seq = 503 count = 499 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 100us (kms_flip:3693) DEBUG: name = flip last_ts = 159.538849 last_received_ts = 159.538223 last_seq = 503 current_ts = 159.555511 current_received_ts = 159.554977 current_seq = 504 count = 500 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 86us (kms_flip:3693) DEBUG: name = flip last_ts = 159.555511 last_received_ts = 159.554977 last_seq = 504 current_ts = 159.572174 current_received_ts = 159.571625 current_seq = 505 count = 501 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 159.572174 last_received_ts = 159.571625 last_seq = 505 current_ts = 159.588837 current_received_ts = 159.588303 current_seq = 506 count = 502 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 143us (kms_flip:3693) DEBUG: name = flip last_ts = 159.588837 last_received_ts = 159.588303 last_seq = 506 current_ts = 159.605499 current_received_ts = 159.604980 current_seq = 507 count = 503 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 92us (kms_flip:3693) DEBUG: name = flip last_ts = 159.605499 last_received_ts = 159.604980 last_seq = 507 current_ts = 159.622162 current_received_ts = 159.621536 current_seq = 508 count = 504 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.622162 last_received_ts = 159.621536 last_seq = 508 current_ts = 159.638824 current_received_ts = 159.638199 current_seq = 509 count = 505 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.638824 last_received_ts = 159.638199 last_seq = 509 current_ts = 159.655487 current_received_ts = 159.654953 current_seq = 510 count = 506 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 127us (kms_flip:3693) DEBUG: name = flip last_ts = 159.655487 last_received_ts = 159.654953 last_seq = 510 current_ts = 159.672165 current_received_ts = 159.671600 current_seq = 511 count = 507 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 86us (kms_flip:3693) DEBUG: name = flip last_ts = 159.672165 last_received_ts = 159.671600 last_seq = 511 current_ts = 159.688828 current_received_ts = 159.688187 current_seq = 512 count = 508 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 100us (kms_flip:3693) DEBUG: name = flip last_ts = 159.688828 last_received_ts = 159.688187 last_seq = 512 current_ts = 159.705490 current_received_ts = 159.704956 current_seq = 513 count = 509 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 109us (kms_flip:3693) DEBUG: name = flip last_ts = 159.705490 last_received_ts = 159.704956 last_seq = 513 current_ts = 159.722153 current_received_ts = 159.721512 current_seq = 514 count = 510 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 86us (kms_flip:3693) DEBUG: name = flip last_ts = 159.722153 last_received_ts = 159.721512 last_seq = 514 current_ts = 159.738815 current_received_ts = 159.738174 current_seq = 515 count = 511 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 87us (kms_flip:3693) DEBUG: name = flip last_ts = 159.738815 last_received_ts = 159.738174 last_seq = 515 current_ts = 159.755478 current_received_ts = 159.754929 current_seq = 516 count = 512 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 143us (kms_flip:3693) DEBUG: name = flip last_ts = 159.755478 last_received_ts = 159.754929 last_seq = 516 current_ts = 159.772141 current_received_ts = 159.771591 current_seq = 517 count = 513 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.772141 last_received_ts = 159.771591 last_seq = 517 current_ts = 159.788803 current_received_ts = 159.788254 current_seq = 518 count = 514 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 181us (kms_flip:3693) DEBUG: name = flip last_ts = 159.788803 last_received_ts = 159.788254 last_seq = 518 current_ts = 159.805466 current_received_ts = 159.804916 current_seq = 519 count = 515 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 129us (kms_flip:3693) DEBUG: name = flip last_ts = 159.805466 last_received_ts = 159.804916 last_seq = 519 current_ts = 159.822128 current_received_ts = 159.821579 current_seq = 520 count = 516 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 94us (kms_flip:3693) DEBUG: name = flip last_ts = 159.822128 last_received_ts = 159.821579 last_seq = 520 current_ts = 159.838806 current_received_ts = 159.838165 current_seq = 521 count = 517 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.838806 last_received_ts = 159.838165 last_seq = 521 current_ts = 159.855469 current_received_ts = 159.854935 current_seq = 522 count = 518 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 135us (kms_flip:3693) DEBUG: name = flip last_ts = 159.855469 last_received_ts = 159.854935 last_seq = 522 current_ts = 159.872131 current_received_ts = 159.871521 current_seq = 523 count = 519 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.872131 last_received_ts = 159.871521 last_seq = 523 current_ts = 159.888779 current_received_ts = 159.888168 current_seq = 524 count = 520 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.888779 last_received_ts = 159.888168 last_seq = 524 current_ts = 159.905457 current_received_ts = 159.904922 current_seq = 525 count = 521 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 122us (kms_flip:3693) DEBUG: name = flip last_ts = 159.905457 last_received_ts = 159.904922 last_seq = 525 current_ts = 159.922119 current_received_ts = 159.921585 current_seq = 526 count = 522 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.922119 last_received_ts = 159.921585 last_seq = 526 current_ts = 159.938782 current_received_ts = 159.938171 current_seq = 527 count = 523 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 159.938782 last_received_ts = 159.938171 last_seq = 527 current_ts = 159.955444 current_received_ts = 159.954910 current_seq = 528 count = 524 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 140us (kms_flip:3693) DEBUG: name = flip last_ts = 159.955444 last_received_ts = 159.954910 last_seq = 528 current_ts = 159.972107 current_received_ts = 159.971542 current_seq = 529 count = 525 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 86us (kms_flip:3693) DEBUG: name = flip last_ts = 159.972107 last_received_ts = 159.971542 last_seq = 529 current_ts = 159.988770 current_received_ts = 159.988251 current_seq = 530 count = 526 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 165us (kms_flip:3693) DEBUG: name = flip last_ts = 159.988770 last_received_ts = 159.988251 last_seq = 530 current_ts = 160.005447 current_received_ts = 160.004898 current_seq = 531 count = 527 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 129us (kms_flip:3693) DEBUG: name = flip last_ts = 160.005447 last_received_ts = 160.004898 last_seq = 531 current_ts = 160.022110 current_received_ts = 160.021545 current_seq = 532 count = 528 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 86us (kms_flip:3693) DEBUG: name = flip last_ts = 160.022110 last_received_ts = 160.021545 last_seq = 532 current_ts = 160.038757 current_received_ts = 160.038193 current_seq = 533 count = 529 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 160.038757 last_received_ts = 160.038193 last_seq = 533 current_ts = 160.055420 current_received_ts = 160.054886 current_seq = 534 count = 530 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 86us (kms_flip:3693) DEBUG: name = flip last_ts = 160.055420 last_received_ts = 160.054886 last_seq = 534 current_ts = 160.072098 current_received_ts = 160.071533 current_seq = 535 count = 531 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 88us (kms_flip:3693) DEBUG: name = flip last_ts = 160.072098 last_received_ts = 160.071533 last_seq = 535 current_ts = 160.088760 current_received_ts = 160.088165 current_seq = 536 count = 532 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 160.088760 last_received_ts = 160.088165 last_seq = 536 current_ts = 160.105423 current_received_ts = 160.104889 current_seq = 537 count = 533 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 132us (kms_flip:3693) DEBUG: name = flip last_ts = 160.105423 last_received_ts = 160.104889 last_seq = 537 current_ts = 160.122086 current_received_ts = 160.121521 current_seq = 538 count = 534 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 160.122086 last_received_ts = 160.121521 last_seq = 538 current_ts = 160.138748 current_received_ts = 160.138214 current_seq = 539 count = 535 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 160.138748 last_received_ts = 160.138214 last_seq = 539 current_ts = 160.155411 current_received_ts = 160.154877 current_seq = 540 count = 536 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 130us (kms_flip:3693) DEBUG: name = flip last_ts = 160.155411 last_received_ts = 160.154877 last_seq = 540 current_ts = 160.172073 current_received_ts = 160.171524 current_seq = 541 count = 537 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 100us (kms_flip:3693) DEBUG: name = flip last_ts = 160.172073 last_received_ts = 160.171524 last_seq = 541 current_ts = 160.188736 current_received_ts = 160.188171 current_seq = 542 count = 538 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 101us (kms_flip:3693) DEBUG: name = flip last_ts = 160.188736 last_received_ts = 160.188171 last_seq = 542 current_ts = 160.205414 current_received_ts = 160.204865 current_seq = 543 count = 539 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 100us (kms_flip:3693) DEBUG: name = flip last_ts = 160.205414 last_received_ts = 160.204865 last_seq = 543 current_ts = 160.222061 current_received_ts = 160.221512 current_seq = 544 count = 540 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 160.222061 last_received_ts = 160.221512 last_seq = 544 current_ts = 160.238739 current_received_ts = 160.238174 current_seq = 545 count = 541 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 97us (kms_flip:3693) DEBUG: name = flip last_ts = 160.238739 last_received_ts = 160.238174 last_seq = 545 current_ts = 160.255402 current_received_ts = 160.254868 current_seq = 546 count = 542 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 92us (kms_flip:3693) DEBUG: name = flip last_ts = 160.255402 last_received_ts = 160.254868 last_seq = 546 current_ts = 160.272064 current_received_ts = 160.271530 current_seq = 547 count = 543 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 99us (kms_flip:3693) DEBUG: name = flip last_ts = 160.272064 last_received_ts = 160.271530 last_seq = 547 current_ts = 160.288727 current_received_ts = 160.288193 current_seq = 548 count = 544 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 100us (kms_flip:3693) DEBUG: name = flip last_ts = 160.288727 last_received_ts = 160.288193 last_seq = 548 current_ts = 160.305389 current_received_ts = 160.304855 current_seq = 549 count = 545 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 98us (kms_flip:3693) DEBUG: name = flip last_ts = 160.305389 last_received_ts = 160.304855 last_seq = 549 current_ts = 160.322052 current_received_ts = 160.321503 current_seq = 550 count = 546 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 88us (kms_flip:3693) DEBUG: name = flip last_ts = 160.322052 last_received_ts = 160.321503 last_seq = 550 current_ts = 160.338715 current_received_ts = 160.338242 current_seq = 551 count = 547 seq_step = 1 (kms_flip:3693) DEBUG: Vblank took 635us (kms_flip:3693) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:3693) CRITICAL: Failed assertion: end - start < 500 (kms_flip:3693) igt_core-INFO: Stack trace: (kms_flip:3693) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:3693) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:3693) igt_core-INFO: #2 ../tests/kms_flip.c:1889 run_test() (kms_flip:3693) igt_core-INFO: #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045() (kms_flip:3693) igt_core-INFO: #4 ../tests/kms_flip.c:2045 main() (kms_flip:3693) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:3693) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:3693) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (10.523s)
Dmesg	<6> [150.018562] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [150.036576] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [150.036724] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [150.036858] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:429] <7> [150.036845] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [150.037213] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430] <7> [150.103748] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:149:pipe A] <7> [150.103989] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [150.104344] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [150.104633] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [150.104959] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [150.105242] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149: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> [150.105506] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [150.105789] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [150.106032] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [150.106257] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [150.106478] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [150.106714] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [150.106946] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [150.107151] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [150.107354] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [150.107548] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [150.107761] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [150.107955] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [150.108141] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [150.108356] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [150.108560] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [150.108749] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [150.108934] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [150.109096] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [150.109253] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [150.109410] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [150.109561] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [150.109750] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [150.109915] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [150.110079] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [150.110229] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [150.110366] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [150.110499] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [150.110629] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [150.110820] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [150.110970] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [150.111094] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [150.111215] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [150.111351] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [150.111493] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:149:pipe A] fastset requirement not met, forcing full modeset <7> [150.111614] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:149:pipe A] releasing DPLL 0 <7> [150.111813] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [150.111929] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:149:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [150.112054] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:143:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [150.112168] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:149:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [150.112296] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [150.112417] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [150.112532] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [150.112692] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:149:pipe A] enable: no [modeset] <7> [150.112810] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:33:plane 1A] fb: [NOFB], visible: no <7> [150.112923] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:63:plane 2A] fb: [NOFB], visible: no <7> [150.113030] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:93:plane 3A] fb: [NOFB], visible: no <7> [150.113135] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:123:plane 4A] fb: [NOFB], visible: no <7> [150.113238] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:133:plane 5A] fb: [NOFB], visible: no <7> [150.113340] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:143:cursor A] fb: [NOFB], visible: no <7> [150.113515] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [150.113628] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [150.113915] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [150.114025] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [150.315890] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:391:eDP-1] set backlight PWM = 0 <7> [150.316563] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [150.337661] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 turn panel power off <7> [150.338068] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [150.338239] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 wait for panel power off time <7> [150.338569] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:390:DDI A/PHY A] - short <7> [150.338697] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [150.389724] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [150.390089] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:149:pipe A] <7> [150.390578] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [150.390491] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:390:DDI A/PHY A] <7> [150.390990] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:390:DDI A/PHY A] - short <7> [150.391374] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [150.391909] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [150.391846] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:390:DDI A/PHY A] <7> [150.392488] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:390:DDI A/PHY A] <7> [150.392946] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:399:DDI TC1/PHY TC1] <7> [150.393294] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DP-MST A] <7> [150.393628] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:402:DP-MST B] <7> [150.394057] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST C] <7> [150.394387] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:411:DDI TC2/PHY TC2] <7> [150.394724] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DP-MST A] <7> [150.395034] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:414:DP-MST B] <7> [150.395337] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST C] <7> [150.395638] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:419:DDI TC3/PHY TC3] <7> [150.395975] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DP-MST A] <7> [150.396241] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:422:DP-MST B] <7> [150.396505] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST C] <7> [150.396869] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:391:eDP-1] <7> [150.397244] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [150.397542] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [150.397951] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [150.398469] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [150.399016] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:149:pipe A] <7> [150.399387] 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> [150.399840] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [150.400182] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [150.401081] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B] <7> [150.401514] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C] <7> [150.401864] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B] <7> [150.401942] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:391:eDP-1] <7> [150.402119] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:391:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [150.402526] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:390:DDI A/PHY A][CRTC:268:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [150.402922] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 link rate required 1303913 available 1728000 <7> [150.403320] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:268:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [150.403698] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:390:DDI A/PHY A] [CRTC:268:pipe B] <7> [150.404085] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [150.404415] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [150.404724] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [150.405018] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [150.405294] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [150.405597] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [150.405919] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [150.406194] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [150.406437] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [150.406665] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [150.406928] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [150.407173] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [150.407380] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [150.407578] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [150.407796] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [150.407984] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [150.408165] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [150.408341] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [150.408510] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [150.408688] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [150.408858] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [150.409014] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [150.409167] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [150.409316] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [150.409457] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [150.409597] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [150.409760] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [150.409895] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [150.410026] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [150.410157] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [150.410282] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [150.410407] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [150.410534] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [150.410659] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [150.410814] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in dpll_hw_state <7> [150.410936] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] expected: <7> [150.411052] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 0, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [150.411178] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: clock: 0 <7> [150.411306] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0x0000, tx[1] = 0x0000, tx[2] = 0x0000 <7> [150.411420] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0000, cmn[1] = 0x0000, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [150.411526] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[0] = 0x0000 <7> [150.411629] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[1] = 0x0000 <7> [150.411760] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[2] = 0x0000 <7> [150.411881] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[3] = 0x0000 <7> [150.411993] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[4] = 0x0000 <7> [150.412089] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[5] = 0x0000 <7> [150.412183] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[6] = 0x0000 <7> [150.412274] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[7] = 0x0000 <7> [150.412364] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[8] = 0x0000 <7> [150.412453] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[9] = 0x0000 <7> [150.412543] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000 <7> [150.412629] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00 <7> [150.412727] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] found: <7> [150.412819] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [150.412908] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_hw_state: clock: 432000, fracen: no, <7> [150.412995] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] multiplier: 225, tx_clk_div: 1. <7> [150.413077] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_rawhw_state: <7> [150.413158] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] tx: 0x10, cmn: 0x21 <7> [150.413236] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [150.413314] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [150.413391] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [150.413467] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [150.413548] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [150.413643] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [150.413809] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [150.413903] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [150.413983] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [150.414051] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:268:pipe B] fastset requirement not met, forcing full modeset <7> [150.414150] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [150.414213] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:268:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [150.414298] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:152:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [150.414362] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:262:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [150.414425] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:152:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [150.414482] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:152:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [150.414543] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:152:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [150.414607] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:152:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [150.414703] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:268:pipe B] data rate 1390840 num active planes 1 <7> [150.414828] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [150.414936] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [150.415035] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [150.415133] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [150.415222] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [150.415299] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:268:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [150.415394] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [150.415484] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [150.415571] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [150.415674] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:268:pipe B] allocated DPLL 0 <7> [150.415775] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:268:pipe B] reserving DPLL 0 <7> [150.415881] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:268:pipe B] enable: yes [modeset] <7> [150.415983] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [150.416069] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [150.416147] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [150.416224] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [150.416309] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [150.416392] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [150.416473] 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> [150.416554] 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> [150.416633] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [150.416732] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [150.416835] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [150.416940] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [150.417029] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [150.417107] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [150.417184] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [150.417263] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [150.417351] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [150.417439] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [150.417527] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [150.417605] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [150.417678] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [150.417767] 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> [150.417856] 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> [150.417950] 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> [150.418031] 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> [150.418108] 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> [150.418184] 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> [150.418259] 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> [150.418334] 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> [150.418409] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855 <7> [150.418477] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [150.418545] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [150.418612] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [150.418691] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [150.418792] 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> [150.418893] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: clock: 432000, fracen: no, <7> [150.418993] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [150.419091] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [150.419180] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [150.419273] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [150.419355] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [150.419426] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [150.419492] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [150.419558] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [150.419630] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [150.419730] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [150.419740] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [150.419819] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [150.419892] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [150.419906] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [150.419992] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [150.420014] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [150.420079] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [150.420156] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [150.420173] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [150.420273] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [150.420374] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [150.420450] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [150.420527] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [150.420605] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [150.420686] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [150.420776] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:152:plane 1B] fb: [FB:429] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [150.420867] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [150.420955] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [150.421044] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:182:plane 2B] fb: [NOFB], visible: no <7> [150.421131] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:212:plane 3B] fb: [NOFB], visible: no <7> [150.421216] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:242:plane 4B] fb: [NOFB], visible: no <7> [150.421288] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:252:plane 5B] fb: [NOFB], visible: no <7> [150.421361] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:262:cursor B] fb: [NOFB], visible: no <7> [150.421757] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [150.421860] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [150.422112] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [150.422243] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [150.422377] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [150.422522] 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> [150.422616] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [150.422718] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [150.422820] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:390:DDI A/PHY A] <7> [150.422905] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:399:DDI TC1/PHY TC1] <7> [150.422986] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DP-MST A] <7> [150.423048] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:402:DP-MST B] <7> [150.423115] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST C] <7> [150.423179] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:411:DDI TC2/PHY TC2] <7> [150.423243] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DP-MST A] <7> [150.423306] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:414:DP-MST B] <7> [150.423367] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST C] <7> [150.423428] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:419:DDI TC3/PHY TC3] <7> [150.423489] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DP-MST A] <7> [150.423552] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:422:DP-MST B] <7> [150.423612] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST C] <7> [150.423698] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [150.423875] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [150.423952] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [150.424068] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [150.425391] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:268:pipe B] <7> [150.425478] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [150.427173] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 turn panel power on <7> [150.427243] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 wait for panel power cycle (463 ms remaining) <7> [150.427928] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [150.428030] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:390:DDI A/PHY A] - long <7> [150.428111] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [150.428246] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:390:DDI A/PHY A] <7> [150.891908] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [150.939425] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [150.939834] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 wait for panel power on <7> [150.940150] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [150.975905] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [150.976352] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:390:DDI A/PHY A] - long <7> [150.976795] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [150.977565] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:390:DDI A/PHY A] <7> [151.148734] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [151.149134] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 turning VDD on <7> [151.149453] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [151.151575] 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> [151.152934] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [151.153832] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [151.155057] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [151.156318] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [151.157522] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Clock recovery OK <7> [151.157957] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [151.159443] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [151.159856] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [151.160642] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [151.161274] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [151.161707] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [151.162244] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:391:eDP-1] set backlight PWM = 4518 <7> [151.178199] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [151.180060] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:391:eDP-1] <7> [151.180520] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:268:pipe B] <7> [153.724053] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 turning VDD off <7> [153.724613] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [160.344839] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [160.345406] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [160.345972] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [160.542298] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

10.52 seconds

Hostname

shard-lnl-2

Igt-Version

IGT-Version: 2.3-g6f7cf72fa (x86_64) (Linux: 6.19.0-rc4-lgci-xe-xe-4359-440d2cb5f3dfa9cbb+ x86_64)

Out

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

Err

Starting dynamic subtest: B-eDP1
(kms_flip:3693) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:3693) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.305710
last_received_ts = 158.305176
last_seq = 429
current_ts = 158.322372
current_received_ts = 158.321854
current_seq = 430
count = 426
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.322372
last_received_ts = 158.321854
last_seq = 430
current_ts = 158.339035
current_received_ts = 158.338501
current_seq = 431
count = 427
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 101us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.339035
last_received_ts = 158.338501
last_seq = 431
current_ts = 158.355698
current_received_ts = 158.355164
current_seq = 432
count = 428
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.355698
last_received_ts = 158.355164
last_seq = 432
current_ts = 158.372360
current_received_ts = 158.371857
current_seq = 433
count = 429
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.372360
last_received_ts = 158.371857
last_seq = 433
current_ts = 158.389023
current_received_ts = 158.388458
current_seq = 434
count = 430
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 96us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.389023
last_received_ts = 158.388458
last_seq = 434
current_ts = 158.405685
current_received_ts = 158.405167
current_seq = 435
count = 431
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.405685
last_received_ts = 158.405167
last_seq = 435
current_ts = 158.422363
current_received_ts = 158.421814
current_seq = 436
count = 432
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 88us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.422363
last_received_ts = 158.421814
last_seq = 436
current_ts = 158.439026
current_received_ts = 158.438431
current_seq = 437
count = 433
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.439026
last_received_ts = 158.438431
last_seq = 437
current_ts = 158.455688
current_received_ts = 158.455154
current_seq = 438
count = 434
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.455688
last_received_ts = 158.455154
last_seq = 438
current_ts = 158.472351
current_received_ts = 158.471802
current_seq = 439
count = 435
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.472351
last_received_ts = 158.471802
last_seq = 439
current_ts = 158.489014
current_received_ts = 158.488419
current_seq = 440
count = 436
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.489014
last_received_ts = 158.488419
last_seq = 440
current_ts = 158.505676
current_received_ts = 158.505157
current_seq = 441
count = 437
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.505676
last_received_ts = 158.505157
last_seq = 441
current_ts = 158.522339
current_received_ts = 158.521820
current_seq = 442
count = 438
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 97us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.522339
last_received_ts = 158.521820
last_seq = 442
current_ts = 158.539001
current_received_ts = 158.538467
current_seq = 443
count = 439
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 167us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.539001
last_received_ts = 158.538467
last_seq = 443
current_ts = 158.555679
current_received_ts = 158.555130
current_seq = 444
count = 440
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 100us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.555679
last_received_ts = 158.555130
last_seq = 444
current_ts = 158.572342
current_received_ts = 158.571793
current_seq = 445
count = 441
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.572342
last_received_ts = 158.571793
last_seq = 445
current_ts = 158.589005
current_received_ts = 158.588470
current_seq = 446
count = 442
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 161us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.589005
last_received_ts = 158.588470
last_seq = 446
current_ts = 158.605667
current_received_ts = 158.605148
current_seq = 447
count = 443
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 100us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.605667
last_received_ts = 158.605148
last_seq = 447
current_ts = 158.622330
current_received_ts = 158.621796
current_seq = 448
count = 444
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 101us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.622330
last_received_ts = 158.621796
last_seq = 448
current_ts = 158.638992
current_received_ts = 158.638443
current_seq = 449
count = 445
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.638992
last_received_ts = 158.638443
last_seq = 449
current_ts = 158.655655
current_received_ts = 158.655121
current_seq = 450
count = 446
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.655655
last_received_ts = 158.655121
last_seq = 450
current_ts = 158.672318
current_received_ts = 158.671783
current_seq = 451
count = 447
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.672318
last_received_ts = 158.671783
last_seq = 451
current_ts = 158.688980
current_received_ts = 158.688416
current_seq = 452
count = 448
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 91us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.688980
last_received_ts = 158.688416
last_seq = 452
current_ts = 158.705643
current_received_ts = 158.705124
current_seq = 453
count = 449
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.705643
last_received_ts = 158.705124
last_seq = 453
current_ts = 158.722321
current_received_ts = 158.721771
current_seq = 454
count = 450
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.722321
last_received_ts = 158.721771
last_seq = 454
current_ts = 158.738968
current_received_ts = 158.738388
current_seq = 455
count = 451
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.738968
last_received_ts = 158.738388
last_seq = 455
current_ts = 158.755646
current_received_ts = 158.755112
current_seq = 456
count = 452
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.755646
last_received_ts = 158.755112
last_seq = 456
current_ts = 158.772308
current_received_ts = 158.771759
current_seq = 457
count = 453
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.772308
last_received_ts = 158.771759
last_seq = 457
current_ts = 158.788956
current_received_ts = 158.788406
current_seq = 458
count = 454
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 101us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.788956
last_received_ts = 158.788406
last_seq = 458
current_ts = 158.805634
current_received_ts = 158.805115
current_seq = 459
count = 455
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.805634
last_received_ts = 158.805115
last_seq = 459
current_ts = 158.822296
current_received_ts = 158.821747
current_seq = 460
count = 456
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.822296
last_received_ts = 158.821747
last_seq = 460
current_ts = 158.838959
current_received_ts = 158.838364
current_seq = 461
count = 457
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.838959
last_received_ts = 158.838364
last_seq = 461
current_ts = 158.855621
current_received_ts = 158.855103
current_seq = 462
count = 458
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.855621
last_received_ts = 158.855103
last_seq = 462
current_ts = 158.872284
current_received_ts = 158.871735
current_seq = 463
count = 459
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.872284
last_received_ts = 158.871735
last_seq = 463
current_ts = 158.888947
current_received_ts = 158.888351
current_seq = 464
count = 460
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.888947
last_received_ts = 158.888351
last_seq = 464
current_ts = 158.905609
current_received_ts = 158.905075
current_seq = 465
count = 461
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 92us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.905609
last_received_ts = 158.905075
last_seq = 465
current_ts = 158.922287
current_received_ts = 158.921738
current_seq = 466
count = 462
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.922287
last_received_ts = 158.921738
last_seq = 466
current_ts = 158.938950
current_received_ts = 158.938339
current_seq = 467
count = 463
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.938950
last_received_ts = 158.938339
last_seq = 467
current_ts = 158.955612
current_received_ts = 158.955093
current_seq = 468
count = 464
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 86us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.955612
last_received_ts = 158.955093
last_seq = 468
current_ts = 158.972275
current_received_ts = 158.971710
current_seq = 469
count = 465
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.972275
last_received_ts = 158.971710
last_seq = 469
current_ts = 158.988937
current_received_ts = 158.988388
current_seq = 470
count = 466
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 163us
(kms_flip:3693) DEBUG: name = flip
last_ts = 158.988937
last_received_ts = 158.988388
last_seq = 470
current_ts = 159.005600
current_received_ts = 159.005066
current_seq = 471
count = 467
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 100us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.005600
last_received_ts = 159.005066
last_seq = 471
current_ts = 159.022263
current_received_ts = 159.021744
current_seq = 472
count = 468
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 100us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.022263
last_received_ts = 159.021744
last_seq = 472
current_ts = 159.038925
current_received_ts = 159.038330
current_seq = 473
count = 469
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.038925
last_received_ts = 159.038330
last_seq = 473
current_ts = 159.055588
current_received_ts = 159.055069
current_seq = 474
count = 470
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 97us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.055588
last_received_ts = 159.055069
last_seq = 474
current_ts = 159.072266
current_received_ts = 159.071716
current_seq = 475
count = 471
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.072266
last_received_ts = 159.071716
last_seq = 475
current_ts = 159.088913
current_received_ts = 159.088318
current_seq = 476
count = 472
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 92us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.088913
last_received_ts = 159.088318
last_seq = 476
current_ts = 159.105576
current_received_ts = 159.105057
current_seq = 477
count = 473
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 96us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.105576
last_received_ts = 159.105057
last_seq = 477
current_ts = 159.122238
current_received_ts = 159.121719
current_seq = 478
count = 474
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.122238
last_received_ts = 159.121719
last_seq = 478
current_ts = 159.138916
current_received_ts = 159.138367
current_seq = 479
count = 475
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.138916
last_received_ts = 159.138367
last_seq = 479
current_ts = 159.155579
current_received_ts = 159.155060
current_seq = 480
count = 476
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.155579
last_received_ts = 159.155060
last_seq = 480
current_ts = 159.172241
current_received_ts = 159.171600
current_seq = 481
count = 477
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.172241
last_received_ts = 159.171600
last_seq = 481
current_ts = 159.188904
current_received_ts = 159.188354
current_seq = 482
count = 478
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 100us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.188904
last_received_ts = 159.188354
last_seq = 482
current_ts = 159.205566
current_received_ts = 159.205048
current_seq = 483
count = 479
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.205566
last_received_ts = 159.205048
last_seq = 483
current_ts = 159.222229
current_received_ts = 159.221588
current_seq = 484
count = 480
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.222229
last_received_ts = 159.221588
last_seq = 484
current_ts = 159.238892
current_received_ts = 159.238373
current_seq = 485
count = 481
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.238892
last_received_ts = 159.238373
last_seq = 485
current_ts = 159.255554
current_received_ts = 159.255035
current_seq = 486
count = 482
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.255554
last_received_ts = 159.255035
last_seq = 486
current_ts = 159.272217
current_received_ts = 159.271683
current_seq = 487
count = 483
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.272217
last_received_ts = 159.271683
last_seq = 487
current_ts = 159.288879
current_received_ts = 159.288300
current_seq = 488
count = 484
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 96us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.288879
last_received_ts = 159.288300
last_seq = 488
current_ts = 159.305557
current_received_ts = 159.305038
current_seq = 489
count = 485
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 97us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.305557
last_received_ts = 159.305038
last_seq = 489
current_ts = 159.322220
current_received_ts = 159.321701
current_seq = 490
count = 486
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 92us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.322220
last_received_ts = 159.321701
last_seq = 490
current_ts = 159.338882
current_received_ts = 159.338333
current_seq = 491
count = 487
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 86us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.338882
last_received_ts = 159.338333
last_seq = 491
current_ts = 159.355545
current_received_ts = 159.355042
current_seq = 492
count = 488
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.355545
last_received_ts = 159.355042
last_seq = 492
current_ts = 159.372208
current_received_ts = 159.371536
current_seq = 493
count = 489
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 94us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.372208
last_received_ts = 159.371536
last_seq = 493
current_ts = 159.388870
current_received_ts = 159.388336
current_seq = 494
count = 490
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 96us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.388870
last_received_ts = 159.388336
last_seq = 494
current_ts = 159.405533
current_received_ts = 159.405045
current_seq = 495
count = 491
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.405533
last_received_ts = 159.405045
last_seq = 495
current_ts = 159.422195
current_received_ts = 159.421661
current_seq = 496
count = 492
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 95us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.422195
last_received_ts = 159.421661
last_seq = 496
current_ts = 159.438858
current_received_ts = 159.438278
current_seq = 497
count = 493
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.438858
last_received_ts = 159.438278
last_seq = 497
current_ts = 159.455521
current_received_ts = 159.454971
current_seq = 498
count = 494
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 131us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.455521
last_received_ts = 159.454971
last_seq = 498
current_ts = 159.472198
current_received_ts = 159.471649
current_seq = 499
count = 495
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.472198
last_received_ts = 159.471649
last_seq = 499
current_ts = 159.488846
current_received_ts = 159.488205
current_seq = 500
count = 496
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 117us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.488846
last_received_ts = 159.488205
last_seq = 500
current_ts = 159.505524
current_received_ts = 159.504974
current_seq = 501
count = 497
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 100us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.505524
last_received_ts = 159.504974
last_seq = 501
current_ts = 159.522186
current_received_ts = 159.521667
current_seq = 502
count = 498
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.522186
last_received_ts = 159.521667
last_seq = 502
current_ts = 159.538849
current_received_ts = 159.538223
current_seq = 503
count = 499
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 100us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.538849
last_received_ts = 159.538223
last_seq = 503
current_ts = 159.555511
current_received_ts = 159.554977
current_seq = 504
count = 500
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 86us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.555511
last_received_ts = 159.554977
last_seq = 504
current_ts = 159.572174
current_received_ts = 159.571625
current_seq = 505
count = 501
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.572174
last_received_ts = 159.571625
last_seq = 505
current_ts = 159.588837
current_received_ts = 159.588303
current_seq = 506
count = 502
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 143us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.588837
last_received_ts = 159.588303
last_seq = 506
current_ts = 159.605499
current_received_ts = 159.604980
current_seq = 507
count = 503
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 92us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.605499
last_received_ts = 159.604980
last_seq = 507
current_ts = 159.622162
current_received_ts = 159.621536
current_seq = 508
count = 504
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.622162
last_received_ts = 159.621536
last_seq = 508
current_ts = 159.638824
current_received_ts = 159.638199
current_seq = 509
count = 505
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.638824
last_received_ts = 159.638199
last_seq = 509
current_ts = 159.655487
current_received_ts = 159.654953
current_seq = 510
count = 506
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 127us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.655487
last_received_ts = 159.654953
last_seq = 510
current_ts = 159.672165
current_received_ts = 159.671600
current_seq = 511
count = 507
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 86us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.672165
last_received_ts = 159.671600
last_seq = 511
current_ts = 159.688828
current_received_ts = 159.688187
current_seq = 512
count = 508
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 100us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.688828
last_received_ts = 159.688187
last_seq = 512
current_ts = 159.705490
current_received_ts = 159.704956
current_seq = 513
count = 509
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 109us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.705490
last_received_ts = 159.704956
last_seq = 513
current_ts = 159.722153
current_received_ts = 159.721512
current_seq = 514
count = 510
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 86us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.722153
last_received_ts = 159.721512
last_seq = 514
current_ts = 159.738815
current_received_ts = 159.738174
current_seq = 515
count = 511
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 87us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.738815
last_received_ts = 159.738174
last_seq = 515
current_ts = 159.755478
current_received_ts = 159.754929
current_seq = 516
count = 512
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 143us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.755478
last_received_ts = 159.754929
last_seq = 516
current_ts = 159.772141
current_received_ts = 159.771591
current_seq = 517
count = 513
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.772141
last_received_ts = 159.771591
last_seq = 517
current_ts = 159.788803
current_received_ts = 159.788254
current_seq = 518
count = 514
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 181us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.788803
last_received_ts = 159.788254
last_seq = 518
current_ts = 159.805466
current_received_ts = 159.804916
current_seq = 519
count = 515
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 129us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.805466
last_received_ts = 159.804916
last_seq = 519
current_ts = 159.822128
current_received_ts = 159.821579
current_seq = 520
count = 516
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 94us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.822128
last_received_ts = 159.821579
last_seq = 520
current_ts = 159.838806
current_received_ts = 159.838165
current_seq = 521
count = 517
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.838806
last_received_ts = 159.838165
last_seq = 521
current_ts = 159.855469
current_received_ts = 159.854935
current_seq = 522
count = 518
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 135us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.855469
last_received_ts = 159.854935
last_seq = 522
current_ts = 159.872131
current_received_ts = 159.871521
current_seq = 523
count = 519
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.872131
last_received_ts = 159.871521
last_seq = 523
current_ts = 159.888779
current_received_ts = 159.888168
current_seq = 524
count = 520
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.888779
last_received_ts = 159.888168
last_seq = 524
current_ts = 159.905457
current_received_ts = 159.904922
current_seq = 525
count = 521
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 122us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.905457
last_received_ts = 159.904922
last_seq = 525
current_ts = 159.922119
current_received_ts = 159.921585
current_seq = 526
count = 522
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.922119
last_received_ts = 159.921585
last_seq = 526
current_ts = 159.938782
current_received_ts = 159.938171
current_seq = 527
count = 523
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.938782
last_received_ts = 159.938171
last_seq = 527
current_ts = 159.955444
current_received_ts = 159.954910
current_seq = 528
count = 524
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 140us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.955444
last_received_ts = 159.954910
last_seq = 528
current_ts = 159.972107
current_received_ts = 159.971542
current_seq = 529
count = 525
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 86us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.972107
last_received_ts = 159.971542
last_seq = 529
current_ts = 159.988770
current_received_ts = 159.988251
current_seq = 530
count = 526
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 165us
(kms_flip:3693) DEBUG: name = flip
last_ts = 159.988770
last_received_ts = 159.988251
last_seq = 530
current_ts = 160.005447
current_received_ts = 160.004898
current_seq = 531
count = 527
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 129us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.005447
last_received_ts = 160.004898
last_seq = 531
current_ts = 160.022110
current_received_ts = 160.021545
current_seq = 532
count = 528
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 86us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.022110
last_received_ts = 160.021545
last_seq = 532
current_ts = 160.038757
current_received_ts = 160.038193
current_seq = 533
count = 529
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.038757
last_received_ts = 160.038193
last_seq = 533
current_ts = 160.055420
current_received_ts = 160.054886
current_seq = 534
count = 530
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 86us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.055420
last_received_ts = 160.054886
last_seq = 534
current_ts = 160.072098
current_received_ts = 160.071533
current_seq = 535
count = 531
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 88us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.072098
last_received_ts = 160.071533
last_seq = 535
current_ts = 160.088760
current_received_ts = 160.088165
current_seq = 536
count = 532
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.088760
last_received_ts = 160.088165
last_seq = 536
current_ts = 160.105423
current_received_ts = 160.104889
current_seq = 537
count = 533
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 132us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.105423
last_received_ts = 160.104889
last_seq = 537
current_ts = 160.122086
current_received_ts = 160.121521
current_seq = 538
count = 534
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.122086
last_received_ts = 160.121521
last_seq = 538
current_ts = 160.138748
current_received_ts = 160.138214
current_seq = 539
count = 535
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.138748
last_received_ts = 160.138214
last_seq = 539
current_ts = 160.155411
current_received_ts = 160.154877
current_seq = 540
count = 536
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 130us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.155411
last_received_ts = 160.154877
last_seq = 540
current_ts = 160.172073
current_received_ts = 160.171524
current_seq = 541
count = 537
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 100us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.172073
last_received_ts = 160.171524
last_seq = 541
current_ts = 160.188736
current_received_ts = 160.188171
current_seq = 542
count = 538
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 101us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.188736
last_received_ts = 160.188171
last_seq = 542
current_ts = 160.205414
current_received_ts = 160.204865
current_seq = 543
count = 539
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 100us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.205414
last_received_ts = 160.204865
last_seq = 543
current_ts = 160.222061
current_received_ts = 160.221512
current_seq = 544
count = 540
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.222061
last_received_ts = 160.221512
last_seq = 544
current_ts = 160.238739
current_received_ts = 160.238174
current_seq = 545
count = 541
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 97us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.238739
last_received_ts = 160.238174
last_seq = 545
current_ts = 160.255402
current_received_ts = 160.254868
current_seq = 546
count = 542
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 92us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.255402
last_received_ts = 160.254868
last_seq = 546
current_ts = 160.272064
current_received_ts = 160.271530
current_seq = 547
count = 543
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 99us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.272064
last_received_ts = 160.271530
last_seq = 547
current_ts = 160.288727
current_received_ts = 160.288193
current_seq = 548
count = 544
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 100us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.288727
last_received_ts = 160.288193
last_seq = 548
current_ts = 160.305389
current_received_ts = 160.304855
current_seq = 549
count = 545
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 98us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.305389
last_received_ts = 160.304855
last_seq = 549
current_ts = 160.322052
current_received_ts = 160.321503
current_seq = 550
count = 546
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 88us
(kms_flip:3693) DEBUG: name = flip
last_ts = 160.322052
last_received_ts = 160.321503
last_seq = 550
current_ts = 160.338715
current_received_ts = 160.338242
current_seq = 551
count = 547
seq_step = 1
(kms_flip:3693) DEBUG: Vblank took 635us
(kms_flip:3693) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:3693) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3693) igt_core-INFO: Stack trace:
(kms_flip:3693) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:3693) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:3693) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:3693) igt_core-INFO:   #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045()
(kms_flip:3693) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:3693) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3693) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3693) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (10.523s)

Dmesg

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

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

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

<7> [150.036858] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:429]

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

<7> [150.037213] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430]

<7> [150.103748] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:149:pipe A]

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

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

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

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

<7> [150.105242] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149: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> [150.105506] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [150.399016] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:149:pipe A]

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

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

<7> [150.401081] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B]

<7> [150.401514] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C]

<7> [150.401864] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B]

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

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

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

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

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

<7> [150.403698] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:390:DDI A/PHY A] [CRTC:268:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [150.410814] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in dpll_hw_state

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

<7> [150.411052] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 0, ssc_enabled: no, use_c10: no, tbt_mode: no

<7> [150.411178] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: clock: 0

<7> [150.411306] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0x0000, tx[1] = 0x0000, tx[2] = 0x0000

<7> [150.411420] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0000, cmn[1] = 0x0000, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [150.411526] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[0] = 0x0000

<7> [150.411629] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[1] = 0x0000

<7> [150.411760] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[2] = 0x0000

<7> [150.411881] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[3] = 0x0000

<7> [150.411993] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[4] = 0x0000

<7> [150.412089] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[5] = 0x0000

<7> [150.412183] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[6] = 0x0000

<7> [150.412274] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[7] = 0x0000

<7> [150.412364] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[8] = 0x0000

<7> [150.412453] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[9] = 0x0000

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

<7> [150.412629] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00

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

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

<7> [150.412908] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_hw_state: clock: 432000, fracen: no,

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

<7> [150.413077] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_rawhw_state:

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [150.414298] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:152:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

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

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

<7> [150.414482] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:152:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0

<7> [150.414543] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:152:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197

<7> [150.414607] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:152:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [150.417767] 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> [150.417856] 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> [150.417950] 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> [150.418031] 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> [150.418108] 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> [150.418184] 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> [150.418259] 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> [150.418334] 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> [150.418409] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855

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

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

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

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

<7> [150.418792] 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> [150.418893] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: clock: 432000, fracen: no,

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [151.151575] 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> [151.152934] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Reloading eDP link rates

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [151.180520] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:268:pipe B]

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

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

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

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

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

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

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