igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1 on shard-lnl@xe-5013-b023767ff66180ad432701eb5ba4ccf8f70de46d Test details

Detail	Value
Duration	11.10 seconds
Hostname	shard-lnl-4
Igt-Version	IGT-Version: 2.4-g3e5747e53 (x86_64) (Linux: 7.1.0-rc2-lgci-xe-xe-5013-b023767ff66180ad4-debug+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (11.096s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:7842) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:7842) CRITICAL: Failed assertion: end - start < 500 (kms_flip:7842) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:7842) DEBUG: Vblank took 55us (kms_flip:7842) DEBUG: name = flip last_ts = 476.960083 last_received_ts = 476.959381 last_seq = 581 current_ts = 476.976715 current_received_ts = 476.976044 current_seq = 582 count = 466 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 51us (kms_flip:7842) DEBUG: name = flip last_ts = 476.976715 last_received_ts = 476.976044 last_seq = 582 current_ts = 476.993378 current_received_ts = 476.992706 current_seq = 583 count = 467 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 63us (kms_flip:7842) DEBUG: name = flip last_ts = 476.993378 last_received_ts = 476.992706 last_seq = 583 current_ts = 477.010040 current_received_ts = 477.009338 current_seq = 584 count = 468 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 45us (kms_flip:7842) DEBUG: name = flip last_ts = 477.010040 last_received_ts = 477.009338 last_seq = 584 current_ts = 477.026703 current_received_ts = 477.026031 current_seq = 585 count = 469 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 57us (kms_flip:7842) DEBUG: name = flip last_ts = 477.026703 last_received_ts = 477.026031 last_seq = 585 current_ts = 477.043365 current_received_ts = 477.042664 current_seq = 586 count = 470 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 53us (kms_flip:7842) DEBUG: name = flip last_ts = 477.043365 last_received_ts = 477.042664 last_seq = 586 current_ts = 477.060028 current_received_ts = 477.059326 current_seq = 587 count = 471 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 56us (kms_flip:7842) DEBUG: name = flip last_ts = 477.060028 last_received_ts = 477.059326 last_seq = 587 current_ts = 477.076660 current_received_ts = 477.075989 current_seq = 588 count = 472 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 76us (kms_flip:7842) DEBUG: name = flip last_ts = 477.076660 last_received_ts = 477.075989 last_seq = 588 current_ts = 477.093323 current_received_ts = 477.092651 current_seq = 589 count = 473 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 44us (kms_flip:7842) DEBUG: name = flip last_ts = 477.093323 last_received_ts = 477.092651 last_seq = 589 current_ts = 477.109985 current_received_ts = 477.109314 current_seq = 590 count = 474 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 43us (kms_flip:7842) DEBUG: name = flip last_ts = 477.109985 last_received_ts = 477.109314 last_seq = 590 current_ts = 477.126648 current_received_ts = 477.125977 current_seq = 591 count = 475 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 68us (kms_flip:7842) DEBUG: name = flip last_ts = 477.126648 last_received_ts = 477.125977 last_seq = 591 current_ts = 477.143311 current_received_ts = 477.142609 current_seq = 592 count = 476 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 59us (kms_flip:7842) DEBUG: name = flip last_ts = 477.143311 last_received_ts = 477.142609 last_seq = 592 current_ts = 477.159973 current_received_ts = 477.159271 current_seq = 593 count = 477 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 42us (kms_flip:7842) DEBUG: name = flip last_ts = 477.159973 last_received_ts = 477.159271 last_seq = 593 current_ts = 477.176605 current_received_ts = 477.175934 current_seq = 594 count = 478 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 74us (kms_flip:7842) DEBUG: name = flip last_ts = 477.176605 last_received_ts = 477.175934 last_seq = 594 current_ts = 477.193268 current_received_ts = 477.192566 current_seq = 595 count = 479 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 52us (kms_flip:7842) DEBUG: name = flip last_ts = 477.193268 last_received_ts = 477.192566 last_seq = 595 current_ts = 477.209930 current_received_ts = 477.209259 current_seq = 596 count = 480 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 45us (kms_flip:7842) DEBUG: name = flip last_ts = 477.209930 last_received_ts = 477.209259 last_seq = 596 current_ts = 477.226593 current_received_ts = 477.225861 current_seq = 597 count = 481 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 54us (kms_flip:7842) DEBUG: name = flip last_ts = 477.226593 last_received_ts = 477.225861 last_seq = 597 current_ts = 477.243256 current_received_ts = 477.242554 current_seq = 598 count = 482 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 53us (kms_flip:7842) DEBUG: name = flip last_ts = 477.243256 last_received_ts = 477.242554 last_seq = 598 current_ts = 477.259918 current_received_ts = 477.259125 current_seq = 599 count = 483 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 54us (kms_flip:7842) DEBUG: name = flip last_ts = 477.259918 last_received_ts = 477.259125 last_seq = 599 current_ts = 477.276581 current_received_ts = 477.275879 current_seq = 600 count = 484 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 43us (kms_flip:7842) DEBUG: name = flip last_ts = 477.276581 last_received_ts = 477.275879 last_seq = 600 current_ts = 477.293213 current_received_ts = 477.292542 current_seq = 601 count = 485 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 56us (kms_flip:7842) DEBUG: name = flip last_ts = 477.293213 last_received_ts = 477.292542 last_seq = 601 current_ts = 477.309875 current_received_ts = 477.309174 current_seq = 602 count = 486 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 55us (kms_flip:7842) DEBUG: name = flip last_ts = 477.309875 last_received_ts = 477.309174 last_seq = 602 current_ts = 477.326538 current_received_ts = 477.325836 current_seq = 603 count = 487 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 43us (kms_flip:7842) DEBUG: name = flip last_ts = 477.326538 last_received_ts = 477.325836 last_seq = 603 current_ts = 477.343201 current_received_ts = 477.342499 current_seq = 604 count = 488 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 73us (kms_flip:7842) DEBUG: name = flip last_ts = 477.343201 last_received_ts = 477.342499 last_seq = 604 current_ts = 477.359863 current_received_ts = 477.359070 current_seq = 605 count = 489 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 49us (kms_flip:7842) DEBUG: name = flip last_ts = 477.359863 last_received_ts = 477.359070 last_seq = 605 current_ts = 477.376495 current_received_ts = 477.375702 current_seq = 606 count = 490 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 56us (kms_flip:7842) DEBUG: name = flip last_ts = 477.376495 last_received_ts = 477.375702 last_seq = 606 current_ts = 477.393188 current_received_ts = 477.392517 current_seq = 607 count = 491 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 55us (kms_flip:7842) DEBUG: name = flip last_ts = 477.393188 last_received_ts = 477.392517 last_seq = 607 current_ts = 477.409821 current_received_ts = 477.409149 current_seq = 608 count = 492 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 67us (kms_flip:7842) DEBUG: name = flip last_ts = 477.409821 last_received_ts = 477.409149 last_seq = 608 current_ts = 477.426483 current_received_ts = 477.425812 current_seq = 609 count = 493 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 81us (kms_flip:7842) DEBUG: name = flip last_ts = 477.426483 last_received_ts = 477.425812 last_seq = 609 current_ts = 477.443146 current_received_ts = 477.442505 current_seq = 610 count = 494 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 105us (kms_flip:7842) DEBUG: name = flip last_ts = 477.443146 last_received_ts = 477.442505 last_seq = 610 current_ts = 477.459808 current_received_ts = 477.459167 current_seq = 611 count = 495 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 134us (kms_flip:7842) DEBUG: name = flip last_ts = 477.459808 last_received_ts = 477.459167 last_seq = 611 current_ts = 477.476471 current_received_ts = 477.475891 current_seq = 612 count = 496 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 76us (kms_flip:7842) DEBUG: name = flip last_ts = 477.476471 last_received_ts = 477.475891 last_seq = 612 current_ts = 477.493134 current_received_ts = 477.492371 current_seq = 613 count = 497 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 47us (kms_flip:7842) DEBUG: name = flip last_ts = 477.493134 last_received_ts = 477.492371 last_seq = 613 current_ts = 477.509766 current_received_ts = 477.509125 current_seq = 614 count = 498 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 82us (kms_flip:7842) DEBUG: name = flip last_ts = 477.509766 last_received_ts = 477.509125 last_seq = 614 current_ts = 477.526428 current_received_ts = 477.525879 current_seq = 615 count = 499 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 53us (kms_flip:7842) DEBUG: name = flip last_ts = 477.526428 last_received_ts = 477.525879 last_seq = 615 current_ts = 477.543091 current_received_ts = 477.542480 current_seq = 616 count = 500 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 157us (kms_flip:7842) DEBUG: name = flip last_ts = 477.543091 last_received_ts = 477.542480 last_seq = 616 current_ts = 477.559753 current_received_ts = 477.559113 current_seq = 617 count = 501 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 80us (kms_flip:7842) DEBUG: name = flip last_ts = 477.559753 last_received_ts = 477.559113 last_seq = 617 current_ts = 477.576416 current_received_ts = 477.575745 current_seq = 618 count = 502 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 60us (kms_flip:7842) DEBUG: name = flip last_ts = 477.576416 last_received_ts = 477.575745 last_seq = 618 current_ts = 477.593048 current_received_ts = 477.592377 current_seq = 619 count = 503 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 61us (kms_flip:7842) DEBUG: name = flip last_ts = 477.593048 last_received_ts = 477.592377 last_seq = 619 current_ts = 477.609711 current_received_ts = 477.609070 current_seq = 620 count = 504 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 64us (kms_flip:7842) DEBUG: name = flip last_ts = 477.609711 last_received_ts = 477.609070 last_seq = 620 current_ts = 477.626373 current_received_ts = 477.625702 current_seq = 621 count = 505 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 68us (kms_flip:7842) DEBUG: name = flip last_ts = 477.626373 last_received_ts = 477.625702 last_seq = 621 current_ts = 477.643036 current_received_ts = 477.642334 current_seq = 622 count = 506 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 54us (kms_flip:7842) DEBUG: name = flip last_ts = 477.643036 last_received_ts = 477.642334 last_seq = 622 current_ts = 477.659698 current_received_ts = 477.658936 current_seq = 623 count = 507 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 53us (kms_flip:7842) DEBUG: name = flip last_ts = 477.659698 last_received_ts = 477.658936 last_seq = 623 current_ts = 477.676361 current_received_ts = 477.675629 current_seq = 624 count = 508 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 115us (kms_flip:7842) DEBUG: name = flip last_ts = 477.676361 last_received_ts = 477.675629 last_seq = 624 current_ts = 477.693024 current_received_ts = 477.692352 current_seq = 625 count = 509 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 78us (kms_flip:7842) DEBUG: name = flip last_ts = 477.693024 last_received_ts = 477.692352 last_seq = 625 current_ts = 477.709686 current_received_ts = 477.709015 current_seq = 626 count = 510 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 69us (kms_flip:7842) DEBUG: name = flip last_ts = 477.709686 last_received_ts = 477.709015 last_seq = 626 current_ts = 477.726318 current_received_ts = 477.725708 current_seq = 627 count = 511 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 71us (kms_flip:7842) DEBUG: name = flip last_ts = 477.726318 last_received_ts = 477.725708 last_seq = 627 current_ts = 477.742981 current_received_ts = 477.742249 current_seq = 628 count = 512 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 63us (kms_flip:7842) DEBUG: name = flip last_ts = 477.742981 last_received_ts = 477.742249 last_seq = 628 current_ts = 477.759644 current_received_ts = 477.759064 current_seq = 629 count = 513 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 62us (kms_flip:7842) DEBUG: name = flip last_ts = 477.759644 last_received_ts = 477.759064 last_seq = 629 current_ts = 477.776306 current_received_ts = 477.775726 current_seq = 630 count = 514 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 68us (kms_flip:7842) DEBUG: name = flip last_ts = 477.776306 last_received_ts = 477.775726 last_seq = 630 current_ts = 477.792969 current_received_ts = 477.792389 current_seq = 631 count = 515 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 63us (kms_flip:7842) DEBUG: name = flip last_ts = 477.792969 last_received_ts = 477.792389 last_seq = 631 current_ts = 477.809601 current_received_ts = 477.809052 current_seq = 632 count = 516 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 63us (kms_flip:7842) DEBUG: name = flip last_ts = 477.809601 last_received_ts = 477.809052 last_seq = 632 current_ts = 477.826263 current_received_ts = 477.825684 current_seq = 633 count = 517 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 63us (kms_flip:7842) DEBUG: name = flip last_ts = 477.826263 last_received_ts = 477.825684 last_seq = 633 current_ts = 477.842926 current_received_ts = 477.842316 current_seq = 634 count = 518 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 40us (kms_flip:7842) DEBUG: name = flip last_ts = 477.842926 last_received_ts = 477.842316 last_seq = 634 current_ts = 477.859589 current_received_ts = 477.858856 current_seq = 635 count = 519 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 64us (kms_flip:7842) DEBUG: name = flip last_ts = 477.859589 last_received_ts = 477.858856 last_seq = 635 current_ts = 477.876251 current_received_ts = 477.875641 current_seq = 636 count = 520 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 63us (kms_flip:7842) DEBUG: name = flip last_ts = 477.876251 last_received_ts = 477.875641 last_seq = 636 current_ts = 477.892914 current_received_ts = 477.892334 current_seq = 637 count = 521 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 40us (kms_flip:7842) DEBUG: name = flip last_ts = 477.892914 last_received_ts = 477.892334 last_seq = 637 current_ts = 477.909576 current_received_ts = 477.908997 current_seq = 638 count = 522 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 40us (kms_flip:7842) DEBUG: name = flip last_ts = 477.909576 last_received_ts = 477.908997 last_seq = 638 current_ts = 477.926239 current_received_ts = 477.925659 current_seq = 639 count = 523 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 64us (kms_flip:7842) DEBUG: name = flip last_ts = 477.926239 last_received_ts = 477.925659 last_seq = 639 current_ts = 477.942871 current_received_ts = 477.942230 current_seq = 640 count = 524 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 70us (kms_flip:7842) DEBUG: name = flip last_ts = 477.942871 last_received_ts = 477.942230 last_seq = 640 current_ts = 477.959534 current_received_ts = 477.958893 current_seq = 641 count = 525 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 61us (kms_flip:7842) DEBUG: name = flip last_ts = 477.959534 last_received_ts = 477.958893 last_seq = 641 current_ts = 477.976196 current_received_ts = 477.975647 current_seq = 642 count = 526 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 45us (kms_flip:7842) DEBUG: name = flip last_ts = 477.976196 last_received_ts = 477.975647 last_seq = 642 current_ts = 477.992859 current_received_ts = 477.992188 current_seq = 643 count = 527 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 68us (kms_flip:7842) DEBUG: name = flip last_ts = 477.992859 last_received_ts = 477.992188 last_seq = 643 current_ts = 478.009491 current_received_ts = 478.008881 current_seq = 644 count = 528 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 77us (kms_flip:7842) DEBUG: name = flip last_ts = 478.009491 last_received_ts = 478.008881 last_seq = 644 current_ts = 478.026184 current_received_ts = 478.025543 current_seq = 645 count = 529 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 70us (kms_flip:7842) DEBUG: name = flip last_ts = 478.026184 last_received_ts = 478.025543 last_seq = 645 current_ts = 478.042816 current_received_ts = 478.042236 current_seq = 646 count = 530 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 47us (kms_flip:7842) DEBUG: name = flip last_ts = 478.042816 last_received_ts = 478.042236 last_seq = 646 current_ts = 478.059479 current_received_ts = 478.058868 current_seq = 647 count = 531 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 64us (kms_flip:7842) DEBUG: name = flip last_ts = 478.059479 last_received_ts = 478.058868 last_seq = 647 current_ts = 478.076141 current_received_ts = 478.075562 current_seq = 648 count = 532 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 149us (kms_flip:7842) DEBUG: name = flip last_ts = 478.076141 last_received_ts = 478.075562 last_seq = 648 current_ts = 478.092804 current_received_ts = 478.092041 current_seq = 649 count = 533 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 69us (kms_flip:7842) DEBUG: name = flip last_ts = 478.092804 last_received_ts = 478.092041 last_seq = 649 current_ts = 478.109467 current_received_ts = 478.108795 current_seq = 650 count = 534 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 60us (kms_flip:7842) DEBUG: name = flip last_ts = 478.109467 last_received_ts = 478.108795 last_seq = 650 current_ts = 478.126129 current_received_ts = 478.125427 current_seq = 651 count = 535 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 56us (kms_flip:7842) DEBUG: name = flip last_ts = 478.126129 last_received_ts = 478.125427 last_seq = 651 current_ts = 478.142761 current_received_ts = 478.142059 current_seq = 652 count = 536 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 58us (kms_flip:7842) DEBUG: name = flip last_ts = 478.142761 last_received_ts = 478.142059 last_seq = 652 current_ts = 478.159424 current_received_ts = 478.158875 current_seq = 653 count = 537 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 67us (kms_flip:7842) DEBUG: name = flip last_ts = 478.159424 last_received_ts = 478.158875 last_seq = 653 current_ts = 478.176086 current_received_ts = 478.175323 current_seq = 654 count = 538 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 121us (kms_flip:7842) DEBUG: name = flip last_ts = 478.176086 last_received_ts = 478.175323 last_seq = 654 current_ts = 478.192749 current_received_ts = 478.191956 current_seq = 655 count = 539 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 70us (kms_flip:7842) DEBUG: name = flip last_ts = 478.192749 last_received_ts = 478.191956 last_seq = 655 current_ts = 478.209412 current_received_ts = 478.208740 current_seq = 656 count = 540 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 59us (kms_flip:7842) DEBUG: name = flip last_ts = 478.209412 last_received_ts = 478.208740 last_seq = 656 current_ts = 478.226074 current_received_ts = 478.225372 current_seq = 657 count = 541 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 51us (kms_flip:7842) DEBUG: name = flip last_ts = 478.226074 last_received_ts = 478.225372 last_seq = 657 current_ts = 478.242706 current_received_ts = 478.242035 current_seq = 658 count = 542 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 39us (kms_flip:7842) DEBUG: name = flip last_ts = 478.242706 last_received_ts = 478.242035 last_seq = 658 current_ts = 478.259369 current_received_ts = 478.258698 current_seq = 659 count = 543 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 45us (kms_flip:7842) DEBUG: name = flip last_ts = 478.259369 last_received_ts = 478.258698 last_seq = 659 current_ts = 478.276031 current_received_ts = 478.275360 current_seq = 660 count = 544 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 55us (kms_flip:7842) DEBUG: name = flip last_ts = 478.276031 last_received_ts = 478.275360 last_seq = 660 current_ts = 478.292694 current_received_ts = 478.292023 current_seq = 661 count = 545 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 57us (kms_flip:7842) DEBUG: name = flip last_ts = 478.292694 last_received_ts = 478.292023 last_seq = 661 current_ts = 478.309357 current_received_ts = 478.308685 current_seq = 662 count = 546 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 50us (kms_flip:7842) DEBUG: name = flip last_ts = 478.309357 last_received_ts = 478.308685 last_seq = 662 current_ts = 478.326019 current_received_ts = 478.325287 current_seq = 663 count = 547 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 45us (kms_flip:7842) DEBUG: name = flip last_ts = 478.326019 last_received_ts = 478.325287 last_seq = 663 current_ts = 478.342682 current_received_ts = 478.341980 current_seq = 664 count = 548 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 80us (kms_flip:7842) DEBUG: name = flip last_ts = 478.342682 last_received_ts = 478.341980 last_seq = 664 current_ts = 478.359314 current_received_ts = 478.358673 current_seq = 665 count = 549 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 48us (kms_flip:7842) DEBUG: name = flip last_ts = 478.359314 last_received_ts = 478.358673 last_seq = 665 current_ts = 478.375977 current_received_ts = 478.375305 current_seq = 666 count = 550 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 62us (kms_flip:7842) DEBUG: name = flip last_ts = 478.375977 last_received_ts = 478.375305 last_seq = 666 current_ts = 478.392639 current_received_ts = 478.391968 current_seq = 667 count = 551 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 81us (kms_flip:7842) DEBUG: name = flip last_ts = 478.392639 last_received_ts = 478.391968 last_seq = 667 current_ts = 478.409302 current_received_ts = 478.408630 current_seq = 668 count = 552 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 55us (kms_flip:7842) DEBUG: name = flip last_ts = 478.409302 last_received_ts = 478.408630 last_seq = 668 current_ts = 478.425964 current_received_ts = 478.425262 current_seq = 669 count = 553 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 55us (kms_flip:7842) DEBUG: name = flip last_ts = 478.425964 last_received_ts = 478.425262 last_seq = 669 current_ts = 478.442627 current_received_ts = 478.441925 current_seq = 670 count = 554 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 53us (kms_flip:7842) DEBUG: name = flip last_ts = 478.442627 last_received_ts = 478.441925 last_seq = 670 current_ts = 478.459259 current_received_ts = 478.458496 current_seq = 671 count = 555 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 45us (kms_flip:7842) DEBUG: name = flip last_ts = 478.459259 last_received_ts = 478.458496 last_seq = 671 current_ts = 478.475922 current_received_ts = 478.475128 current_seq = 672 count = 556 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 56us (kms_flip:7842) DEBUG: name = flip last_ts = 478.475922 last_received_ts = 478.475128 last_seq = 672 current_ts = 478.492584 current_received_ts = 478.491913 current_seq = 673 count = 557 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 52us (kms_flip:7842) DEBUG: name = flip last_ts = 478.492584 last_received_ts = 478.491913 last_seq = 673 current_ts = 478.509247 current_received_ts = 478.508545 current_seq = 674 count = 558 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 53us (kms_flip:7842) DEBUG: name = flip last_ts = 478.509247 last_received_ts = 478.508545 last_seq = 674 current_ts = 478.525909 current_received_ts = 478.525116 current_seq = 675 count = 559 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 53us (kms_flip:7842) DEBUG: name = flip last_ts = 478.525909 last_received_ts = 478.525116 last_seq = 675 current_ts = 478.542572 current_received_ts = 478.541809 current_seq = 676 count = 560 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 50us (kms_flip:7842) DEBUG: name = flip last_ts = 478.542572 last_received_ts = 478.541809 last_seq = 676 current_ts = 478.559235 current_received_ts = 478.558411 current_seq = 677 count = 561 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 49us (kms_flip:7842) DEBUG: name = flip last_ts = 478.559235 last_received_ts = 478.558411 last_seq = 677 current_ts = 478.575867 current_received_ts = 478.575287 current_seq = 678 count = 562 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 79us (kms_flip:7842) DEBUG: name = flip last_ts = 478.575867 last_received_ts = 478.575287 last_seq = 678 current_ts = 478.592529 current_received_ts = 478.591736 current_seq = 679 count = 563 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 55us (kms_flip:7842) DEBUG: name = flip last_ts = 478.592529 last_received_ts = 478.591736 last_seq = 679 current_ts = 478.609192 current_received_ts = 478.608398 current_seq = 680 count = 564 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 60us (kms_flip:7842) DEBUG: name = flip last_ts = 478.609192 last_received_ts = 478.608398 last_seq = 680 current_ts = 478.625854 current_received_ts = 478.625153 current_seq = 681 count = 565 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 51us (kms_flip:7842) DEBUG: name = flip last_ts = 478.625854 last_received_ts = 478.625153 last_seq = 681 current_ts = 478.642517 current_received_ts = 478.641815 current_seq = 682 count = 566 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 56us (kms_flip:7842) DEBUG: name = flip last_ts = 478.642517 last_received_ts = 478.641815 last_seq = 682 current_ts = 478.659149 current_received_ts = 478.658478 current_seq = 683 count = 567 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 54us (kms_flip:7842) DEBUG: name = flip last_ts = 478.659149 last_received_ts = 478.658478 last_seq = 683 current_ts = 478.675812 current_received_ts = 478.675140 current_seq = 684 count = 568 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 47us (kms_flip:7842) DEBUG: name = flip last_ts = 478.675812 last_received_ts = 478.675140 last_seq = 684 current_ts = 478.692474 current_received_ts = 478.691803 current_seq = 685 count = 569 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 55us (kms_flip:7842) DEBUG: name = flip last_ts = 478.692474 last_received_ts = 478.691803 last_seq = 685 current_ts = 478.709137 current_received_ts = 478.708435 current_seq = 686 count = 570 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 54us (kms_flip:7842) DEBUG: name = flip last_ts = 478.709137 last_received_ts = 478.708435 last_seq = 686 current_ts = 478.725800 current_received_ts = 478.725098 current_seq = 687 count = 571 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 54us (kms_flip:7842) DEBUG: name = flip last_ts = 478.725800 last_received_ts = 478.725098 last_seq = 687 current_ts = 478.742462 current_received_ts = 478.741669 current_seq = 688 count = 572 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 54us (kms_flip:7842) DEBUG: name = flip last_ts = 478.742462 last_received_ts = 478.741669 last_seq = 688 current_ts = 478.759125 current_received_ts = 478.758423 current_seq = 689 count = 573 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 39us (kms_flip:7842) DEBUG: name = flip last_ts = 478.759125 last_received_ts = 478.758423 last_seq = 689 current_ts = 478.775757 current_received_ts = 478.775055 current_seq = 690 count = 574 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 44us (kms_flip:7842) DEBUG: name = flip last_ts = 478.775757 last_received_ts = 478.775055 last_seq = 690 current_ts = 478.792419 current_received_ts = 478.791748 current_seq = 691 count = 575 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 54us (kms_flip:7842) DEBUG: name = flip last_ts = 478.792419 last_received_ts = 478.791748 last_seq = 691 current_ts = 478.809082 current_received_ts = 478.808411 current_seq = 692 count = 576 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 43us (kms_flip:7842) DEBUG: name = flip last_ts = 478.809082 last_received_ts = 478.808411 last_seq = 692 current_ts = 478.825745 current_received_ts = 478.825073 current_seq = 693 count = 577 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 54us (kms_flip:7842) DEBUG: name = flip last_ts = 478.825745 last_received_ts = 478.825073 last_seq = 693 current_ts = 478.842407 current_received_ts = 478.841705 current_seq = 694 count = 578 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 55us (kms_flip:7842) DEBUG: name = flip last_ts = 478.842407 last_received_ts = 478.841705 last_seq = 694 current_ts = 478.859070 current_received_ts = 478.858368 current_seq = 695 count = 579 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 55us (kms_flip:7842) DEBUG: name = flip last_ts = 478.859070 last_received_ts = 478.858368 last_seq = 695 current_ts = 478.875702 current_received_ts = 478.874939 current_seq = 696 count = 580 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 42us (kms_flip:7842) DEBUG: name = flip last_ts = 478.875702 last_received_ts = 478.874939 last_seq = 696 current_ts = 478.892365 current_received_ts = 478.891663 current_seq = 697 count = 581 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 56us (kms_flip:7842) DEBUG: name = flip last_ts = 478.892365 last_received_ts = 478.891663 last_seq = 697 current_ts = 478.909027 current_received_ts = 478.908356 current_seq = 698 count = 582 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 58us (kms_flip:7842) DEBUG: name = flip last_ts = 478.909027 last_received_ts = 478.908356 last_seq = 698 current_ts = 478.925690 current_received_ts = 478.924927 current_seq = 699 count = 583 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 82us (kms_flip:7842) DEBUG: name = flip last_ts = 478.925690 last_received_ts = 478.924927 last_seq = 699 current_ts = 478.942352 current_received_ts = 478.941650 current_seq = 700 count = 584 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 54us (kms_flip:7842) DEBUG: name = flip last_ts = 478.942352 last_received_ts = 478.941650 last_seq = 700 current_ts = 478.959015 current_received_ts = 478.958344 current_seq = 701 count = 585 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 56us (kms_flip:7842) DEBUG: name = flip last_ts = 478.959015 last_received_ts = 478.958344 last_seq = 701 current_ts = 478.975647 current_received_ts = 478.974976 current_seq = 702 count = 586 seq_step = 1 (kms_flip:7842) DEBUG: Vblank took 620us (kms_flip:7842) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:7842) CRITICAL: Failed assertion: end - start < 500 (kms_flip:7842) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:7842) igt_core-INFO: Stack trace: (kms_flip:7842) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:7842) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:7842) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:7842) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() (kms_flip:7842) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:7842) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:7842) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:7842) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (11.096s)
Dmesg	<6> [542.655054] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [542.658573] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:433] <7> [542.660167] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:434] <7> [542.742688] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [542.742873] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [542.743035] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [542.743158] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [542.743271] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [542.743382] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [542.743494] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [542.743604] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [542.743713] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [542.743931] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [542.744041] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [542.744149] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [542.744258] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [542.744365] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [542.744472] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [542.744580] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [542.744688] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [542.744802] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [542.744908] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [542.745013] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [542.745117] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [542.745221] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [542.745326] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [542.745431] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [542.745536] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [542.745641] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [542.745754] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [542.745863] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [542.745967] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [542.746072] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [542.746176] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [542.746280] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [542.746384] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [542.746489] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [542.746593] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [542.746699] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [542.746809] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [542.746913] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [542.747016] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [542.747123] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [542.747228] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [542.747400] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [542.747492] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [542.747605] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0 <7> [542.747683] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [542.747764] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm <7> [542.747839] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [542.747913] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [542.747986] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [542.748076] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [542.748198] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400 <7> [542.748315] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400 <7> [542.748430] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [542.748544] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [542.748658] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [542.748892] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [542.749034] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [542.749152] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [542.749269] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [542.749384] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [542.749543] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [542.749663] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [542.750077] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [542.750215] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [542.750328] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [542.750441] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [542.750556] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [542.750778] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [542.751521] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [542.751699] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [542.752042] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [542.752210] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006f <7> [542.752869] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [542.753012] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [542.957875] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [542.958486] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [542.970206] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [542.970485] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [542.970759] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [542.970644] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [542.971262] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [543.023098] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [543.023568] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [543.031250] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [543.031578] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [543.031612] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [543.032150] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [543.033063] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [543.033525] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [543.034025] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [543.034345] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [543.034645] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [543.034963] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [543.035256] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [543.035548] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [543.035855] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [543.036148] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [543.036437] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [543.036725] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [543.037033] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [543.037323] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [543.037609] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [543.037913] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [543.038285] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [543.038560] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [543.038824] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [543.039328] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [543.039709] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [543.040189] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [543.040529] 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> [543.040978] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [543.041276] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [543.042658] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [543.043163] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [543.043530] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [543.043623] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [543.043903] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [543.044304] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [543.044620] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [543.044953] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [543.045262] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [543.045560] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [543.045849] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [543.046107] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [543.046371] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [543.046614] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [543.046877] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [543.047106] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [543.047327] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [543.047541] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [543.047750] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [543.047967] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [543.048166] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [543.048361] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [543.048552] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [543.048734] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [543.048921] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [543.049092] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [543.049258] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [543.049428] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [543.049589] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [543.049745] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [543.050071] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [543.050222] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [543.050370] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [543.050510] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [543.050647] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [543.050778] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [543.050923] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [543.051054] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [543.051183] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [543.051304] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [543.051425] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [543.051547] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [543.051664] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [543.051780] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [543.051903] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [543.052018] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [543.052123] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [543.052229] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [543.052408] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [543.052498] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [543.052615] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [543.052693] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:264:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [543.052769] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [543.052849] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [543.052932] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [543.053009] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [543.053112] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [543.053234] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [543.053348] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [543.053462] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [543.053576] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [543.053689] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [543.053803] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [543.053963] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [543.054083] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [543.054194] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [543.054305] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [543.054449] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [543.054552] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [543.054661] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [543.054782] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [543.054907] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [543.055024] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [543.055136] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [543.055248] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [543.055360] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [543.055472] 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> [543.055585] 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> [543.055697] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [543.055808] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [543.055928] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [543.056044] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [543.056158] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [543.056271] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [543.056386] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [543.056497] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [543.056611] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [543.056723] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [543.056835] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [543.056958] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [543.057071] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [543.057184] 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> [543.057298] 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> [543.057410] 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> [543.057522] 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> [543.057635] 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> [543.057745] 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> [543.057868] 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> [543.057985] 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> [543.058100] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0 <7> [543.058212] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [543.058326] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [543.058437] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [543.058549] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [543.058660] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [543.058770] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [543.058891] 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> [543.059008] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [543.059119] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [543.059230] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [543.059341] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [543.059451] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [543.059502] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [543.059562] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [543.059607] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [543.059686] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [543.059676] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [543.059777] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [543.059792] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [543.059913] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [543.060025] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [543.060136] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [543.060246] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [543.060356] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [543.060465] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [543.060575] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [543.060686] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [543.060799] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [543.060939] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [543.060941] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [543.061053] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [543.061089] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [543.061165] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [543.061209] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [543.061276] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [543.061357] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [543.061387] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:433] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [543.061500] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [543.061612] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [543.061723] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [543.061835] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [543.061959] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [543.062072] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [543.062183] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [543.062759] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [543.062902] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [543.063165] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [543.063338] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [543.063502] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [543.063675] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [543.063807] 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> [543.063950] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [543.064065] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [543.064182] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [543.064275] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [543.064364] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [543.064449] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [543.064534] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [543.064622] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [543.064709] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [543.064796] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [543.064890] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [543.064977] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [543.065061] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [543.065144] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [543.065227] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [543.065338] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [543.065530] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [543.065616] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [543.065752] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [543.066852] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [543.066962] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [543.069042] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [543.069147] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (463 ms remaining) <7> [543.534111] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [543.634794] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [543.635097] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [543.635377] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [543.671340] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [543.672010] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [543.672613] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [543.673221] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [543.845649] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [543.845963] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [543.846290] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [543.848368] 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> [543.849892] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [543.850658] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [543.851782] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [543.853060] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [543.854178] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [543.854510] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [543.855977] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [543.856320] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [543.857082] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [543.857603] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [543.857947] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [543.858391] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [543.891199] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [543.892880] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [543.893277] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <7> [546.415055] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off <7> [546.415608] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [553.706681] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [553.707061] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [553.707327] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [553.754849] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

