Hardware List

Results for igt@kms_flip@plain-flip-ts-check@c-edp1

Machine description: shard-mtlp-6

Result: Fail

git-log-oneline i915_display_info21 igt_runner21 runtimes21 results21.json results21-i915-load.json i915_display_info_post_exec21 boot21 dmesg21

Detail	Value
Duration	12.25 seconds
Hostname	shard-mtlp-6
Igt-Version	IGT-Version: 2.0-gf05383af3 (x86_64) (Linux: 6.14.0-rc7-CI_DRM_16300-g74f632d1bd3b+ x86_64)
Out	Starting dynamic subtest: C-eDP1 2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa Expected frametime: 11111us; measured 11061.6us +- 2.306us accuracy 0.06% vblank interval differs from modeline! expected 11111.1us, measured 11062us +- 2.306us, difference 49.5us (21.5 sigma) Stack trace: #0 ../lib/igt_core.c:2055 __igt_fail_assert() #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1831 run_test() #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987() #4 ../tests/kms_flip.c:1987 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest C-eDP1: FAIL (12.252s)
Err	Starting dynamic subtest: C-eDP1 (kms_flip:2440) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660: (kms_flip:2440) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon) Dynamic subtest C-eDP1 failed. ** DEBUG (kms_flip:2440) DEBUG: name = flip last_ts = 224.268341 last_received_ts = 224.268021 last_seq = 627 current_ts = 224.279419 current_received_ts = 224.279144 current_seq = 628 count = 556 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.268341/627, current 224.279419/628: elapsed=11085.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.279419 last_received_ts = 224.279144 last_seq = 628 current_ts = 224.290512 current_received_ts = 224.290207 current_seq = 629 count = 557 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.279419/628, current 224.290512/629: elapsed=11083.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.290512 last_received_ts = 224.290207 last_seq = 629 current_ts = 224.301605 current_received_ts = 224.301285 current_seq = 630 count = 558 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.290512/629, current 224.301605/630: elapsed=11091.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.301605 last_received_ts = 224.301285 last_seq = 630 current_ts = 224.312683 current_received_ts = 224.312393 current_seq = 631 count = 559 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.301605/630, current 224.312683/631: elapsed=11081.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.312683 last_received_ts = 224.312393 last_seq = 631 current_ts = 224.323761 current_received_ts = 224.323486 current_seq = 632 count = 560 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.312683/631, current 224.323761/632: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.323761 last_received_ts = 224.323486 last_seq = 632 current_ts = 224.334854 current_received_ts = 224.334579 current_seq = 633 count = 561 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.323761/632, current 224.334854/633: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.334854 last_received_ts = 224.334579 last_seq = 633 current_ts = 224.345947 current_received_ts = 224.345673 current_seq = 634 count = 562 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.334854/633, current 224.345947/634: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.345947 last_received_ts = 224.345673 last_seq = 634 current_ts = 224.357025 current_received_ts = 224.356735 current_seq = 635 count = 563 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.345947/634, current 224.357025/635: elapsed=11081.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.357025 last_received_ts = 224.356735 last_seq = 635 current_ts = 224.368118 current_received_ts = 224.367813 current_seq = 636 count = 564 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.357025/635, current 224.368118/636: elapsed=11092.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.368118 last_received_ts = 224.367813 last_seq = 636 current_ts = 224.379211 current_received_ts = 224.378891 current_seq = 637 count = 565 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.368118/636, current 224.379211/637: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.379211 last_received_ts = 224.378891 last_seq = 637 current_ts = 224.390289 current_received_ts = 224.389969 current_seq = 638 count = 566 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.379211/637, current 224.390289/638: elapsed=11085.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.390289 last_received_ts = 224.389969 last_seq = 638 current_ts = 224.401382 current_received_ts = 224.401062 current_seq = 639 count = 567 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.390289/638, current 224.401382/639: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.401382 last_received_ts = 224.401062 last_seq = 639 current_ts = 224.412460 current_received_ts = 224.412186 current_seq = 640 count = 568 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.401382/639, current 224.412460/640: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.412460 last_received_ts = 224.412186 last_seq = 640 current_ts = 224.423553 current_received_ts = 224.423233 current_seq = 641 count = 569 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.412460/640, current 224.423553/641: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.423553 last_received_ts = 224.423233 last_seq = 641 current_ts = 224.434647 current_received_ts = 224.434311 current_seq = 642 count = 570 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.423553/641, current 224.434647/642: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.434647 last_received_ts = 224.434311 last_seq = 642 current_ts = 224.445724 current_received_ts = 224.445450 current_seq = 643 count = 571 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.434647/642, current 224.445724/643: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.445724 last_received_ts = 224.445450 last_seq = 643 current_ts = 224.456818 current_received_ts = 224.456497 current_seq = 644 count = 572 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.445724/643, current 224.456818/644: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.456818 last_received_ts = 224.456497 last_seq = 644 current_ts = 224.467911 current_received_ts = 224.467606 current_seq = 645 count = 573 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.456818/644, current 224.467911/645: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.467911 last_received_ts = 224.467606 last_seq = 645 current_ts = 224.478989 current_received_ts = 224.478699 current_seq = 646 count = 574 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.467911/645, current 224.478989/646: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.478989 last_received_ts = 224.478699 last_seq = 646 current_ts = 224.490082 current_received_ts = 224.489777 current_seq = 647 count = 575 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.478989/646, current 224.490082/647: elapsed=11092.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.490082 last_received_ts = 224.489777 last_seq = 647 current_ts = 224.501175 current_received_ts = 224.500870 current_seq = 648 count = 576 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.490082/647, current 224.501175/648: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.501175 last_received_ts = 224.500870 last_seq = 648 current_ts = 224.512253 current_received_ts = 224.511948 current_seq = 649 count = 577 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.501175/648, current 224.512253/649: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.512253 last_received_ts = 224.511948 last_seq = 649 current_ts = 224.523346 current_received_ts = 224.523041 current_seq = 650 count = 578 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.512253/649, current 224.523346/650: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.523346 last_received_ts = 224.523041 last_seq = 650 current_ts = 224.534439 current_received_ts = 224.534088 current_seq = 651 count = 579 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.523346/650, current 224.534439/651: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.534439 last_received_ts = 224.534088 last_seq = 651 current_ts = 224.545517 current_received_ts = 224.545227 current_seq = 652 count = 580 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.534439/651, current 224.545517/652: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.545517 last_received_ts = 224.545227 last_seq = 652 current_ts = 224.556610 current_received_ts = 224.556290 current_seq = 653 count = 581 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.545517/652, current 224.556610/653: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.556610 last_received_ts = 224.556290 last_seq = 653 current_ts = 224.567703 current_received_ts = 224.567398 current_seq = 654 count = 582 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.556610/653, current 224.567703/654: elapsed=11091.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.567703 last_received_ts = 224.567398 last_seq = 654 current_ts = 224.578781 current_received_ts = 224.578476 current_seq = 655 count = 583 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.567703/654, current 224.578781/655: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.578781 last_received_ts = 224.578476 last_seq = 655 current_ts = 224.589874 current_received_ts = 224.589554 current_seq = 656 count = 584 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.578781/655, current 224.589874/656: elapsed=11091.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.589874 last_received_ts = 224.589554 last_seq = 656 current_ts = 224.600967 current_received_ts = 224.600677 current_seq = 657 count = 585 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.589874/656, current 224.600967/657: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.600967 last_received_ts = 224.600677 last_seq = 657 current_ts = 224.612061 current_received_ts = 224.611740 current_seq = 658 count = 586 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.600967/657, current 224.612061/658: elapsed=11085.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.612061 last_received_ts = 224.611740 last_seq = 658 current_ts = 224.623138 current_received_ts = 224.622818 current_seq = 659 count = 587 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.612061/658, current 224.623138/659: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.623138 last_received_ts = 224.622818 last_seq = 659 current_ts = 224.634232 current_received_ts = 224.633957 current_seq = 660 count = 588 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.623138/659, current 224.634232/660: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.634232 last_received_ts = 224.633957 last_seq = 660 current_ts = 224.645325 current_received_ts = 224.645020 current_seq = 661 count = 589 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.634232/660, current 224.645325/661: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.645325 last_received_ts = 224.645020 last_seq = 661 current_ts = 224.656403 current_received_ts = 224.656097 current_seq = 662 count = 590 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.645325/661, current 224.656403/662: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.656403 last_received_ts = 224.656097 last_seq = 662 current_ts = 224.667496 current_received_ts = 224.667221 current_seq = 663 count = 591 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.656403/662, current 224.667496/663: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.667496 last_received_ts = 224.667221 last_seq = 663 current_ts = 224.678589 current_received_ts = 224.678284 current_seq = 664 count = 592 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.667496/663, current 224.678589/664: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.678589 last_received_ts = 224.678284 last_seq = 664 current_ts = 224.689667 current_received_ts = 224.689346 current_seq = 665 count = 593 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.678589/664, current 224.689667/665: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.689667 last_received_ts = 224.689346 last_seq = 665 current_ts = 224.700760 current_received_ts = 224.700485 current_seq = 666 count = 594 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.689667/665, current 224.700760/666: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.700760 last_received_ts = 224.700485 last_seq = 666 current_ts = 224.711853 current_received_ts = 224.711533 current_seq = 667 count = 595 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.700760/666, current 224.711853/667: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.711853 last_received_ts = 224.711533 last_seq = 667 current_ts = 224.722931 current_received_ts = 224.722626 current_seq = 668 count = 596 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.711853/667, current 224.722931/668: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.722931 last_received_ts = 224.722626 last_seq = 668 current_ts = 224.734024 current_received_ts = 224.733734 current_seq = 669 count = 597 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.722931/668, current 224.734024/669: elapsed=11092.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.734024 last_received_ts = 224.733734 last_seq = 669 current_ts = 224.745117 current_received_ts = 224.744797 current_seq = 670 count = 598 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.734024/669, current 224.745117/670: elapsed=11085.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.745117 last_received_ts = 224.744797 last_seq = 670 current_ts = 224.756195 current_received_ts = 224.755890 current_seq = 671 count = 599 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.745117/670, current 224.756195/671: elapsed=11091.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.756195 last_received_ts = 224.755890 last_seq = 671 current_ts = 224.767288 current_received_ts = 224.766983 current_seq = 672 count = 600 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.756195/671, current 224.767288/672: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.767288 last_received_ts = 224.766983 last_seq = 672 current_ts = 224.778381 current_received_ts = 224.778061 current_seq = 673 count = 601 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.767288/672, current 224.778381/673: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.778381 last_received_ts = 224.778061 last_seq = 673 current_ts = 224.789459 current_received_ts = 224.789169 current_seq = 674 count = 602 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.778381/673, current 224.789459/674: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.789459 last_received_ts = 224.789169 last_seq = 674 current_ts = 224.800552 current_received_ts = 224.800262 current_seq = 675 count = 603 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.789459/674, current 224.800552/675: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.800552 last_received_ts = 224.800262 last_seq = 675 current_ts = 224.811646 current_received_ts = 224.811340 current_seq = 676 count = 604 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.800552/675, current 224.811646/676: elapsed=11085.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.811646 last_received_ts = 224.811340 last_seq = 676 current_ts = 224.822723 current_received_ts = 224.822433 current_seq = 677 count = 605 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.811646/676, current 224.822723/677: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.822723 last_received_ts = 224.822433 last_seq = 677 current_ts = 224.833817 current_received_ts = 224.833511 current_seq = 678 count = 606 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.822723/677, current 224.833817/678: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.833817 last_received_ts = 224.833511 last_seq = 678 current_ts = 224.844910 current_received_ts = 224.844589 current_seq = 679 count = 607 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.833817/678, current 224.844910/679: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.844910 last_received_ts = 224.844589 last_seq = 679 current_ts = 224.856003 current_received_ts = 224.855713 current_seq = 680 count = 608 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.844910/679, current 224.856003/680: elapsed=11091.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.856003 last_received_ts = 224.855713 last_seq = 680 current_ts = 224.867081 current_received_ts = 224.866791 current_seq = 681 count = 609 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.856003/680, current 224.867081/681: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.867081 last_received_ts = 224.866791 last_seq = 681 current_ts = 224.878174 current_received_ts = 224.877869 current_seq = 682 count = 610 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.867081/681, current 224.878174/682: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.878174 last_received_ts = 224.877869 last_seq = 682 current_ts = 224.889252 current_received_ts = 224.888962 current_seq = 683 count = 611 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.878174/682, current 224.889252/683: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.889252 last_received_ts = 224.888962 last_seq = 683 current_ts = 224.900345 current_received_ts = 224.900040 current_seq = 684 count = 612 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.889252/683, current 224.900345/684: elapsed=11091.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.900345 last_received_ts = 224.900040 last_seq = 684 current_ts = 224.911438 current_received_ts = 224.911118 current_seq = 685 count = 613 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.900345/684, current 224.911438/685: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.911438 last_received_ts = 224.911118 last_seq = 685 current_ts = 224.922516 current_received_ts = 224.922211 current_seq = 686 count = 614 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.911438/685, current 224.922516/686: elapsed=11085.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.922516 last_received_ts = 224.922211 last_seq = 686 current_ts = 224.933609 current_received_ts = 224.933304 current_seq = 687 count = 615 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.922516/686, current 224.933609/687: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.933609 last_received_ts = 224.933304 last_seq = 687 current_ts = 224.944702 current_received_ts = 224.944382 current_seq = 688 count = 616 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.933609/687, current 224.944702/688: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.944702 last_received_ts = 224.944382 last_seq = 688 current_ts = 224.955795 current_received_ts = 224.955490 current_seq = 689 count = 617 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.944702/688, current 224.955795/689: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.955795 last_received_ts = 224.955490 last_seq = 689 current_ts = 224.966873 current_received_ts = 224.966568 current_seq = 690 count = 618 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.955795/689, current 224.966873/690: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 224.966873 last_received_ts = 224.966568 last_seq = 690 current_ts = 224.977966 current_received_ts = 224.977646 current_seq = 691 count = 619 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.966873/690, current 224.977966/691: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.977966 last_received_ts = 224.977646 last_seq = 691 current_ts = 224.989044 current_received_ts = 224.988754 current_seq = 692 count = 620 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.977966/691, current 224.989044/692: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 224.989044 last_received_ts = 224.988754 last_seq = 692 current_ts = 225.000137 current_received_ts = 224.999832 current_seq = 693 count = 621 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 224.989044/692, current 225.000137/693: elapsed=11093.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.000137 last_received_ts = 224.999832 last_seq = 693 current_ts = 225.011230 current_received_ts = 225.010910 current_seq = 694 count = 622 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.000137/693, current 225.011230/694: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.011230 last_received_ts = 225.010910 last_seq = 694 current_ts = 225.022324 current_received_ts = 225.022034 current_seq = 695 count = 623 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.011230/694, current 225.022324/695: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.022324 last_received_ts = 225.022034 last_seq = 695 current_ts = 225.033401 current_received_ts = 225.033081 current_seq = 696 count = 624 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.022324/695, current 225.033401/696: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.033401 last_received_ts = 225.033081 last_seq = 696 current_ts = 225.044495 current_received_ts = 225.044189 current_seq = 697 count = 625 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.033401/696, current 225.044495/697: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.044495 last_received_ts = 225.044189 last_seq = 697 current_ts = 225.055588 current_received_ts = 225.055267 current_seq = 698 count = 626 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.044495/697, current 225.055588/698: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.055588 last_received_ts = 225.055267 last_seq = 698 current_ts = 225.066666 current_received_ts = 225.066376 current_seq = 699 count = 627 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.055588/698, current 225.066666/699: elapsed=11091.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.066666 last_received_ts = 225.066376 last_seq = 699 current_ts = 225.077759 current_received_ts = 225.077469 current_seq = 700 count = 628 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.066666/699, current 225.077759/700: elapsed=11085.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.077759 last_received_ts = 225.077469 last_seq = 700 current_ts = 225.088852 current_received_ts = 225.088531 current_seq = 701 count = 629 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.077759/700, current 225.088852/701: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.088852 last_received_ts = 225.088531 last_seq = 701 current_ts = 225.099930 current_received_ts = 225.099625 current_seq = 702 count = 630 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.088852/701, current 225.099930/702: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.099930 last_received_ts = 225.099625 last_seq = 702 current_ts = 225.111023 current_received_ts = 225.110733 current_seq = 703 count = 631 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.099930/702, current 225.111023/703: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.111023 last_received_ts = 225.110733 last_seq = 703 current_ts = 225.122116 current_received_ts = 225.121796 current_seq = 704 count = 632 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.111023/703, current 225.122116/704: elapsed=11085.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.122116 last_received_ts = 225.121796 last_seq = 704 current_ts = 225.133209 current_received_ts = 225.132889 current_seq = 705 count = 633 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.122116/704, current 225.133209/705: elapsed=11093.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.133209 last_received_ts = 225.132889 last_seq = 705 current_ts = 225.144287 current_received_ts = 225.144043 current_seq = 706 count = 634 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.133209/705, current 225.144287/706: elapsed=11085.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.144287 last_received_ts = 225.144043 last_seq = 706 current_ts = 225.155380 current_received_ts = 225.155060 current_seq = 707 count = 635 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.144287/706, current 225.155380/707: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.155380 last_received_ts = 225.155060 last_seq = 707 current_ts = 225.166473 current_received_ts = 225.166168 current_seq = 708 count = 636 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.155380/707, current 225.166473/708: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.166473 last_received_ts = 225.166168 last_seq = 708 current_ts = 225.177551 current_received_ts = 225.177246 current_seq = 709 count = 637 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.166473/708, current 225.177551/709: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.177551 last_received_ts = 225.177246 last_seq = 709 current_ts = 225.188644 current_received_ts = 225.188324 current_seq = 710 count = 638 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.177551/709, current 225.188644/710: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.188644 last_received_ts = 225.188324 last_seq = 710 current_ts = 225.199722 current_received_ts = 225.199417 current_seq = 711 count = 639 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.188644/710, current 225.199722/711: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.199722 last_received_ts = 225.199417 last_seq = 711 current_ts = 225.210815 current_received_ts = 225.210526 current_seq = 712 count = 640 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.199722/711, current 225.210815/712: elapsed=11094.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.210815 last_received_ts = 225.210526 last_seq = 712 current_ts = 225.221909 current_received_ts = 225.221588 current_seq = 713 count = 641 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.210815/712, current 225.221909/713: elapsed=11086.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.221909 last_received_ts = 225.221588 last_seq = 713 current_ts = 225.233002 current_received_ts = 225.232681 current_seq = 714 count = 642 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.221909/713, current 225.233002/714: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.233002 last_received_ts = 225.232681 last_seq = 714 current_ts = 225.244080 current_received_ts = 225.243790 current_seq = 715 count = 643 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.233002/714, current 225.244080/715: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.244080 last_received_ts = 225.243790 last_seq = 715 current_ts = 225.255173 current_received_ts = 225.254852 current_seq = 716 count = 644 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.244080/715, current 225.255173/716: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.255173 last_received_ts = 225.254852 last_seq = 716 current_ts = 225.266251 current_received_ts = 225.265930 current_seq = 717 count = 645 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.255173/716, current 225.266251/717: elapsed=11085.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.266251 last_received_ts = 225.265930 last_seq = 717 current_ts = 225.277344 current_received_ts = 225.277054 current_seq = 718 count = 646 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.266251/717, current 225.277344/718: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.277344 last_received_ts = 225.277054 last_seq = 718 current_ts = 225.288437 current_received_ts = 225.288116 current_seq = 719 count = 647 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.277344/718, current 225.288437/719: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.288437 last_received_ts = 225.288116 last_seq = 719 current_ts = 225.299530 current_received_ts = 225.299210 current_seq = 720 count = 648 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.288437/719, current 225.299530/720: elapsed=11093.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.299530 last_received_ts = 225.299210 last_seq = 720 current_ts = 225.310608 current_received_ts = 225.310287 current_seq = 721 count = 649 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.299530/720, current 225.310608/721: elapsed=11084.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.310608 last_received_ts = 225.310287 last_seq = 721 current_ts = 225.321701 current_received_ts = 225.321381 current_seq = 722 count = 650 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.310608/721, current 225.321701/722: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.321701 last_received_ts = 225.321381 last_seq = 722 current_ts = 225.332794 current_received_ts = 225.332520 current_seq = 723 count = 651 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.321701/722, current 225.332794/723: elapsed=11091.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.332794 last_received_ts = 225.332520 last_seq = 723 current_ts = 225.343872 current_received_ts = 225.343582 current_seq = 724 count = 652 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.332794/723, current 225.343872/724: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.343872 last_received_ts = 225.343582 last_seq = 724 current_ts = 225.354965 current_received_ts = 225.354660 current_seq = 725 count = 653 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.343872/724, current 225.354965/725: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.354965 last_received_ts = 225.354660 last_seq = 725 current_ts = 225.366058 current_received_ts = 225.365753 current_seq = 726 count = 654 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.354965/725, current 225.366058/726: elapsed=11088.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.366058 last_received_ts = 225.365753 last_seq = 726 current_ts = 225.377151 current_received_ts = 225.376846 current_seq = 727 count = 655 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.366058/726, current 225.377151/727: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.377151 last_received_ts = 225.376846 last_seq = 727 current_ts = 225.388245 current_received_ts = 225.387939 current_seq = 728 count = 656 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.377151/727, current 225.388245/728: elapsed=11093.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.388245 last_received_ts = 225.387939 last_seq = 728 current_ts = 225.399323 current_received_ts = 225.399033 current_seq = 729 count = 657 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.388245/728, current 225.399323/729: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.399323 last_received_ts = 225.399033 last_seq = 729 current_ts = 225.410416 current_received_ts = 225.410110 current_seq = 730 count = 658 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.399323/729, current 225.410416/730: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.410416 last_received_ts = 225.410110 last_seq = 730 current_ts = 225.421509 current_received_ts = 225.421204 current_seq = 731 count = 659 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.410416/730, current 225.421509/731: elapsed=11093.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.421509 last_received_ts = 225.421204 last_seq = 731 current_ts = 225.432602 current_received_ts = 225.432281 current_seq = 732 count = 660 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.421509/731, current 225.432602/732: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.432602 last_received_ts = 225.432281 last_seq = 732 current_ts = 225.443695 current_received_ts = 225.443375 current_seq = 733 count = 661 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.432602/732, current 225.443695/733: elapsed=11093.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.443695 last_received_ts = 225.443375 last_seq = 733 current_ts = 225.454773 current_received_ts = 225.454483 current_seq = 734 count = 662 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.443695/733, current 225.454773/734: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.454773 last_received_ts = 225.454483 last_seq = 734 current_ts = 225.465866 current_received_ts = 225.465561 current_seq = 735 count = 663 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.454773/734, current 225.465866/735: elapsed=11092.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.465866 last_received_ts = 225.465561 last_seq = 735 current_ts = 225.476959 current_received_ts = 225.476669 current_seq = 736 count = 664 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.465866/735, current 225.476959/736: elapsed=11092.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.476959 last_received_ts = 225.476669 last_seq = 736 current_ts = 225.488052 current_received_ts = 225.487732 current_seq = 737 count = 665 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.476959/736, current 225.488052/737: elapsed=11092.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.488052 last_received_ts = 225.487732 last_seq = 737 current_ts = 225.499146 current_received_ts = 225.498840 current_seq = 738 count = 666 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.488052/737, current 225.499146/738: elapsed=11087.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.499146 last_received_ts = 225.498840 last_seq = 738 current_ts = 225.510223 current_received_ts = 225.509918 current_seq = 739 count = 667 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.499146/738, current 225.510223/739: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.510223 last_received_ts = 225.509918 last_seq = 739 current_ts = 225.521317 current_received_ts = 225.521027 current_seq = 740 count = 668 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.510223/739, current 225.521317/740: elapsed=11094.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.521317 last_received_ts = 225.521027 last_seq = 740 current_ts = 225.532410 current_received_ts = 225.532120 current_seq = 741 count = 669 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.521317/740, current 225.532410/741: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.532410 last_received_ts = 225.532120 last_seq = 741 current_ts = 225.543503 current_received_ts = 225.543198 current_seq = 742 count = 670 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.532410/741, current 225.543503/742: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.543503 last_received_ts = 225.543198 last_seq = 742 current_ts = 225.554596 current_received_ts = 225.554321 current_seq = 743 count = 671 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.543503/742, current 225.554596/743: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.554596 last_received_ts = 225.554321 last_seq = 743 current_ts = 225.565689 current_received_ts = 225.565384 current_seq = 744 count = 672 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.554596/743, current 225.565689/744: elapsed=11092.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.565689 last_received_ts = 225.565384 last_seq = 744 current_ts = 225.576767 current_received_ts = 225.576462 current_seq = 745 count = 673 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.565689/744, current 225.576767/745: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.576767 last_received_ts = 225.576462 last_seq = 745 current_ts = 225.587860 current_received_ts = 225.587570 current_seq = 746 count = 674 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.576767/745, current 225.587860/746: elapsed=11089.0us expected=11061.6us +- 55.3us, error 0.2% (kms_flip:2440) DEBUG: name = flip last_ts = 225.587860 last_received_ts = 225.587570 last_seq = 746 current_ts = 225.598953 current_received_ts = 225.598633 current_seq = 747 count = 675 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.587860/746, current 225.598953/747: elapsed=11092.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: name = flip last_ts = 225.598953 last_received_ts = 225.598633 last_seq = 747 current_ts = 225.610046 current_received_ts = 225.609741 current_seq = 748 count = 676 seq_step = 1 (kms_flip:2440) DEBUG: flip ts/seq: last 225.598953/747, current 225.610046/748: elapsed=11090.0us expected=11061.6us +- 55.3us, error 0.3% (kms_flip:2440) DEBUG: expected 678, counted 677, encoder type 2 (kms_flip:2440) DEBUG: dropped frames, expected 678, counted 677, encoder type 2 (kms_flip:2440) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660: (kms_flip:2440) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon) (kms_flip:2440) igt_core-INFO: Stack trace: (kms_flip:2440) igt_core-INFO: #0 ../lib/igt_core.c:2055 __igt_fail_assert() (kms_flip:2440) igt_core-INFO: #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0() (kms_flip:2440) igt_core-INFO: #2 ../tests/kms_flip.c:1831 run_test() (kms_flip:2440) igt_core-INFO: #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987() (kms_flip:2440) igt_core-INFO: #4 ../tests/kms_flip.c:1987 main() (kms_flip:2440) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2440) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2440) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest C-eDP1: FAIL (12.252s)
Dmesg	<6> [263.565593] [IGT] kms_flip: starting dynamic subtest C-eDP1 <7> [263.566076] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:304] <7> [263.566147] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:305] <7> [263.577652] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [263.578373] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [263.605616] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [263.605814] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [263.629324] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [263.629538] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [263.655850] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [263.656042] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [263.686292] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A] <7> [263.686449] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off <7> [263.686704] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00 <7> [263.686981] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:134:pipe B] <7> [263.687056] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [263.687177] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [263.687329] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1) <7> [263.687445] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in lane_count (expected 4, found 0) <7> [263.687560] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in dp_m_n (expected tu 64 data 7483046/8388608 link 498869/524288, found tu 0, data 0/0 link 0/0) <7> [263.687674] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [263.687788] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [263.687902] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [263.688016] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [263.688132] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [263.688246] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [263.688398] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [263.688513] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [263.688631] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [263.688746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [263.688861] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [263.688972] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [263.689087] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1878, found 0) <7> [263.689202] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1878, found 0) <7> [263.689333] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [263.689449] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [263.689561] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [263.689675] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [263.689788] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [263.689902] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [263.690013] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [263.690125] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [263.690237] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [263.690364] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [263.690477] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1878, found 0) <7> [263.690591] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1878, found 0) <7> [263.690703] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [263.690817] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [263.690932] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [263.691059] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [263.691170] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [263.691288] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 513820, found 0) <7> [263.691416] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 513820, found 0) <7> [263.691528] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in port_clock (expected 540000, found 0) <7> [263.691644] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:134:pipe B] fastset requirement not met, forcing full modeset <7> [263.691782] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [263.691899] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:134:pipe B] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x2 -> 0x0 <7> [263.692031] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] ddb ( 0 - 4001) -> ( 0 - 0), size 4001 -> 0 <7> [263.692143] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:129:cursor B] ddb (4001 - 4096) -> ( 0 - 0), size 95 -> 0 <7> [263.692253] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84: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> [263.692385] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] lines 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [263.692510] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] blocks 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [263.692619] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] min_ddb 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [263.692731] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:134:pipe B] data rate 0 num active planes 0 <7> [263.692852] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 0 qgv_peak_bw: 51200 <7> [263.692979] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 51200 <7> [263.693101] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 51200 <7> [263.693245] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 51200 <7> [263.693381] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 0 <7> [263.693498] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing <7> [263.693612] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz <7> [263.693729] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0 <7> [263.693860] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:134:pipe B] enable: no [modeset] <7> [263.693988] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:84:plane 1B] fb: [NOFB], visible: no <7> [263.694113] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:93:plane 2B] fb: [NOFB], visible: no <7> [263.694239] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:102:plane 3B] fb: [NOFB], visible: no <7> [263.694382] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:111:plane 4B] fb: [NOFB], visible: no <7> [263.694497] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:120:plane 5B] fb: [NOFB], visible: no <7> [263.694612] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:129:cursor B] fb: [NOFB], visible: no <7> [263.694762] i915 0000:00:02.0: [drm:intel_psr_disable_locked [i915]] Disabling PSR2 <7> [263.695029] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD on <7> [263.695251] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006f <7> [263.695997] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]] <7> [263.902600] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 0 <7> [263.903253] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B <7> [263.906959] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power off <7> [263.907399] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x00000089, pins 0x00000010, long 0x00000000 <7> [263.907443] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power off time <7> [263.907870] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - short <7> [263.907974] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [263.957862] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [263.958467] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring short hpd on eDP [ENCODER:240:DDI A/PHY A] <7> [263.958467] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A <7> [263.959611] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A] <7> [263.959980] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010 <7> [263.960117] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B] <7> [263.960441] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long <7> [263.960542] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A] <7> [263.960868] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [263.960995] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B] <7> [263.961288] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A] <7> [263.961418] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C] <7> [263.961855] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D] <7> [263.962264] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1] <7> [263.962856] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A] <7> [263.963249] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B] <7> [263.963482] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C] <7> [263.963663] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D] <7> [263.963853] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2] <7> [263.964022] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3] <7> [263.964161] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A] <7> [263.964300] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B] <7> [263.964436] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C] <7> [263.964572] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D] <7> [263.964726] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4] <7> [263.964869] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A] <7> [263.965002] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B] <7> [263.965118] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C] <7> [263.965233] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D] <7> [263.965346] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1] <7> [263.965544] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no) <7> [263.965909] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: yes -> no (pipe: ) <7> [263.966294] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [263.966621] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_B <7> [263.966916] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [263.967225] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:134:pipe B] <7> [263.967492] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Post changing CDCLK to 172800 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [263.967656] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=432 <7> [263.967960] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:186:pipe C] <7> [263.968091] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:238:pipe D] <7> [263.968191] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:186:pipe C] <7> [263.968215] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:241:eDP-1] <7> [263.968262] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:241:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [263.968395] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:240:DDI A/PHY A][CRTC:186:pipe C] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 max link_bpp 30.0000 <7> [263.968508] i915 0000:00:02.0: [drm:intel_dp_compute_link_config [i915]] DP lane count 4 clock 540000 bpp input 30 compressed 0.0000 link rate required 1926825 available 2160000 <7> [263.968620] i915 0000:00:02.0: [drm:intel_psr_compute_config [i915]] PSR2 not supported in transcoder C <7> [263.968758] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:186:pipe C] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [263.968876] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:240:DDI A/PHY A] [CRTC:186:pipe C] <7> [263.968986] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [263.969104] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [263.969219] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [263.969333] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [263.969445] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7483046/8388608 link 498869/524288) <7> [263.969562] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [263.969690] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [263.969809] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [263.969919] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [263.970031] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [263.970141] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [263.970249] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [263.970358] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [263.970470] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [263.970580] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [263.970705] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [263.970839] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [263.970951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1878) <7> [263.971061] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1878) <7> [263.971172] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [263.971282] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [263.971392] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [263.971503] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [263.971614] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [263.971737] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [263.971862] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [263.971970] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [263.972078] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [263.972188] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [263.972298] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1878) <7> [263.972407] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1878) <7> [263.972516] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [263.972626] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [263.972749] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [263.972879] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [263.972990] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [263.973100] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 513820) <7> [263.973208] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 513820) <7> [263.973318] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:186:pipe C] fastset requirement not met in port_clock (expected 0, found 540000) <7> [263.973427] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:186:pipe C] fastset requirement not met, forcing full modeset <7> [263.973556] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no <7> [263.973668] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:186:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4 <7> [263.973836] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:136:plane 1C] ddb ( 0 - 0) -> ( 0 - 1953), size 0 -> 1953 <7> [263.973955] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:181:cursor C] ddb ( 0 - 0) -> (1953 - 2048), size 0 -> 95 <7> [263.974062] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:136:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,*stwm <7> [263.974168] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:136:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0 <7> [263.974277] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:136:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87 <7> [263.974385] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:136:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88 <7> [263.974495] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:186:pipe C] data rate 2055280 num active planes 1 <7> [263.974614] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200 <7> [263.974740] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [263.974866] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [263.974978] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [263.975090] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159 <7> [263.975209] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:136:plane 1C] min cdclk (256910 kHz) > [CRTC:186:pipe C] min cdclk (0 kHz) <7> [263.975322] i915 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [i915]] new bandwidth min cdclk (40143 kHz) > old min cdclk (0 kHz) <7> [263.975435] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing <7> [263.975548] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 307200 kHz, actual 307200 kHz <7> [263.975659] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0 <7> [263.975795] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:186:pipe C] enable: yes [modeset] <7> [263.975925] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [263.976037] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: C, pipe bpp: 30, dithering: 0 <7> [263.976151] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [263.976262] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [263.976374] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [263.976484] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [263.976594] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m_n: lanes: 4; data_m: 7483046, data_n: 8388608, link_m: 498869, link_n: 524288, tu: 64 <7> [263.976706] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [263.976926] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled <7> [263.977084] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled <7> [263.977237] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] psr: enabled, selective update: disabled, panel replay: disabled, selective fetch: disabled <7> [263.977398] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum HBlank: 0 <7> [263.977603] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [263.977719] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] DP SDP: VSC, revision 2, length 8 <7> [263.977851] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB <7> [263.977966] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB <7> [263.978078] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0 <7> [263.978187] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range <7> [263.978297] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined <7> [263.978457] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1 <7> [263.978615] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0 <7> [263.978754] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0 <7> [263.978882] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0 <7> [263.978995] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa <7> [263.979109] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa <7> [263.979222] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1878 vs=1803-1809 vt=1878, flags=0xa <7> [263.979335] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x40 0xa <7> [263.979447] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1878 vs=1803-1809 vt=1878, flags=0xa <7> [263.979557] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 540000, pipe src: 2880x1800+0+0, pixel rate 513820 <7> [263.979668] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 48, ips linetime: 0 <7> [263.979792] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [263.979919] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [263.980028] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [263.980138] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x83d60, dpll_md: 0xf42110, fp0: 0xf8, fp1: 0x1000000 <7> [263.980247] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [263.980357] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [263.980467] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [263.980579] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [263.980690] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [263.980813] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [263.980937] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [263.981046] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [263.981156] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [263.981267] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [263.981376] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [263.981486] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [263.981596] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:136:plane 1C] fb: [FB:304] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes <7> [263.981708] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [263.981873] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [263.981993] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:145:plane 2C] fb: [NOFB], visible: no <7> [263.982105] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:154:plane 3C] fb: [NOFB], visible: no <7> [263.982215] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:163:plane 4C] fb: [NOFB], visible: no <7> [263.982326] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:172:plane 5C] fb: [NOFB], visible: no <7> [263.982438] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:181:cursor C] fb: [NOFB], visible: no <7> [263.984322] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [263.984501] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_C <7> [263.984703] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 307200 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [263.984873] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=768 <7> [263.985011] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A] <7> [263.985130] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B] <7> [263.985243] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A] <7> [263.985352] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B] <7> [263.985462] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C] <7> [263.985573] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D] <7> [263.985683] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1] <7> [263.985814] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A] <7> [263.985936] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B] <7> [263.986043] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C] <7> [263.986150] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D] <7> [263.986257] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2] <7> [263.986365] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3] <7> [263.986471] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A] <7> [263.986579] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B] <7> [263.986689] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C] <7> [263.986818] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D] <7> [263.986941] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4] <7> [263.987050] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A] <7> [263.987158] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B] <7> [263.987266] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C] <7> [263.987373] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D] <7> [263.987482] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0xd <7> [263.987697] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no) <7> [263.987870] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A <7> [263.988843] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power on <7> [263.988989] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power cycle (470 ms remaining) <7> [264.465549] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [264.484944] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [264.485503] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power on <7> [264.486007] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [264.517346] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010 <7> [264.517819] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long <7> [264.518243] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [264.518680] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A] <7> [264.686282] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [264.688831] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD on <7> [264.689362] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [264.693182] i915 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c4 41 00 00 01 c0 02 00 00 00 00 0b 80 <7> [264.693990] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [264.694886] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 07 <7> [264.695848] i915 0000:00:02.0: [drm:intel_dp_set_signal_levels [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [264.696502] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [264.697620] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Clock recovery OK <7> [264.697727] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS3 <7> [264.699379] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [264.699489] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Link Training passed at link rate = 540000, lane count = 4 <7> [264.700066] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe C <7> [264.700298] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]] <7> [264.700406] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe C <7> [264.700569] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 13892 <7> [264.711552] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR1 <7> [264.712936] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1] <7> [264.713148] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:186:pipe C] <7> [267.228009] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD off <7> [267.228577] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <6> [275.817688] [IGT] kms_flip: finished subtest C-eDP1, FAIL

Created at 2025-03-21 22:58:27