igt@kms_flip@flip-vs-expired-vblank@b-edp1 on shard-lnl@xe-4315-633f3e5eab13c5bc2d760d1f3db65eb346d9babb Test details

Detail	Value
Duration	9.02 seconds
Hostname	shard-lnl-1
Igt-Version	IGT-Version: 2.3-g943af1354 (x86_64) (Linux: 6.19.0-rc3-lgci-xe-xe-4315-633f3e5eab13c5bc2+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1889 run_test() #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045() #4 ../tests/kms_flip.c:2045 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (9.018s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:4991) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:4991) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:4991) DEBUG: name = flip last_ts = 344.896057 last_received_ts = 344.895447 last_seq = 553 current_ts = 344.912689 current_received_ts = 344.912231 current_seq = 554 count = 342 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 31us (kms_flip:4991) DEBUG: name = flip last_ts = 344.912689 last_received_ts = 344.912231 last_seq = 554 current_ts = 344.929352 current_received_ts = 344.928894 current_seq = 555 count = 343 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 30us (kms_flip:4991) DEBUG: name = flip last_ts = 344.929352 last_received_ts = 344.928894 last_seq = 555 current_ts = 344.945984 current_received_ts = 344.945526 current_seq = 556 count = 344 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 344.945984 last_received_ts = 344.945526 last_seq = 556 current_ts = 344.962646 current_received_ts = 344.962189 current_seq = 557 count = 345 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 81us (kms_flip:4991) DEBUG: name = flip last_ts = 344.962646 last_received_ts = 344.962189 last_seq = 557 current_ts = 344.979309 current_received_ts = 344.978729 current_seq = 558 count = 346 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 90us (kms_flip:4991) DEBUG: name = flip last_ts = 344.979309 last_received_ts = 344.978729 last_seq = 558 current_ts = 344.995941 current_received_ts = 344.995361 current_seq = 559 count = 347 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 112us (kms_flip:4991) DEBUG: name = flip last_ts = 344.995941 last_received_ts = 344.995361 last_seq = 559 current_ts = 345.012604 current_received_ts = 345.012024 current_seq = 560 count = 348 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 30us (kms_flip:4991) DEBUG: name = flip last_ts = 345.012604 last_received_ts = 345.012024 last_seq = 560 current_ts = 345.029236 current_received_ts = 345.028656 current_seq = 561 count = 349 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 88us (kms_flip:4991) DEBUG: name = flip last_ts = 345.029236 last_received_ts = 345.028656 last_seq = 561 current_ts = 345.045898 current_received_ts = 345.045349 current_seq = 562 count = 350 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 84us (kms_flip:4991) DEBUG: name = flip last_ts = 345.045898 last_received_ts = 345.045349 last_seq = 562 current_ts = 345.062531 current_received_ts = 345.062073 current_seq = 563 count = 351 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 30us (kms_flip:4991) DEBUG: name = flip last_ts = 345.062531 last_received_ts = 345.062073 last_seq = 563 current_ts = 345.079193 current_received_ts = 345.078583 current_seq = 564 count = 352 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 32us (kms_flip:4991) DEBUG: name = flip last_ts = 345.079193 last_received_ts = 345.078583 last_seq = 564 current_ts = 345.095825 current_received_ts = 345.095428 current_seq = 565 count = 353 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 32us (kms_flip:4991) DEBUG: name = flip last_ts = 345.095825 last_received_ts = 345.095428 last_seq = 565 current_ts = 345.112488 current_received_ts = 345.111908 current_seq = 566 count = 354 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 345.112488 last_received_ts = 345.111908 last_seq = 566 current_ts = 345.129150 current_received_ts = 345.128693 current_seq = 567 count = 355 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 30us (kms_flip:4991) DEBUG: name = flip last_ts = 345.129150 last_received_ts = 345.128693 last_seq = 567 current_ts = 345.145782 current_received_ts = 345.145294 current_seq = 568 count = 356 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 345.145782 last_received_ts = 345.145294 last_seq = 568 current_ts = 345.162445 current_received_ts = 345.161835 current_seq = 569 count = 357 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 32us (kms_flip:4991) DEBUG: name = flip last_ts = 345.162445 last_received_ts = 345.161835 last_seq = 569 current_ts = 345.179077 current_received_ts = 345.178650 current_seq = 570 count = 358 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 29us (kms_flip:4991) DEBUG: name = flip last_ts = 345.179077 last_received_ts = 345.178650 last_seq = 570 current_ts = 345.195740 current_received_ts = 345.195129 current_seq = 571 count = 359 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 81us (kms_flip:4991) DEBUG: name = flip last_ts = 345.195740 last_received_ts = 345.195129 last_seq = 571 current_ts = 345.212402 current_received_ts = 345.211884 current_seq = 572 count = 360 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 65us (kms_flip:4991) DEBUG: name = flip last_ts = 345.212402 last_received_ts = 345.211884 last_seq = 572 current_ts = 345.229034 current_received_ts = 345.228455 current_seq = 573 count = 361 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 114us (kms_flip:4991) DEBUG: name = flip last_ts = 345.229034 last_received_ts = 345.228455 last_seq = 573 current_ts = 345.245697 current_received_ts = 345.245087 current_seq = 574 count = 362 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 345.245697 last_received_ts = 345.245087 last_seq = 574 current_ts = 345.262329 current_received_ts = 345.261749 current_seq = 575 count = 363 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 90us (kms_flip:4991) DEBUG: name = flip last_ts = 345.262329 last_received_ts = 345.261749 last_seq = 575 current_ts = 345.278992 current_received_ts = 345.278381 current_seq = 576 count = 364 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 345.278992 last_received_ts = 345.278381 last_seq = 576 current_ts = 345.295624 current_received_ts = 345.295074 current_seq = 577 count = 365 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 99us (kms_flip:4991) DEBUG: name = flip last_ts = 345.295624 last_received_ts = 345.295074 last_seq = 577 current_ts = 345.312286 current_received_ts = 345.311707 current_seq = 578 count = 366 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 345.312286 last_received_ts = 345.311707 last_seq = 578 current_ts = 345.328949 current_received_ts = 345.328461 current_seq = 579 count = 367 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 345.328949 last_received_ts = 345.328461 last_seq = 579 current_ts = 345.345581 current_received_ts = 345.345154 current_seq = 580 count = 368 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 29us (kms_flip:4991) DEBUG: name = flip last_ts = 345.345581 last_received_ts = 345.345154 last_seq = 580 current_ts = 345.362244 current_received_ts = 345.361633 current_seq = 581 count = 369 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 30us (kms_flip:4991) DEBUG: name = flip last_ts = 345.362244 last_received_ts = 345.361633 last_seq = 581 current_ts = 345.378876 current_received_ts = 345.378174 current_seq = 582 count = 370 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 345.378876 last_received_ts = 345.378174 last_seq = 582 current_ts = 345.395538 current_received_ts = 345.394928 current_seq = 583 count = 371 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 32us (kms_flip:4991) DEBUG: name = flip last_ts = 345.395538 last_received_ts = 345.394928 last_seq = 583 current_ts = 345.412170 current_received_ts = 345.411591 current_seq = 584 count = 372 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 345.412170 last_received_ts = 345.411591 last_seq = 584 current_ts = 345.428833 current_received_ts = 345.428345 current_seq = 585 count = 373 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 35us (kms_flip:4991) DEBUG: name = flip last_ts = 345.428833 last_received_ts = 345.428345 last_seq = 585 current_ts = 345.445496 current_received_ts = 345.444885 current_seq = 586 count = 374 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 94us (kms_flip:4991) DEBUG: name = flip last_ts = 345.445496 last_received_ts = 345.444885 last_seq = 586 current_ts = 345.462128 current_received_ts = 345.461517 current_seq = 587 count = 375 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 84us (kms_flip:4991) DEBUG: name = flip last_ts = 345.462128 last_received_ts = 345.461517 last_seq = 587 current_ts = 345.478790 current_received_ts = 345.478149 current_seq = 588 count = 376 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 31us (kms_flip:4991) DEBUG: name = flip last_ts = 345.478790 last_received_ts = 345.478149 last_seq = 588 current_ts = 345.495422 current_received_ts = 345.494812 current_seq = 589 count = 377 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 31us (kms_flip:4991) DEBUG: name = flip last_ts = 345.495422 last_received_ts = 345.494812 last_seq = 589 current_ts = 345.512085 current_received_ts = 345.511475 current_seq = 590 count = 378 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 345.512085 last_received_ts = 345.511475 last_seq = 590 current_ts = 345.528717 current_received_ts = 345.528107 current_seq = 591 count = 379 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 345.528717 last_received_ts = 345.528107 last_seq = 591 current_ts = 345.545380 current_received_ts = 345.544769 current_seq = 592 count = 380 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 345.545380 last_received_ts = 345.544769 last_seq = 592 current_ts = 345.562042 current_received_ts = 345.561401 current_seq = 593 count = 381 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 345.562042 last_received_ts = 345.561401 last_seq = 593 current_ts = 345.578674 current_received_ts = 345.578064 current_seq = 594 count = 382 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 345.578674 last_received_ts = 345.578064 last_seq = 594 current_ts = 345.595337 current_received_ts = 345.594757 current_seq = 595 count = 383 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 345.595337 last_received_ts = 345.594757 last_seq = 595 current_ts = 345.611969 current_received_ts = 345.611511 current_seq = 596 count = 384 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 345.611969 last_received_ts = 345.611511 last_seq = 596 current_ts = 345.628632 current_received_ts = 345.628021 current_seq = 597 count = 385 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 32us (kms_flip:4991) DEBUG: name = flip last_ts = 345.628632 last_received_ts = 345.628021 last_seq = 597 current_ts = 345.645264 current_received_ts = 345.644745 current_seq = 598 count = 386 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 106us (kms_flip:4991) DEBUG: name = flip last_ts = 345.645264 last_received_ts = 345.644745 last_seq = 598 current_ts = 345.661926 current_received_ts = 345.661316 current_seq = 599 count = 387 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 31us (kms_flip:4991) DEBUG: name = flip last_ts = 345.661926 last_received_ts = 345.661316 last_seq = 599 current_ts = 345.678589 current_received_ts = 345.677948 current_seq = 600 count = 388 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 44us (kms_flip:4991) DEBUG: name = flip last_ts = 345.678589 last_received_ts = 345.677948 last_seq = 600 current_ts = 345.695221 current_received_ts = 345.694611 current_seq = 601 count = 389 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 345.695221 last_received_ts = 345.694611 last_seq = 601 current_ts = 345.711853 current_received_ts = 345.711273 current_seq = 602 count = 390 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 35us (kms_flip:4991) DEBUG: name = flip last_ts = 345.711853 last_received_ts = 345.711273 last_seq = 602 current_ts = 345.728516 current_received_ts = 345.727905 current_seq = 603 count = 391 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 35us (kms_flip:4991) DEBUG: name = flip last_ts = 345.728516 last_received_ts = 345.727905 last_seq = 603 current_ts = 345.745178 current_received_ts = 345.744385 current_seq = 604 count = 392 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 54us (kms_flip:4991) DEBUG: name = flip last_ts = 345.745178 last_received_ts = 345.744385 last_seq = 604 current_ts = 345.761810 current_received_ts = 345.761078 current_seq = 605 count = 393 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 49us (kms_flip:4991) DEBUG: name = flip last_ts = 345.761810 last_received_ts = 345.761078 last_seq = 605 current_ts = 345.778473 current_received_ts = 345.777863 current_seq = 606 count = 394 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 30us (kms_flip:4991) DEBUG: name = flip last_ts = 345.778473 last_received_ts = 345.777863 last_seq = 606 current_ts = 345.795135 current_received_ts = 345.794525 current_seq = 607 count = 395 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 32us (kms_flip:4991) DEBUG: name = flip last_ts = 345.795135 last_received_ts = 345.794525 last_seq = 607 current_ts = 345.811768 current_received_ts = 345.811157 current_seq = 608 count = 396 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 35us (kms_flip:4991) DEBUG: name = flip last_ts = 345.811768 last_received_ts = 345.811157 last_seq = 608 current_ts = 345.828430 current_received_ts = 345.827850 current_seq = 609 count = 397 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 35us (kms_flip:4991) DEBUG: name = flip last_ts = 345.828430 last_received_ts = 345.827850 last_seq = 609 current_ts = 345.845062 current_received_ts = 345.844421 current_seq = 610 count = 398 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 345.845062 last_received_ts = 345.844421 last_seq = 610 current_ts = 345.861725 current_received_ts = 345.860931 current_seq = 611 count = 399 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 46us (kms_flip:4991) DEBUG: name = flip last_ts = 345.861725 last_received_ts = 345.860931 last_seq = 611 current_ts = 345.878387 current_received_ts = 345.877747 current_seq = 612 count = 400 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 35us (kms_flip:4991) DEBUG: name = flip last_ts = 345.878387 last_received_ts = 345.877747 last_seq = 612 current_ts = 345.895020 current_received_ts = 345.894257 current_seq = 613 count = 401 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 56us (kms_flip:4991) DEBUG: name = flip last_ts = 345.895020 last_received_ts = 345.894257 last_seq = 613 current_ts = 345.911682 current_received_ts = 345.911194 current_seq = 614 count = 402 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 35us (kms_flip:4991) DEBUG: name = flip last_ts = 345.911682 last_received_ts = 345.911194 last_seq = 614 current_ts = 345.928314 current_received_ts = 345.927704 current_seq = 615 count = 403 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 41us (kms_flip:4991) DEBUG: name = flip last_ts = 345.928314 last_received_ts = 345.927704 last_seq = 615 current_ts = 345.944977 current_received_ts = 345.944489 current_seq = 616 count = 404 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 345.944977 last_received_ts = 345.944489 last_seq = 616 current_ts = 345.961639 current_received_ts = 345.961029 current_seq = 617 count = 405 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 345.961639 last_received_ts = 345.961029 last_seq = 617 current_ts = 345.978271 current_received_ts = 345.977814 current_seq = 618 count = 406 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 89us (kms_flip:4991) DEBUG: name = flip last_ts = 345.978271 last_received_ts = 345.977814 last_seq = 618 current_ts = 345.994934 current_received_ts = 345.994293 current_seq = 619 count = 407 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 345.994934 last_received_ts = 345.994293 last_seq = 619 current_ts = 346.011566 current_received_ts = 346.010956 current_seq = 620 count = 408 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 43us (kms_flip:4991) DEBUG: name = flip last_ts = 346.011566 last_received_ts = 346.010956 last_seq = 620 current_ts = 346.028229 current_received_ts = 346.027618 current_seq = 621 count = 409 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 346.028229 last_received_ts = 346.027618 last_seq = 621 current_ts = 346.044861 current_received_ts = 346.044250 current_seq = 622 count = 410 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 32us (kms_flip:4991) DEBUG: name = flip last_ts = 346.044861 last_received_ts = 346.044250 last_seq = 622 current_ts = 346.061523 current_received_ts = 346.060913 current_seq = 623 count = 411 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 31us (kms_flip:4991) DEBUG: name = flip last_ts = 346.061523 last_received_ts = 346.060913 last_seq = 623 current_ts = 346.078186 current_received_ts = 346.077606 current_seq = 624 count = 412 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 94us (kms_flip:4991) DEBUG: name = flip last_ts = 346.078186 last_received_ts = 346.077606 last_seq = 624 current_ts = 346.094818 current_received_ts = 346.094330 current_seq = 625 count = 413 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 59us (kms_flip:4991) DEBUG: name = flip last_ts = 346.094818 last_received_ts = 346.094330 last_seq = 625 current_ts = 346.111481 current_received_ts = 346.111023 current_seq = 626 count = 414 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 96us (kms_flip:4991) DEBUG: name = flip last_ts = 346.111481 last_received_ts = 346.111023 last_seq = 626 current_ts = 346.128113 current_received_ts = 346.127533 current_seq = 627 count = 415 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 36us (kms_flip:4991) DEBUG: name = flip last_ts = 346.128113 last_received_ts = 346.127533 last_seq = 627 current_ts = 346.144775 current_received_ts = 346.144165 current_seq = 628 count = 416 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 346.144775 last_received_ts = 346.144165 last_seq = 628 current_ts = 346.161438 current_received_ts = 346.160828 current_seq = 629 count = 417 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 90us (kms_flip:4991) DEBUG: name = flip last_ts = 346.161438 last_received_ts = 346.160828 last_seq = 629 current_ts = 346.178070 current_received_ts = 346.177490 current_seq = 630 count = 418 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 40us (kms_flip:4991) DEBUG: name = flip last_ts = 346.178070 last_received_ts = 346.177490 last_seq = 630 current_ts = 346.194733 current_received_ts = 346.194122 current_seq = 631 count = 419 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 39us (kms_flip:4991) DEBUG: name = flip last_ts = 346.194733 last_received_ts = 346.194122 last_seq = 631 current_ts = 346.211365 current_received_ts = 346.210785 current_seq = 632 count = 420 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 38us (kms_flip:4991) DEBUG: name = flip last_ts = 346.211365 last_received_ts = 346.210785 last_seq = 632 current_ts = 346.228027 current_received_ts = 346.227570 current_seq = 633 count = 421 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 346.228027 last_received_ts = 346.227570 last_seq = 633 current_ts = 346.244690 current_received_ts = 346.244202 current_seq = 634 count = 422 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 31us (kms_flip:4991) DEBUG: name = flip last_ts = 346.244690 last_received_ts = 346.244202 last_seq = 634 current_ts = 346.261322 current_received_ts = 346.260864 current_seq = 635 count = 423 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 35us (kms_flip:4991) DEBUG: name = flip last_ts = 346.261322 last_received_ts = 346.260864 last_seq = 635 current_ts = 346.277985 current_received_ts = 346.277527 current_seq = 636 count = 424 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 31us (kms_flip:4991) DEBUG: name = flip last_ts = 346.277985 last_received_ts = 346.277527 last_seq = 636 current_ts = 346.294617 current_received_ts = 346.294159 current_seq = 637 count = 425 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 32us (kms_flip:4991) DEBUG: name = flip last_ts = 346.294617 last_received_ts = 346.294159 last_seq = 637 current_ts = 346.311279 current_received_ts = 346.310669 current_seq = 638 count = 426 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 35us (kms_flip:4991) DEBUG: name = flip last_ts = 346.311279 last_received_ts = 346.310669 last_seq = 638 current_ts = 346.327942 current_received_ts = 346.327301 current_seq = 639 count = 427 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 346.327942 last_received_ts = 346.327301 last_seq = 639 current_ts = 346.344574 current_received_ts = 346.343964 current_seq = 640 count = 428 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 44us (kms_flip:4991) DEBUG: name = flip last_ts = 346.344574 last_received_ts = 346.343964 last_seq = 640 current_ts = 346.361237 current_received_ts = 346.360626 current_seq = 641 count = 429 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 129us (kms_flip:4991) DEBUG: name = flip last_ts = 346.361237 last_received_ts = 346.360626 last_seq = 641 current_ts = 346.377869 current_received_ts = 346.377258 current_seq = 642 count = 430 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 95us (kms_flip:4991) DEBUG: name = flip last_ts = 346.377869 last_received_ts = 346.377258 last_seq = 642 current_ts = 346.394531 current_received_ts = 346.393768 current_seq = 643 count = 431 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 46us (kms_flip:4991) DEBUG: name = flip last_ts = 346.394531 last_received_ts = 346.393768 last_seq = 643 current_ts = 346.411194 current_received_ts = 346.410583 current_seq = 644 count = 432 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 29us (kms_flip:4991) DEBUG: name = flip last_ts = 346.411194 last_received_ts = 346.410583 last_seq = 644 current_ts = 346.427826 current_received_ts = 346.427216 current_seq = 645 count = 433 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 29us (kms_flip:4991) DEBUG: name = flip last_ts = 346.427826 last_received_ts = 346.427216 last_seq = 645 current_ts = 346.444489 current_received_ts = 346.443878 current_seq = 646 count = 434 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 346.444489 last_received_ts = 346.443878 last_seq = 646 current_ts = 346.461121 current_received_ts = 346.460541 current_seq = 647 count = 435 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 105us (kms_flip:4991) DEBUG: name = flip last_ts = 346.461121 last_received_ts = 346.460541 last_seq = 647 current_ts = 346.477783 current_received_ts = 346.477173 current_seq = 648 count = 436 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 30us (kms_flip:4991) DEBUG: name = flip last_ts = 346.477783 last_received_ts = 346.477173 last_seq = 648 current_ts = 346.494446 current_received_ts = 346.493835 current_seq = 649 count = 437 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 89us (kms_flip:4991) DEBUG: name = flip last_ts = 346.494446 last_received_ts = 346.493835 last_seq = 649 current_ts = 346.511078 current_received_ts = 346.510620 current_seq = 650 count = 438 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 120us (kms_flip:4991) DEBUG: name = flip last_ts = 346.511078 last_received_ts = 346.510620 last_seq = 650 current_ts = 346.527740 current_received_ts = 346.527130 current_seq = 651 count = 439 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 30us (kms_flip:4991) DEBUG: name = flip last_ts = 346.527740 last_received_ts = 346.527130 last_seq = 651 current_ts = 346.544373 current_received_ts = 346.543915 current_seq = 652 count = 440 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 32us (kms_flip:4991) DEBUG: name = flip last_ts = 346.544373 last_received_ts = 346.543915 last_seq = 652 current_ts = 346.561035 current_received_ts = 346.560608 current_seq = 653 count = 441 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 115us (kms_flip:4991) DEBUG: name = flip last_ts = 346.561035 last_received_ts = 346.560608 last_seq = 653 current_ts = 346.577698 current_received_ts = 346.577087 current_seq = 654 count = 442 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 128us (kms_flip:4991) DEBUG: name = flip last_ts = 346.577698 last_received_ts = 346.577087 last_seq = 654 current_ts = 346.594330 current_received_ts = 346.593719 current_seq = 655 count = 443 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 34us (kms_flip:4991) DEBUG: name = flip last_ts = 346.594330 last_received_ts = 346.593719 last_seq = 655 current_ts = 346.610992 current_received_ts = 346.610382 current_seq = 656 count = 444 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 86us (kms_flip:4991) DEBUG: name = flip last_ts = 346.610992 last_received_ts = 346.610382 last_seq = 656 current_ts = 346.627625 current_received_ts = 346.627167 current_seq = 657 count = 445 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 87us (kms_flip:4991) DEBUG: name = flip last_ts = 346.627625 last_received_ts = 346.627167 last_seq = 657 current_ts = 346.644287 current_received_ts = 346.643524 current_seq = 658 count = 446 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 109us (kms_flip:4991) DEBUG: name = flip last_ts = 346.644287 last_received_ts = 346.643524 last_seq = 658 current_ts = 346.660919 current_received_ts = 346.660461 current_seq = 659 count = 447 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 346.660919 last_received_ts = 346.660461 last_seq = 659 current_ts = 346.677582 current_received_ts = 346.676819 current_seq = 660 count = 448 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 50us (kms_flip:4991) DEBUG: name = flip last_ts = 346.677582 last_received_ts = 346.676819 last_seq = 660 current_ts = 346.694214 current_received_ts = 346.693756 current_seq = 661 count = 449 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 346.694214 last_received_ts = 346.693756 last_seq = 661 current_ts = 346.710876 current_received_ts = 346.710266 current_seq = 662 count = 450 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 89us (kms_flip:4991) DEBUG: name = flip last_ts = 346.710876 last_received_ts = 346.710266 last_seq = 662 current_ts = 346.727539 current_received_ts = 346.726929 current_seq = 663 count = 451 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 95us (kms_flip:4991) DEBUG: name = flip last_ts = 346.727539 last_received_ts = 346.726929 last_seq = 663 current_ts = 346.744171 current_received_ts = 346.743439 current_seq = 664 count = 452 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 55us (kms_flip:4991) DEBUG: name = flip last_ts = 346.744171 last_received_ts = 346.743439 last_seq = 664 current_ts = 346.760834 current_received_ts = 346.760468 current_seq = 665 count = 453 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 80us (kms_flip:4991) DEBUG: name = flip last_ts = 346.760834 last_received_ts = 346.760468 last_seq = 665 current_ts = 346.777496 current_received_ts = 346.776917 current_seq = 666 count = 454 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 92us (kms_flip:4991) DEBUG: name = flip last_ts = 346.777496 last_received_ts = 346.776917 last_seq = 666 current_ts = 346.794128 current_received_ts = 346.793549 current_seq = 667 count = 455 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 92us (kms_flip:4991) DEBUG: name = flip last_ts = 346.794128 last_received_ts = 346.793549 last_seq = 667 current_ts = 346.810791 current_received_ts = 346.810303 current_seq = 668 count = 456 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 91us (kms_flip:4991) DEBUG: name = flip last_ts = 346.810791 last_received_ts = 346.810303 last_seq = 668 current_ts = 346.827423 current_received_ts = 346.826843 current_seq = 669 count = 457 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 89us (kms_flip:4991) DEBUG: name = flip last_ts = 346.827423 last_received_ts = 346.826843 last_seq = 669 current_ts = 346.844086 current_received_ts = 346.843475 current_seq = 670 count = 458 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 346.844086 last_received_ts = 346.843475 last_seq = 670 current_ts = 346.860748 current_received_ts = 346.860138 current_seq = 671 count = 459 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 33us (kms_flip:4991) DEBUG: name = flip last_ts = 346.860748 last_received_ts = 346.860138 last_seq = 671 current_ts = 346.877380 current_received_ts = 346.876923 current_seq = 672 count = 460 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 31us (kms_flip:4991) DEBUG: name = flip last_ts = 346.877380 last_received_ts = 346.876923 last_seq = 672 current_ts = 346.894043 current_received_ts = 346.893585 current_seq = 673 count = 461 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 35us (kms_flip:4991) DEBUG: name = flip last_ts = 346.894043 last_received_ts = 346.893585 last_seq = 673 current_ts = 346.910706 current_received_ts = 346.910248 current_seq = 674 count = 462 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 82us (kms_flip:4991) DEBUG: name = flip last_ts = 346.910706 last_received_ts = 346.910248 last_seq = 674 current_ts = 346.927338 current_received_ts = 346.926910 current_seq = 675 count = 463 seq_step = 1 (kms_flip:4991) DEBUG: Vblank took 565us (kms_flip:4991) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:4991) CRITICAL: Failed assertion: end - start < 500 (kms_flip:4991) igt_core-INFO: Stack trace: (kms_flip:4991) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:4991) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:4991) igt_core-INFO: #2 ../tests/kms_flip.c:1889 run_test() (kms_flip:4991) igt_core-INFO: #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045() (kms_flip:4991) igt_core-INFO: #4 ../tests/kms_flip.c:2045 main() (kms_flip:4991) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:4991) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:4991) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (9.018s)
Dmesg	<6> [477.446086] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [477.447676] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:429] <7> [477.448654] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430] <7> [477.457004] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [477.457358] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [477.457624] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [477.523933] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:149:pipe A] <7> [477.524118] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [477.524411] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [477.524646] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [477.524872] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [477.525118] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [477.525330] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [477.525538] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [477.525731] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [477.525936] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [477.526144] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [477.526322] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [477.526498] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [477.526671] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [477.526848] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [477.527046] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [477.527210] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [477.527367] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [477.527525] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [477.527675] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [477.527844] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [477.528010] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [477.528151] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [477.528290] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [477.528425] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [477.528557] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [477.528688] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [477.528816] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [477.528951] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [477.529074] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [477.529191] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [477.529307] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [477.529425] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [477.529555] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [477.529672] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [477.529786] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [477.529895] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [477.530036] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [477.530143] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:149:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [477.530250] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:149:pipe A] fastset requirement not met, forcing full modeset <7> [477.530358] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:149:pipe A] releasing DPLL 0 <7> [477.530525] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [477.530622] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:149:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [477.530733] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:143:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [477.530831] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:149:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [477.530959] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [477.531072] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [477.531180] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [477.531315] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:149:pipe A] enable: no [modeset] <7> [477.531421] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:33:plane 1A] fb: [NOFB], visible: no <7> [477.531523] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:63:plane 2A] fb: [NOFB], visible: no <7> [477.531622] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:93:plane 3A] fb: [NOFB], visible: no <7> [477.531720] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:123:plane 4A] fb: [NOFB], visible: no <7> [477.531813] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:133:plane 5A] fb: [NOFB], visible: no <7> [477.531903] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:143:cursor A] fb: [NOFB], visible: no <7> [477.532067] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [477.532185] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [477.532438] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [477.532531] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [477.736503] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:391:eDP-1] set backlight PWM = 0 <7> [477.736906] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [477.740321] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 turn panel power off <7> [477.740550] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 wait for panel power off time <7> [477.740777] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [477.793128] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [477.793848] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:390:DDI A/PHY A] - short <7> [477.801806] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [477.802230] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:149:pipe A] <7> [477.802286] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:390:DDI A/PHY A] <7> [477.803569] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [477.804011] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [477.804489] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:390:DDI A/PHY A] <7> [477.804838] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:399:DDI TC1/PHY TC1] <7> [477.805125] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DP-MST A] <7> [477.805431] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:402:DP-MST B] <7> [477.805699] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST C] <7> [477.806014] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:411:DDI TC2/PHY TC2] <7> [477.806279] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DP-MST A] <7> [477.806581] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:414:DP-MST B] <7> [477.806835] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST C] <7> [477.807084] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:419:DDI TC3/PHY TC3] <7> [477.807352] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DP-MST A] <7> [477.807594] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:422:DP-MST B] <7> [477.807835] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST C] <7> [477.808086] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:391:eDP-1] <7> [477.808438] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [477.808709] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [477.808968] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [477.809453] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [477.809942] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:149:pipe A] <7> [477.810234] 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> [477.810618] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [477.810864] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [477.811702] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B] <7> [477.812083] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C] <7> [477.812419] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B] <7> [477.812504] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:391:eDP-1] <7> [477.812718] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:391:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [477.813119] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:390:DDI A/PHY A][CRTC:268:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [477.813481] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 link rate required 1303913 available 1728000 <7> [477.813829] xe 0000:00:02.0: [drm:intel_psr_compute_config [xe]] Selective update not enabled because it would inhibit pipe CRC calculation <7> [477.814086] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:268:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [477.814449] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:390:DDI A/PHY A] [CRTC:268:pipe B] <7> [477.814848] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [477.815169] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [477.815507] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [477.815792] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [477.816070] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [477.816379] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [477.816663] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [477.816909] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [477.817145] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [477.817392] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [477.817604] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [477.817817] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [477.818054] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [477.818254] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [477.818473] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [477.818661] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [477.818868] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [477.819058] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [477.819235] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [477.819414] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [477.819575] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [477.819761] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [477.819947] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [477.820113] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [477.820262] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [477.820431] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [477.820573] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [477.820714] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [477.820855] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [477.820987] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [477.821115] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [477.821240] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [477.821373] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [477.821513] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [477.821655] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [477.821784] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [477.821898] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [477.822025] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:268:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [477.822150] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:268:pipe B] fastset requirement not met, forcing full modeset <7> [477.822320] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [477.822473] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:268:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [477.822597] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:152:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [477.822677] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:262:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [477.822753] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:152:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [477.822829] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:152:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [477.822902] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:152:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [477.822973] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:152:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [477.823060] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:268:pipe B] data rate 1390840 num active planes 1 <7> [477.823174] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [477.823285] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [477.823403] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [477.823506] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [477.823607] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [477.823708] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:268:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [477.823819] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [477.823921] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [477.824023] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [477.824150] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:268:pipe B] allocated DPLL 0 <7> [477.824243] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:268:pipe B] reserving DPLL 0 <7> [477.824332] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:268:pipe B] enable: yes [modeset] <7> [477.824446] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [477.824554] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [477.824658] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [477.824743] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [477.824824] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [477.824902] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [477.824978] 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> [477.825059] 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> [477.825143] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [477.825223] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [477.825296] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: disabled, panel replay: disabled, selective fetch: disabled <7> [477.825373] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [477.825468] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [477.825563] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 2, length 8 <7> [477.825658] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [477.825735] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [477.825807] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [477.825879] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [477.825951] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [477.826023] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [477.826094] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [477.826165] 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> [477.826238] 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> [477.826312] 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> [477.826401] 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> [477.826498] 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> [477.826593] 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> [477.826683] 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> [477.826758] 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> [477.826829] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855 <7> [477.826901] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [477.826972] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [477.827043] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [477.827114] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [477.827186] 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> [477.827257] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: clock: 432000, fracen: no, <7> [477.827327] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [477.827418] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [477.827511] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [477.827602] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [477.827692] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [477.827765] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [477.827835] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [477.827904] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [477.827973] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [477.828042] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [477.828112] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [477.828180] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [477.828249] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [477.828317] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [477.828398] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [477.828491] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [477.828584] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [477.828676] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [477.828755] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [477.828834] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [477.828914] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [477.828993] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:152:plane 1B] fb: [FB:429] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [477.829064] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [477.829134] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [477.829204] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:182:plane 2B] fb: [NOFB], visible: no <7> [477.829275] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:212:plane 3B] fb: [NOFB], visible: no <7> [477.829345] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:242:plane 4B] fb: [NOFB], visible: no <7> [477.829444] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:252:plane 5B] fb: [NOFB], visible: no <7> [477.829536] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:262:cursor B] fb: [NOFB], visible: no <7> [477.829890] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [477.830006] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [477.830135] 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> [477.830221] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [477.830301] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [477.830389] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:390:DDI A/PHY A] <7> [477.830477] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:399:DDI TC1/PHY TC1] <7> [477.830560] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DP-MST A] <7> [477.830642] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:402:DP-MST B] <7> [477.830714] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST C] <7> [477.830774] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:411:DDI TC2/PHY TC2] <7> [477.830834] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DP-MST A] <7> [477.830892] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:414:DP-MST B] <7> [477.830950] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST C] <7> [477.831007] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:419:DDI TC3/PHY TC3] <7> [477.831065] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DP-MST A] <7> [477.831069] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [477.831121] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:422:DP-MST B] <7> [477.831177] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST C] <7> [477.831197] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:390:DDI A/PHY A] - long <7> [477.831253] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [477.831287] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [477.831409] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [477.831387] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:390:DDI A/PHY A] <7> [477.831485] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [477.831605] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [477.832401] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:268:pipe B] <7> [477.832484] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [477.834126] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 turn panel power on <7> [477.834191] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 wait for panel power cycle (469 ms remaining) <7> [478.305342] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [478.326121] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [478.326471] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 wait for panel power on <7> [478.326740] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [478.363109] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [478.363718] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:390:DDI A/PHY A] - long <7> [478.364198] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [478.364746] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:390:DDI A/PHY A] <7> [478.536036] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [478.536422] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 turning VDD on <7> [478.536672] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [478.538629] 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> [478.539880] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [478.540594] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [478.541643] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [478.542717] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [478.543733] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Clock recovery OK <7> [478.544059] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [478.545546] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [478.545930] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:391:eDP-1][ENCODER:390:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [478.546813] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [478.547335] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [478.547748] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [478.548209] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:391:eDP-1] set backlight PWM = 4518 <7> [478.549653] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] reserved 14745600 bytes of contiguous stolen space for FBC, limit: 2 <7> [478.550001] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] Enabling FBC on [PLANE:152:plane 1B] <7> [478.564342] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR1 <7> [478.565983] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:391:eDP-1] <7> [478.566374] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:268:pipe B] <7> [481.085607] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 turning VDD off <7> [481.085940] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:390:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [486.330394] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [486.330688] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [486.330890] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [486.464774] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