11.10 seconds

Hostname

shard-lnl-4

Igt-Version

IGT-Version: 2.4-g3e5747e53 (x86_64) (Linux: 7.1.0-rc2-lgci-xe-xe-5013-b023767ff66180ad4-debug+ x86_64)

Out

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

Err

Starting dynamic subtest: B-eDP1
(kms_flip:7842) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:7842) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7842) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:7842) DEBUG: Vblank took 55us
(kms_flip:7842) DEBUG: name = flip
last_ts = 476.960083
last_received_ts = 476.959381
last_seq = 581
current_ts = 476.976715
current_received_ts = 476.976044
current_seq = 582
count = 466
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 51us
(kms_flip:7842) DEBUG: name = flip
last_ts = 476.976715
last_received_ts = 476.976044
last_seq = 582
current_ts = 476.993378
current_received_ts = 476.992706
current_seq = 583
count = 467
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 63us
(kms_flip:7842) DEBUG: name = flip
last_ts = 476.993378
last_received_ts = 476.992706
last_seq = 583
current_ts = 477.010040
current_received_ts = 477.009338
current_seq = 584
count = 468
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 45us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.010040
last_received_ts = 477.009338
last_seq = 584
current_ts = 477.026703
current_received_ts = 477.026031
current_seq = 585
count = 469
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 57us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.026703
last_received_ts = 477.026031
last_seq = 585
current_ts = 477.043365
current_received_ts = 477.042664
current_seq = 586
count = 470
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 53us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.043365
last_received_ts = 477.042664
last_seq = 586
current_ts = 477.060028
current_received_ts = 477.059326
current_seq = 587
count = 471
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 56us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.060028
last_received_ts = 477.059326
last_seq = 587
current_ts = 477.076660
current_received_ts = 477.075989
current_seq = 588
count = 472
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 76us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.076660
last_received_ts = 477.075989
last_seq = 588
current_ts = 477.093323
current_received_ts = 477.092651
current_seq = 589
count = 473
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 44us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.093323
last_received_ts = 477.092651
last_seq = 589
current_ts = 477.109985
current_received_ts = 477.109314
current_seq = 590
count = 474
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 43us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.109985
last_received_ts = 477.109314
last_seq = 590
current_ts = 477.126648
current_received_ts = 477.125977
current_seq = 591
count = 475
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 68us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.126648
last_received_ts = 477.125977
last_seq = 591
current_ts = 477.143311
current_received_ts = 477.142609
current_seq = 592
count = 476
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 59us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.143311
last_received_ts = 477.142609
last_seq = 592
current_ts = 477.159973
current_received_ts = 477.159271
current_seq = 593
count = 477
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 42us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.159973
last_received_ts = 477.159271
last_seq = 593
current_ts = 477.176605
current_received_ts = 477.175934
current_seq = 594
count = 478
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 74us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.176605
last_received_ts = 477.175934
last_seq = 594
current_ts = 477.193268
current_received_ts = 477.192566
current_seq = 595
count = 479
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 52us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.193268
last_received_ts = 477.192566
last_seq = 595
current_ts = 477.209930
current_received_ts = 477.209259
current_seq = 596
count = 480
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 45us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.209930
last_received_ts = 477.209259
last_seq = 596
current_ts = 477.226593
current_received_ts = 477.225861
current_seq = 597
count = 481
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 54us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.226593
last_received_ts = 477.225861
last_seq = 597
current_ts = 477.243256
current_received_ts = 477.242554
current_seq = 598
count = 482
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 53us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.243256
last_received_ts = 477.242554
last_seq = 598
current_ts = 477.259918
current_received_ts = 477.259125
current_seq = 599
count = 483
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 54us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.259918
last_received_ts = 477.259125
last_seq = 599
current_ts = 477.276581
current_received_ts = 477.275879
current_seq = 600
count = 484
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 43us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.276581
last_received_ts = 477.275879
last_seq = 600
current_ts = 477.293213
current_received_ts = 477.292542
current_seq = 601
count = 485
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 56us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.293213
last_received_ts = 477.292542
last_seq = 601
current_ts = 477.309875
current_received_ts = 477.309174
current_seq = 602
count = 486
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 55us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.309875
last_received_ts = 477.309174
last_seq = 602
current_ts = 477.326538
current_received_ts = 477.325836
current_seq = 603
count = 487
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 43us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.326538
last_received_ts = 477.325836
last_seq = 603
current_ts = 477.343201
current_received_ts = 477.342499
current_seq = 604
count = 488
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 73us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.343201
last_received_ts = 477.342499
last_seq = 604
current_ts = 477.359863
current_received_ts = 477.359070
current_seq = 605
count = 489
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 49us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.359863
last_received_ts = 477.359070
last_seq = 605
current_ts = 477.376495
current_received_ts = 477.375702
current_seq = 606
count = 490
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 56us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.376495
last_received_ts = 477.375702
last_seq = 606
current_ts = 477.393188
current_received_ts = 477.392517
current_seq = 607
count = 491
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 55us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.393188
last_received_ts = 477.392517
last_seq = 607
current_ts = 477.409821
current_received_ts = 477.409149
current_seq = 608
count = 492
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 67us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.409821
last_received_ts = 477.409149
last_seq = 608
current_ts = 477.426483
current_received_ts = 477.425812
current_seq = 609
count = 493
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 81us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.426483
last_received_ts = 477.425812
last_seq = 609
current_ts = 477.443146
current_received_ts = 477.442505
current_seq = 610
count = 494
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 105us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.443146
last_received_ts = 477.442505
last_seq = 610
current_ts = 477.459808
current_received_ts = 477.459167
current_seq = 611
count = 495
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 134us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.459808
last_received_ts = 477.459167
last_seq = 611
current_ts = 477.476471
current_received_ts = 477.475891
current_seq = 612
count = 496
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 76us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.476471
last_received_ts = 477.475891
last_seq = 612
current_ts = 477.493134
current_received_ts = 477.492371
current_seq = 613
count = 497
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 47us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.493134
last_received_ts = 477.492371
last_seq = 613
current_ts = 477.509766
current_received_ts = 477.509125
current_seq = 614
count = 498
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 82us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.509766
last_received_ts = 477.509125
last_seq = 614
current_ts = 477.526428
current_received_ts = 477.525879
current_seq = 615
count = 499
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 53us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.526428
last_received_ts = 477.525879
last_seq = 615
current_ts = 477.543091
current_received_ts = 477.542480
current_seq = 616
count = 500
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 157us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.543091
last_received_ts = 477.542480
last_seq = 616
current_ts = 477.559753
current_received_ts = 477.559113
current_seq = 617
count = 501
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 80us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.559753
last_received_ts = 477.559113
last_seq = 617
current_ts = 477.576416
current_received_ts = 477.575745
current_seq = 618
count = 502
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 60us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.576416
last_received_ts = 477.575745
last_seq = 618
current_ts = 477.593048
current_received_ts = 477.592377
current_seq = 619
count = 503
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 61us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.593048
last_received_ts = 477.592377
last_seq = 619
current_ts = 477.609711
current_received_ts = 477.609070
current_seq = 620
count = 504
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 64us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.609711
last_received_ts = 477.609070
last_seq = 620
current_ts = 477.626373
current_received_ts = 477.625702
current_seq = 621
count = 505
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 68us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.626373
last_received_ts = 477.625702
last_seq = 621
current_ts = 477.643036
current_received_ts = 477.642334
current_seq = 622
count = 506
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 54us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.643036
last_received_ts = 477.642334
last_seq = 622
current_ts = 477.659698
current_received_ts = 477.658936
current_seq = 623
count = 507
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 53us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.659698
last_received_ts = 477.658936
last_seq = 623
current_ts = 477.676361
current_received_ts = 477.675629
current_seq = 624
count = 508
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 115us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.676361
last_received_ts = 477.675629
last_seq = 624
current_ts = 477.693024
current_received_ts = 477.692352
current_seq = 625
count = 509
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 78us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.693024
last_received_ts = 477.692352
last_seq = 625
current_ts = 477.709686
current_received_ts = 477.709015
current_seq = 626
count = 510
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 69us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.709686
last_received_ts = 477.709015
last_seq = 626
current_ts = 477.726318
current_received_ts = 477.725708
current_seq = 627
count = 511
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 71us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.726318
last_received_ts = 477.725708
last_seq = 627
current_ts = 477.742981
current_received_ts = 477.742249
current_seq = 628
count = 512
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 63us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.742981
last_received_ts = 477.742249
last_seq = 628
current_ts = 477.759644
current_received_ts = 477.759064
current_seq = 629
count = 513
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 62us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.759644
last_received_ts = 477.759064
last_seq = 629
current_ts = 477.776306
current_received_ts = 477.775726
current_seq = 630
count = 514
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 68us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.776306
last_received_ts = 477.775726
last_seq = 630
current_ts = 477.792969
current_received_ts = 477.792389
current_seq = 631
count = 515
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 63us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.792969
last_received_ts = 477.792389
last_seq = 631
current_ts = 477.809601
current_received_ts = 477.809052
current_seq = 632
count = 516
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 63us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.809601
last_received_ts = 477.809052
last_seq = 632
current_ts = 477.826263
current_received_ts = 477.825684
current_seq = 633
count = 517
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 63us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.826263
last_received_ts = 477.825684
last_seq = 633
current_ts = 477.842926
current_received_ts = 477.842316
current_seq = 634
count = 518
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 40us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.842926
last_received_ts = 477.842316
last_seq = 634
current_ts = 477.859589
current_received_ts = 477.858856
current_seq = 635
count = 519
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 64us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.859589
last_received_ts = 477.858856
last_seq = 635
current_ts = 477.876251
current_received_ts = 477.875641
current_seq = 636
count = 520
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 63us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.876251
last_received_ts = 477.875641
last_seq = 636
current_ts = 477.892914
current_received_ts = 477.892334
current_seq = 637
count = 521
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 40us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.892914
last_received_ts = 477.892334
last_seq = 637
current_ts = 477.909576
current_received_ts = 477.908997
current_seq = 638
count = 522
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 40us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.909576
last_received_ts = 477.908997
last_seq = 638
current_ts = 477.926239
current_received_ts = 477.925659
current_seq = 639
count = 523
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 64us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.926239
last_received_ts = 477.925659
last_seq = 639
current_ts = 477.942871
current_received_ts = 477.942230
current_seq = 640
count = 524
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 70us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.942871
last_received_ts = 477.942230
last_seq = 640
current_ts = 477.959534
current_received_ts = 477.958893
current_seq = 641
count = 525
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 61us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.959534
last_received_ts = 477.958893
last_seq = 641
current_ts = 477.976196
current_received_ts = 477.975647
current_seq = 642
count = 526
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 45us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.976196
last_received_ts = 477.975647
last_seq = 642
current_ts = 477.992859
current_received_ts = 477.992188
current_seq = 643
count = 527
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 68us
(kms_flip:7842) DEBUG: name = flip
last_ts = 477.992859
last_received_ts = 477.992188
last_seq = 643
current_ts = 478.009491
current_received_ts = 478.008881
current_seq = 644
count = 528
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 77us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.009491
last_received_ts = 478.008881
last_seq = 644
current_ts = 478.026184
current_received_ts = 478.025543
current_seq = 645
count = 529
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 70us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.026184
last_received_ts = 478.025543
last_seq = 645
current_ts = 478.042816
current_received_ts = 478.042236
current_seq = 646
count = 530
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 47us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.042816
last_received_ts = 478.042236
last_seq = 646
current_ts = 478.059479
current_received_ts = 478.058868
current_seq = 647
count = 531
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 64us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.059479
last_received_ts = 478.058868
last_seq = 647
current_ts = 478.076141
current_received_ts = 478.075562
current_seq = 648
count = 532
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 149us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.076141
last_received_ts = 478.075562
last_seq = 648
current_ts = 478.092804
current_received_ts = 478.092041
current_seq = 649
count = 533
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 69us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.092804
last_received_ts = 478.092041
last_seq = 649
current_ts = 478.109467
current_received_ts = 478.108795
current_seq = 650
count = 534
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 60us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.109467
last_received_ts = 478.108795
last_seq = 650
current_ts = 478.126129
current_received_ts = 478.125427
current_seq = 651
count = 535
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 56us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.126129
last_received_ts = 478.125427
last_seq = 651
current_ts = 478.142761
current_received_ts = 478.142059
current_seq = 652
count = 536
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 58us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.142761
last_received_ts = 478.142059
last_seq = 652
current_ts = 478.159424
current_received_ts = 478.158875
current_seq = 653
count = 537
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 67us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.159424
last_received_ts = 478.158875
last_seq = 653
current_ts = 478.176086
current_received_ts = 478.175323
current_seq = 654
count = 538
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 121us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.176086
last_received_ts = 478.175323
last_seq = 654
current_ts = 478.192749
current_received_ts = 478.191956
current_seq = 655
count = 539
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 70us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.192749
last_received_ts = 478.191956
last_seq = 655
current_ts = 478.209412
current_received_ts = 478.208740
current_seq = 656
count = 540
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 59us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.209412
last_received_ts = 478.208740
last_seq = 656
current_ts = 478.226074
current_received_ts = 478.225372
current_seq = 657
count = 541
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 51us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.226074
last_received_ts = 478.225372
last_seq = 657
current_ts = 478.242706
current_received_ts = 478.242035
current_seq = 658
count = 542
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 39us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.242706
last_received_ts = 478.242035
last_seq = 658
current_ts = 478.259369
current_received_ts = 478.258698
current_seq = 659
count = 543
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 45us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.259369
last_received_ts = 478.258698
last_seq = 659
current_ts = 478.276031
current_received_ts = 478.275360
current_seq = 660
count = 544
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 55us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.276031
last_received_ts = 478.275360
last_seq = 660
current_ts = 478.292694
current_received_ts = 478.292023
current_seq = 661
count = 545
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 57us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.292694
last_received_ts = 478.292023
last_seq = 661
current_ts = 478.309357
current_received_ts = 478.308685
current_seq = 662
count = 546
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 50us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.309357
last_received_ts = 478.308685
last_seq = 662
current_ts = 478.326019
current_received_ts = 478.325287
current_seq = 663
count = 547
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 45us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.326019
last_received_ts = 478.325287
last_seq = 663
current_ts = 478.342682
current_received_ts = 478.341980
current_seq = 664
count = 548
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 80us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.342682
last_received_ts = 478.341980
last_seq = 664
current_ts = 478.359314
current_received_ts = 478.358673
current_seq = 665
count = 549
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 48us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.359314
last_received_ts = 478.358673
last_seq = 665
current_ts = 478.375977
current_received_ts = 478.375305
current_seq = 666
count = 550
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 62us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.375977
last_received_ts = 478.375305
last_seq = 666
current_ts = 478.392639
current_received_ts = 478.391968
current_seq = 667
count = 551
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 81us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.392639
last_received_ts = 478.391968
last_seq = 667
current_ts = 478.409302
current_received_ts = 478.408630
current_seq = 668
count = 552
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 55us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.409302
last_received_ts = 478.408630
last_seq = 668
current_ts = 478.425964
current_received_ts = 478.425262
current_seq = 669
count = 553
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 55us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.425964
last_received_ts = 478.425262
last_seq = 669
current_ts = 478.442627
current_received_ts = 478.441925
current_seq = 670
count = 554
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 53us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.442627
last_received_ts = 478.441925
last_seq = 670
current_ts = 478.459259
current_received_ts = 478.458496
current_seq = 671
count = 555
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 45us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.459259
last_received_ts = 478.458496
last_seq = 671
current_ts = 478.475922
current_received_ts = 478.475128
current_seq = 672
count = 556
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 56us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.475922
last_received_ts = 478.475128
last_seq = 672
current_ts = 478.492584
current_received_ts = 478.491913
current_seq = 673
count = 557
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 52us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.492584
last_received_ts = 478.491913
last_seq = 673
current_ts = 478.509247
current_received_ts = 478.508545
current_seq = 674
count = 558
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 53us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.509247
last_received_ts = 478.508545
last_seq = 674
current_ts = 478.525909
current_received_ts = 478.525116
current_seq = 675
count = 559
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 53us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.525909
last_received_ts = 478.525116
last_seq = 675
current_ts = 478.542572
current_received_ts = 478.541809
current_seq = 676
count = 560
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 50us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.542572
last_received_ts = 478.541809
last_seq = 676
current_ts = 478.559235
current_received_ts = 478.558411
current_seq = 677
count = 561
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 49us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.559235
last_received_ts = 478.558411
last_seq = 677
current_ts = 478.575867
current_received_ts = 478.575287
current_seq = 678
count = 562
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 79us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.575867
last_received_ts = 478.575287
last_seq = 678
current_ts = 478.592529
current_received_ts = 478.591736
current_seq = 679
count = 563
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 55us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.592529
last_received_ts = 478.591736
last_seq = 679
current_ts = 478.609192
current_received_ts = 478.608398
current_seq = 680
count = 564
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 60us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.609192
last_received_ts = 478.608398
last_seq = 680
current_ts = 478.625854
current_received_ts = 478.625153
current_seq = 681
count = 565
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 51us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.625854
last_received_ts = 478.625153
last_seq = 681
current_ts = 478.642517
current_received_ts = 478.641815
current_seq = 682
count = 566
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 56us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.642517
last_received_ts = 478.641815
last_seq = 682
current_ts = 478.659149
current_received_ts = 478.658478
current_seq = 683
count = 567
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 54us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.659149
last_received_ts = 478.658478
last_seq = 683
current_ts = 478.675812
current_received_ts = 478.675140
current_seq = 684
count = 568
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 47us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.675812
last_received_ts = 478.675140
last_seq = 684
current_ts = 478.692474
current_received_ts = 478.691803
current_seq = 685
count = 569
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 55us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.692474
last_received_ts = 478.691803
last_seq = 685
current_ts = 478.709137
current_received_ts = 478.708435
current_seq = 686
count = 570
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 54us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.709137
last_received_ts = 478.708435
last_seq = 686
current_ts = 478.725800
current_received_ts = 478.725098
current_seq = 687
count = 571
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 54us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.725800
last_received_ts = 478.725098
last_seq = 687
current_ts = 478.742462
current_received_ts = 478.741669
current_seq = 688
count = 572
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 54us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.742462
last_received_ts = 478.741669
last_seq = 688
current_ts = 478.759125
current_received_ts = 478.758423
current_seq = 689
count = 573
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 39us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.759125
last_received_ts = 478.758423
last_seq = 689
current_ts = 478.775757
current_received_ts = 478.775055
current_seq = 690
count = 574
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 44us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.775757
last_received_ts = 478.775055
last_seq = 690
current_ts = 478.792419
current_received_ts = 478.791748
current_seq = 691
count = 575
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 54us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.792419
last_received_ts = 478.791748
last_seq = 691
current_ts = 478.809082
current_received_ts = 478.808411
current_seq = 692
count = 576
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 43us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.809082
last_received_ts = 478.808411
last_seq = 692
current_ts = 478.825745
current_received_ts = 478.825073
current_seq = 693
count = 577
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 54us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.825745
last_received_ts = 478.825073
last_seq = 693
current_ts = 478.842407
current_received_ts = 478.841705
current_seq = 694
count = 578
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 55us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.842407
last_received_ts = 478.841705
last_seq = 694
current_ts = 478.859070
current_received_ts = 478.858368
current_seq = 695
count = 579
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 55us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.859070
last_received_ts = 478.858368
last_seq = 695
current_ts = 478.875702
current_received_ts = 478.874939
current_seq = 696
count = 580
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 42us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.875702
last_received_ts = 478.874939
last_seq = 696
current_ts = 478.892365
current_received_ts = 478.891663
current_seq = 697
count = 581
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 56us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.892365
last_received_ts = 478.891663
last_seq = 697
current_ts = 478.909027
current_received_ts = 478.908356
current_seq = 698
count = 582
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 58us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.909027
last_received_ts = 478.908356
last_seq = 698
current_ts = 478.925690
current_received_ts = 478.924927
current_seq = 699
count = 583
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 82us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.925690
last_received_ts = 478.924927
last_seq = 699
current_ts = 478.942352
current_received_ts = 478.941650
current_seq = 700
count = 584
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 54us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.942352
last_received_ts = 478.941650
last_seq = 700
current_ts = 478.959015
current_received_ts = 478.958344
current_seq = 701
count = 585
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 56us
(kms_flip:7842) DEBUG: name = flip
last_ts = 478.959015
last_received_ts = 478.958344
last_seq = 701
current_ts = 478.975647
current_received_ts = 478.974976
current_seq = 702
count = 586
seq_step = 1
(kms_flip:7842) DEBUG: Vblank took 620us
(kms_flip:7842) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:7842) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7842) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:7842) igt_core-INFO: Stack trace:
(kms_flip:7842) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:7842) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:7842) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:7842) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:7842) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:7842) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7842) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7842) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (11.096s)

Dmesg

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [543.057184] 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> [543.057298] 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> [543.057410] 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> [543.057522] 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> [543.057635] 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> [543.057745] 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> [543.057868] 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> [543.057985] 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> [543.058100] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0

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

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

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

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

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

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

<7> [543.058891] 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> [543.059008] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [543.848368] 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> [543.849892] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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