9.02 seconds

Hostname

shard-lnl-1

Igt-Version

IGT-Version: 2.3-g943af1354 (x86_64) (Linux: 6.19.0-rc3-lgci-xe-xe-4315-633f3e5eab13c5bc2+ x86_64)

Out

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

Err

Starting dynamic subtest: B-eDP1
(kms_flip:4991) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:4991) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:4991) DEBUG: name = flip
last_ts = 344.896057
last_received_ts = 344.895447
last_seq = 553
current_ts = 344.912689
current_received_ts = 344.912231
current_seq = 554
count = 342
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 31us
(kms_flip:4991) DEBUG: name = flip
last_ts = 344.912689
last_received_ts = 344.912231
last_seq = 554
current_ts = 344.929352
current_received_ts = 344.928894
current_seq = 555
count = 343
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 30us
(kms_flip:4991) DEBUG: name = flip
last_ts = 344.929352
last_received_ts = 344.928894
last_seq = 555
current_ts = 344.945984
current_received_ts = 344.945526
current_seq = 556
count = 344
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 344.945984
last_received_ts = 344.945526
last_seq = 556
current_ts = 344.962646
current_received_ts = 344.962189
current_seq = 557
count = 345
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 81us
(kms_flip:4991) DEBUG: name = flip
last_ts = 344.962646
last_received_ts = 344.962189
last_seq = 557
current_ts = 344.979309
current_received_ts = 344.978729
current_seq = 558
count = 346
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 90us
(kms_flip:4991) DEBUG: name = flip
last_ts = 344.979309
last_received_ts = 344.978729
last_seq = 558
current_ts = 344.995941
current_received_ts = 344.995361
current_seq = 559
count = 347
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 112us
(kms_flip:4991) DEBUG: name = flip
last_ts = 344.995941
last_received_ts = 344.995361
last_seq = 559
current_ts = 345.012604
current_received_ts = 345.012024
current_seq = 560
count = 348
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 30us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.012604
last_received_ts = 345.012024
last_seq = 560
current_ts = 345.029236
current_received_ts = 345.028656
current_seq = 561
count = 349
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 88us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.029236
last_received_ts = 345.028656
last_seq = 561
current_ts = 345.045898
current_received_ts = 345.045349
current_seq = 562
count = 350
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 84us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.045898
last_received_ts = 345.045349
last_seq = 562
current_ts = 345.062531
current_received_ts = 345.062073
current_seq = 563
count = 351
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 30us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.062531
last_received_ts = 345.062073
last_seq = 563
current_ts = 345.079193
current_received_ts = 345.078583
current_seq = 564
count = 352
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 32us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.079193
last_received_ts = 345.078583
last_seq = 564
current_ts = 345.095825
current_received_ts = 345.095428
current_seq = 565
count = 353
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 32us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.095825
last_received_ts = 345.095428
last_seq = 565
current_ts = 345.112488
current_received_ts = 345.111908
current_seq = 566
count = 354
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.112488
last_received_ts = 345.111908
last_seq = 566
current_ts = 345.129150
current_received_ts = 345.128693
current_seq = 567
count = 355
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 30us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.129150
last_received_ts = 345.128693
last_seq = 567
current_ts = 345.145782
current_received_ts = 345.145294
current_seq = 568
count = 356
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.145782
last_received_ts = 345.145294
last_seq = 568
current_ts = 345.162445
current_received_ts = 345.161835
current_seq = 569
count = 357
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 32us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.162445
last_received_ts = 345.161835
last_seq = 569
current_ts = 345.179077
current_received_ts = 345.178650
current_seq = 570
count = 358
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 29us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.179077
last_received_ts = 345.178650
last_seq = 570
current_ts = 345.195740
current_received_ts = 345.195129
current_seq = 571
count = 359
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 81us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.195740
last_received_ts = 345.195129
last_seq = 571
current_ts = 345.212402
current_received_ts = 345.211884
current_seq = 572
count = 360
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 65us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.212402
last_received_ts = 345.211884
last_seq = 572
current_ts = 345.229034
current_received_ts = 345.228455
current_seq = 573
count = 361
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 114us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.229034
last_received_ts = 345.228455
last_seq = 573
current_ts = 345.245697
current_received_ts = 345.245087
current_seq = 574
count = 362
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.245697
last_received_ts = 345.245087
last_seq = 574
current_ts = 345.262329
current_received_ts = 345.261749
current_seq = 575
count = 363
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 90us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.262329
last_received_ts = 345.261749
last_seq = 575
current_ts = 345.278992
current_received_ts = 345.278381
current_seq = 576
count = 364
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.278992
last_received_ts = 345.278381
last_seq = 576
current_ts = 345.295624
current_received_ts = 345.295074
current_seq = 577
count = 365
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 99us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.295624
last_received_ts = 345.295074
last_seq = 577
current_ts = 345.312286
current_received_ts = 345.311707
current_seq = 578
count = 366
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.312286
last_received_ts = 345.311707
last_seq = 578
current_ts = 345.328949
current_received_ts = 345.328461
current_seq = 579
count = 367
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.328949
last_received_ts = 345.328461
last_seq = 579
current_ts = 345.345581
current_received_ts = 345.345154
current_seq = 580
count = 368
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 29us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.345581
last_received_ts = 345.345154
last_seq = 580
current_ts = 345.362244
current_received_ts = 345.361633
current_seq = 581
count = 369
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 30us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.362244
last_received_ts = 345.361633
last_seq = 581
current_ts = 345.378876
current_received_ts = 345.378174
current_seq = 582
count = 370
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.378876
last_received_ts = 345.378174
last_seq = 582
current_ts = 345.395538
current_received_ts = 345.394928
current_seq = 583
count = 371
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 32us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.395538
last_received_ts = 345.394928
last_seq = 583
current_ts = 345.412170
current_received_ts = 345.411591
current_seq = 584
count = 372
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.412170
last_received_ts = 345.411591
last_seq = 584
current_ts = 345.428833
current_received_ts = 345.428345
current_seq = 585
count = 373
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 35us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.428833
last_received_ts = 345.428345
last_seq = 585
current_ts = 345.445496
current_received_ts = 345.444885
current_seq = 586
count = 374
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 94us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.445496
last_received_ts = 345.444885
last_seq = 586
current_ts = 345.462128
current_received_ts = 345.461517
current_seq = 587
count = 375
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 84us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.462128
last_received_ts = 345.461517
last_seq = 587
current_ts = 345.478790
current_received_ts = 345.478149
current_seq = 588
count = 376
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 31us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.478790
last_received_ts = 345.478149
last_seq = 588
current_ts = 345.495422
current_received_ts = 345.494812
current_seq = 589
count = 377
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 31us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.495422
last_received_ts = 345.494812
last_seq = 589
current_ts = 345.512085
current_received_ts = 345.511475
current_seq = 590
count = 378
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.512085
last_received_ts = 345.511475
last_seq = 590
current_ts = 345.528717
current_received_ts = 345.528107
current_seq = 591
count = 379
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.528717
last_received_ts = 345.528107
last_seq = 591
current_ts = 345.545380
current_received_ts = 345.544769
current_seq = 592
count = 380
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.545380
last_received_ts = 345.544769
last_seq = 592
current_ts = 345.562042
current_received_ts = 345.561401
current_seq = 593
count = 381
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.562042
last_received_ts = 345.561401
last_seq = 593
current_ts = 345.578674
current_received_ts = 345.578064
current_seq = 594
count = 382
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.578674
last_received_ts = 345.578064
last_seq = 594
current_ts = 345.595337
current_received_ts = 345.594757
current_seq = 595
count = 383
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.595337
last_received_ts = 345.594757
last_seq = 595
current_ts = 345.611969
current_received_ts = 345.611511
current_seq = 596
count = 384
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.611969
last_received_ts = 345.611511
last_seq = 596
current_ts = 345.628632
current_received_ts = 345.628021
current_seq = 597
count = 385
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 32us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.628632
last_received_ts = 345.628021
last_seq = 597
current_ts = 345.645264
current_received_ts = 345.644745
current_seq = 598
count = 386
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 106us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.645264
last_received_ts = 345.644745
last_seq = 598
current_ts = 345.661926
current_received_ts = 345.661316
current_seq = 599
count = 387
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 31us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.661926
last_received_ts = 345.661316
last_seq = 599
current_ts = 345.678589
current_received_ts = 345.677948
current_seq = 600
count = 388
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 44us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.678589
last_received_ts = 345.677948
last_seq = 600
current_ts = 345.695221
current_received_ts = 345.694611
current_seq = 601
count = 389
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.695221
last_received_ts = 345.694611
last_seq = 601
current_ts = 345.711853
current_received_ts = 345.711273
current_seq = 602
count = 390
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 35us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.711853
last_received_ts = 345.711273
last_seq = 602
current_ts = 345.728516
current_received_ts = 345.727905
current_seq = 603
count = 391
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 35us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.728516
last_received_ts = 345.727905
last_seq = 603
current_ts = 345.745178
current_received_ts = 345.744385
current_seq = 604
count = 392
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 54us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.745178
last_received_ts = 345.744385
last_seq = 604
current_ts = 345.761810
current_received_ts = 345.761078
current_seq = 605
count = 393
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 49us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.761810
last_received_ts = 345.761078
last_seq = 605
current_ts = 345.778473
current_received_ts = 345.777863
current_seq = 606
count = 394
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 30us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.778473
last_received_ts = 345.777863
last_seq = 606
current_ts = 345.795135
current_received_ts = 345.794525
current_seq = 607
count = 395
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 32us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.795135
last_received_ts = 345.794525
last_seq = 607
current_ts = 345.811768
current_received_ts = 345.811157
current_seq = 608
count = 396
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 35us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.811768
last_received_ts = 345.811157
last_seq = 608
current_ts = 345.828430
current_received_ts = 345.827850
current_seq = 609
count = 397
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 35us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.828430
last_received_ts = 345.827850
last_seq = 609
current_ts = 345.845062
current_received_ts = 345.844421
current_seq = 610
count = 398
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.845062
last_received_ts = 345.844421
last_seq = 610
current_ts = 345.861725
current_received_ts = 345.860931
current_seq = 611
count = 399
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 46us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.861725
last_received_ts = 345.860931
last_seq = 611
current_ts = 345.878387
current_received_ts = 345.877747
current_seq = 612
count = 400
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 35us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.878387
last_received_ts = 345.877747
last_seq = 612
current_ts = 345.895020
current_received_ts = 345.894257
current_seq = 613
count = 401
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 56us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.895020
last_received_ts = 345.894257
last_seq = 613
current_ts = 345.911682
current_received_ts = 345.911194
current_seq = 614
count = 402
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 35us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.911682
last_received_ts = 345.911194
last_seq = 614
current_ts = 345.928314
current_received_ts = 345.927704
current_seq = 615
count = 403
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 41us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.928314
last_received_ts = 345.927704
last_seq = 615
current_ts = 345.944977
current_received_ts = 345.944489
current_seq = 616
count = 404
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.944977
last_received_ts = 345.944489
last_seq = 616
current_ts = 345.961639
current_received_ts = 345.961029
current_seq = 617
count = 405
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.961639
last_received_ts = 345.961029
last_seq = 617
current_ts = 345.978271
current_received_ts = 345.977814
current_seq = 618
count = 406
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 89us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.978271
last_received_ts = 345.977814
last_seq = 618
current_ts = 345.994934
current_received_ts = 345.994293
current_seq = 619
count = 407
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 345.994934
last_received_ts = 345.994293
last_seq = 619
current_ts = 346.011566
current_received_ts = 346.010956
current_seq = 620
count = 408
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 43us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.011566
last_received_ts = 346.010956
last_seq = 620
current_ts = 346.028229
current_received_ts = 346.027618
current_seq = 621
count = 409
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.028229
last_received_ts = 346.027618
last_seq = 621
current_ts = 346.044861
current_received_ts = 346.044250
current_seq = 622
count = 410
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 32us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.044861
last_received_ts = 346.044250
last_seq = 622
current_ts = 346.061523
current_received_ts = 346.060913
current_seq = 623
count = 411
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 31us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.061523
last_received_ts = 346.060913
last_seq = 623
current_ts = 346.078186
current_received_ts = 346.077606
current_seq = 624
count = 412
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 94us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.078186
last_received_ts = 346.077606
last_seq = 624
current_ts = 346.094818
current_received_ts = 346.094330
current_seq = 625
count = 413
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 59us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.094818
last_received_ts = 346.094330
last_seq = 625
current_ts = 346.111481
current_received_ts = 346.111023
current_seq = 626
count = 414
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 96us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.111481
last_received_ts = 346.111023
last_seq = 626
current_ts = 346.128113
current_received_ts = 346.127533
current_seq = 627
count = 415
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 36us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.128113
last_received_ts = 346.127533
last_seq = 627
current_ts = 346.144775
current_received_ts = 346.144165
current_seq = 628
count = 416
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.144775
last_received_ts = 346.144165
last_seq = 628
current_ts = 346.161438
current_received_ts = 346.160828
current_seq = 629
count = 417
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 90us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.161438
last_received_ts = 346.160828
last_seq = 629
current_ts = 346.178070
current_received_ts = 346.177490
current_seq = 630
count = 418
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 40us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.178070
last_received_ts = 346.177490
last_seq = 630
current_ts = 346.194733
current_received_ts = 346.194122
current_seq = 631
count = 419
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 39us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.194733
last_received_ts = 346.194122
last_seq = 631
current_ts = 346.211365
current_received_ts = 346.210785
current_seq = 632
count = 420
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 38us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.211365
last_received_ts = 346.210785
last_seq = 632
current_ts = 346.228027
current_received_ts = 346.227570
current_seq = 633
count = 421
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.228027
last_received_ts = 346.227570
last_seq = 633
current_ts = 346.244690
current_received_ts = 346.244202
current_seq = 634
count = 422
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 31us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.244690
last_received_ts = 346.244202
last_seq = 634
current_ts = 346.261322
current_received_ts = 346.260864
current_seq = 635
count = 423
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 35us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.261322
last_received_ts = 346.260864
last_seq = 635
current_ts = 346.277985
current_received_ts = 346.277527
current_seq = 636
count = 424
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 31us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.277985
last_received_ts = 346.277527
last_seq = 636
current_ts = 346.294617
current_received_ts = 346.294159
current_seq = 637
count = 425
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 32us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.294617
last_received_ts = 346.294159
last_seq = 637
current_ts = 346.311279
current_received_ts = 346.310669
current_seq = 638
count = 426
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 35us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.311279
last_received_ts = 346.310669
last_seq = 638
current_ts = 346.327942
current_received_ts = 346.327301
current_seq = 639
count = 427
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.327942
last_received_ts = 346.327301
last_seq = 639
current_ts = 346.344574
current_received_ts = 346.343964
current_seq = 640
count = 428
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 44us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.344574
last_received_ts = 346.343964
last_seq = 640
current_ts = 346.361237
current_received_ts = 346.360626
current_seq = 641
count = 429
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 129us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.361237
last_received_ts = 346.360626
last_seq = 641
current_ts = 346.377869
current_received_ts = 346.377258
current_seq = 642
count = 430
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 95us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.377869
last_received_ts = 346.377258
last_seq = 642
current_ts = 346.394531
current_received_ts = 346.393768
current_seq = 643
count = 431
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 46us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.394531
last_received_ts = 346.393768
last_seq = 643
current_ts = 346.411194
current_received_ts = 346.410583
current_seq = 644
count = 432
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 29us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.411194
last_received_ts = 346.410583
last_seq = 644
current_ts = 346.427826
current_received_ts = 346.427216
current_seq = 645
count = 433
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 29us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.427826
last_received_ts = 346.427216
last_seq = 645
current_ts = 346.444489
current_received_ts = 346.443878
current_seq = 646
count = 434
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.444489
last_received_ts = 346.443878
last_seq = 646
current_ts = 346.461121
current_received_ts = 346.460541
current_seq = 647
count = 435
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 105us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.461121
last_received_ts = 346.460541
last_seq = 647
current_ts = 346.477783
current_received_ts = 346.477173
current_seq = 648
count = 436
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 30us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.477783
last_received_ts = 346.477173
last_seq = 648
current_ts = 346.494446
current_received_ts = 346.493835
current_seq = 649
count = 437
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 89us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.494446
last_received_ts = 346.493835
last_seq = 649
current_ts = 346.511078
current_received_ts = 346.510620
current_seq = 650
count = 438
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 120us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.511078
last_received_ts = 346.510620
last_seq = 650
current_ts = 346.527740
current_received_ts = 346.527130
current_seq = 651
count = 439
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 30us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.527740
last_received_ts = 346.527130
last_seq = 651
current_ts = 346.544373
current_received_ts = 346.543915
current_seq = 652
count = 440
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 32us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.544373
last_received_ts = 346.543915
last_seq = 652
current_ts = 346.561035
current_received_ts = 346.560608
current_seq = 653
count = 441
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 115us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.561035
last_received_ts = 346.560608
last_seq = 653
current_ts = 346.577698
current_received_ts = 346.577087
current_seq = 654
count = 442
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 128us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.577698
last_received_ts = 346.577087
last_seq = 654
current_ts = 346.594330
current_received_ts = 346.593719
current_seq = 655
count = 443
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 34us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.594330
last_received_ts = 346.593719
last_seq = 655
current_ts = 346.610992
current_received_ts = 346.610382
current_seq = 656
count = 444
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 86us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.610992
last_received_ts = 346.610382
last_seq = 656
current_ts = 346.627625
current_received_ts = 346.627167
current_seq = 657
count = 445
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 87us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.627625
last_received_ts = 346.627167
last_seq = 657
current_ts = 346.644287
current_received_ts = 346.643524
current_seq = 658
count = 446
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 109us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.644287
last_received_ts = 346.643524
last_seq = 658
current_ts = 346.660919
current_received_ts = 346.660461
current_seq = 659
count = 447
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.660919
last_received_ts = 346.660461
last_seq = 659
current_ts = 346.677582
current_received_ts = 346.676819
current_seq = 660
count = 448
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 50us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.677582
last_received_ts = 346.676819
last_seq = 660
current_ts = 346.694214
current_received_ts = 346.693756
current_seq = 661
count = 449
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.694214
last_received_ts = 346.693756
last_seq = 661
current_ts = 346.710876
current_received_ts = 346.710266
current_seq = 662
count = 450
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 89us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.710876
last_received_ts = 346.710266
last_seq = 662
current_ts = 346.727539
current_received_ts = 346.726929
current_seq = 663
count = 451
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 95us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.727539
last_received_ts = 346.726929
last_seq = 663
current_ts = 346.744171
current_received_ts = 346.743439
current_seq = 664
count = 452
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 55us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.744171
last_received_ts = 346.743439
last_seq = 664
current_ts = 346.760834
current_received_ts = 346.760468
current_seq = 665
count = 453
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 80us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.760834
last_received_ts = 346.760468
last_seq = 665
current_ts = 346.777496
current_received_ts = 346.776917
current_seq = 666
count = 454
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 92us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.777496
last_received_ts = 346.776917
last_seq = 666
current_ts = 346.794128
current_received_ts = 346.793549
current_seq = 667
count = 455
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 92us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.794128
last_received_ts = 346.793549
last_seq = 667
current_ts = 346.810791
current_received_ts = 346.810303
current_seq = 668
count = 456
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 91us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.810791
last_received_ts = 346.810303
last_seq = 668
current_ts = 346.827423
current_received_ts = 346.826843
current_seq = 669
count = 457
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 89us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.827423
last_received_ts = 346.826843
last_seq = 669
current_ts = 346.844086
current_received_ts = 346.843475
current_seq = 670
count = 458
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.844086
last_received_ts = 346.843475
last_seq = 670
current_ts = 346.860748
current_received_ts = 346.860138
current_seq = 671
count = 459
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 33us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.860748
last_received_ts = 346.860138
last_seq = 671
current_ts = 346.877380
current_received_ts = 346.876923
current_seq = 672
count = 460
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 31us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.877380
last_received_ts = 346.876923
last_seq = 672
current_ts = 346.894043
current_received_ts = 346.893585
current_seq = 673
count = 461
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 35us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.894043
last_received_ts = 346.893585
last_seq = 673
current_ts = 346.910706
current_received_ts = 346.910248
current_seq = 674
count = 462
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 82us
(kms_flip:4991) DEBUG: name = flip
last_ts = 346.910706
last_received_ts = 346.910248
last_seq = 674
current_ts = 346.927338
current_received_ts = 346.926910
current_seq = 675
count = 463
seq_step = 1
(kms_flip:4991) DEBUG: Vblank took 565us
(kms_flip:4991) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:4991) CRITICAL: Failed assertion: end - start < 500
(kms_flip:4991) igt_core-INFO: Stack trace:
(kms_flip:4991) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:4991) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:4991) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:4991) igt_core-INFO:   #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045()
(kms_flip:4991) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:4991) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:4991) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:4991) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (9.018s)

Dmesg

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [477.813829] xe 0000:00:02.0: [drm:intel_psr_compute_config [xe]] Selective update not enabled because it would inhibit pipe CRC calculation

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [477.826165] 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> [477.826238] 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> [477.826312] 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> [477.826401] 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> [477.826498] 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> [477.826593] 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> [477.826683] 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> [477.826758] 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> [477.826829] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [478.550001] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] Enabling FBC on [PLANE:152:plane 1B]

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

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

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

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

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

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

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

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

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

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