igt@kms_flip@flip-vs-expired-vblank@a-edp1 on shard-lnl@xe-pw-167864v1 Test details

Detail	Value
Duration	4.01 seconds
Hostname	shard-lnl-1
Igt-Version	IGT-Version: 2.4-ge322bfd77 (x86_64) (Linux: 7.1.0-rc6-lgci-xe-xe-pw-167864v1-debug+ x86_64)
Out	Using IGT_SRANDOM=1780598138 for randomisation Opened device: /dev/dri/card0 Using monotonic timestamps Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2106 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-eDP1: FAIL (4.007s)
Err	Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 [205.373284] (kms_flip:4716) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [205.373425] (kms_flip:4716) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest A-eDP1 failed. ** DEBUG [203.355428] (kms_flip:4716) DEBUG: name = flip last_ts = 204.488419 last_received_ts = 204.487747 last_seq = 3628 current_ts = 204.505081 current_received_ts = 204.504410 current_seq = 3629 count = 33 seq_step = 1 [203.355569] (kms_flip:4716) DEBUG: Vblank took 138us [203.372087] (kms_flip:4716) DEBUG: name = flip last_ts = 204.505081 last_received_ts = 204.504410 last_seq = 3629 current_ts = 204.521744 current_received_ts = 204.521057 current_seq = 3630 count = 34 seq_step = 1 [203.372150] (kms_flip:4716) DEBUG: Vblank took 56us [203.388675] (kms_flip:4716) DEBUG: name = flip last_ts = 204.521744 last_received_ts = 204.521057 last_seq = 3630 current_ts = 204.538422 current_received_ts = 204.537659 current_seq = 3631 count = 35 seq_step = 1 [203.388802] (kms_flip:4716) DEBUG: Vblank took 123us [203.405438] (kms_flip:4716) DEBUG: name = flip last_ts = 204.538422 last_received_ts = 204.537659 last_seq = 3631 current_ts = 204.555084 current_received_ts = 204.554413 current_seq = 3632 count = 36 seq_step = 1 [203.405573] (kms_flip:4716) DEBUG: Vblank took 125us [203.422070] (kms_flip:4716) DEBUG: name = flip last_ts = 204.555084 last_received_ts = 204.554413 last_seq = 3632 current_ts = 204.571747 current_received_ts = 204.571060 current_seq = 3633 count = 37 seq_step = 1 [203.422128] (kms_flip:4716) DEBUG: Vblank took 53us [203.438747] (kms_flip:4716) DEBUG: name = flip last_ts = 204.571747 last_received_ts = 204.571060 last_seq = 3633 current_ts = 204.588409 current_received_ts = 204.587738 current_seq = 3634 count = 38 seq_step = 1 [203.438858] (kms_flip:4716) DEBUG: Vblank took 108us [203.455416] (kms_flip:4716) DEBUG: name = flip last_ts = 204.588409 last_received_ts = 204.587738 last_seq = 3634 current_ts = 204.605072 current_received_ts = 204.604401 current_seq = 3635 count = 39 seq_step = 1 [203.455544] (kms_flip:4716) DEBUG: Vblank took 121us [203.472135] (kms_flip:4716) DEBUG: name = flip last_ts = 204.605072 last_received_ts = 204.604401 last_seq = 3635 current_ts = 204.621735 current_received_ts = 204.621109 current_seq = 3636 count = 40 seq_step = 1 [203.472215] (kms_flip:4716) DEBUG: Vblank took 72us [203.488881] (kms_flip:4716) DEBUG: name = flip last_ts = 204.621735 last_received_ts = 204.621109 last_seq = 3636 current_ts = 204.638412 current_received_ts = 204.637863 current_seq = 3637 count = 41 seq_step = 1 [203.488950] (kms_flip:4716) DEBUG: Vblank took 60us [203.505399] (kms_flip:4716) DEBUG: name = flip last_ts = 204.638412 last_received_ts = 204.637863 last_seq = 3637 current_ts = 204.655075 current_received_ts = 204.654373 current_seq = 3638 count = 42 seq_step = 1 [203.505521] (kms_flip:4716) DEBUG: Vblank took 116us [203.522125] (kms_flip:4716) DEBUG: name = flip last_ts = 204.655075 last_received_ts = 204.654373 last_seq = 3638 current_ts = 204.671738 current_received_ts = 204.671112 current_seq = 3639 count = 43 seq_step = 1 [203.522208] (kms_flip:4716) DEBUG: Vblank took 75us [203.538848] (kms_flip:4716) DEBUG: name = flip last_ts = 204.671738 last_received_ts = 204.671112 last_seq = 3639 current_ts = 204.688400 current_received_ts = 204.687836 current_seq = 3640 count = 44 seq_step = 1 [203.538914] (kms_flip:4716) DEBUG: Vblank took 58us [203.555413] (kms_flip:4716) DEBUG: name = flip last_ts = 204.688400 last_received_ts = 204.687836 last_seq = 3640 current_ts = 204.705078 current_received_ts = 204.704391 current_seq = 3641 count = 45 seq_step = 1 [203.555552] (kms_flip:4716) DEBUG: Vblank took 133us [203.572135] (kms_flip:4716) DEBUG: name = flip last_ts = 204.705078 last_received_ts = 204.704391 last_seq = 3641 current_ts = 204.721741 current_received_ts = 204.721115 current_seq = 3642 count = 46 seq_step = 1 [203.572207] (kms_flip:4716) DEBUG: Vblank took 65us [203.588810] (kms_flip:4716) DEBUG: name = flip last_ts = 204.721741 last_received_ts = 204.721115 last_seq = 3642 current_ts = 204.738388 current_received_ts = 204.737793 current_seq = 3643 count = 47 seq_step = 1 [203.588868] (kms_flip:4716) DEBUG: Vblank took 51us [203.605403] (kms_flip:4716) DEBUG: name = flip last_ts = 204.738388 last_received_ts = 204.737793 last_seq = 3643 current_ts = 204.755066 current_received_ts = 204.754395 current_seq = 3644 count = 48 seq_step = 1 [203.605545] (kms_flip:4716) DEBUG: Vblank took 134us [203.622117] (kms_flip:4716) DEBUG: name = flip last_ts = 204.755066 last_received_ts = 204.754395 last_seq = 3644 current_ts = 204.771729 current_received_ts = 204.771103 current_seq = 3645 count = 49 seq_step = 1 [203.622189] (kms_flip:4716) DEBUG: Vblank took 64us [203.638822] (kms_flip:4716) DEBUG: name = flip last_ts = 204.771729 last_received_ts = 204.771103 last_seq = 3645 current_ts = 204.788391 current_received_ts = 204.787811 current_seq = 3646 count = 50 seq_step = 1 [203.638883] (kms_flip:4716) DEBUG: Vblank took 54us [203.655383] (kms_flip:4716) DEBUG: name = flip last_ts = 204.788391 last_received_ts = 204.787811 last_seq = 3646 current_ts = 204.805054 current_received_ts = 204.804367 current_seq = 3647 count = 51 seq_step = 1 [203.655505] (kms_flip:4716) DEBUG: Vblank took 115us [203.672139] (kms_flip:4716) DEBUG: name = flip last_ts = 204.805054 last_received_ts = 204.804367 last_seq = 3647 current_ts = 204.821716 current_received_ts = 204.821121 current_seq = 3648 count = 52 seq_step = 1 [203.672200] (kms_flip:4716) DEBUG: Vblank took 54us [203.688810] (kms_flip:4716) DEBUG: name = flip last_ts = 204.821716 last_received_ts = 204.821121 last_seq = 3648 current_ts = 204.838379 current_received_ts = 204.837799 current_seq = 3649 count = 53 seq_step = 1 [203.688869] (kms_flip:4716) DEBUG: Vblank took 51us [203.705393] (kms_flip:4716) DEBUG: name = flip last_ts = 204.838379 last_received_ts = 204.837799 last_seq = 3649 current_ts = 204.855057 current_received_ts = 204.854385 current_seq = 3650 count = 54 seq_step = 1 [203.705512] (kms_flip:4716) DEBUG: Vblank took 113us [203.722058] (kms_flip:4716) DEBUG: name = flip last_ts = 204.855057 last_received_ts = 204.854385 last_seq = 3650 current_ts = 204.871719 current_received_ts = 204.871048 current_seq = 3651 count = 55 seq_step = 1 [203.722186] (kms_flip:4716) DEBUG: Vblank took 120us [203.738714] (kms_flip:4716) DEBUG: name = flip last_ts = 204.871719 last_received_ts = 204.871048 last_seq = 3651 current_ts = 204.888382 current_received_ts = 204.887711 current_seq = 3652 count = 56 seq_step = 1 [203.738831] (kms_flip:4716) DEBUG: Vblank took 109us [203.755397] (kms_flip:4716) DEBUG: name = flip last_ts = 204.888382 last_received_ts = 204.887711 last_seq = 3652 current_ts = 204.905045 current_received_ts = 204.904388 current_seq = 3653 count = 57 seq_step = 1 [203.755518] (kms_flip:4716) DEBUG: Vblank took 113us [203.772068] (kms_flip:4716) DEBUG: name = flip last_ts = 204.905045 last_received_ts = 204.904388 last_seq = 3653 current_ts = 204.921707 current_received_ts = 204.921066 current_seq = 3654 count = 58 seq_step = 1 [203.772149] (kms_flip:4716) DEBUG: Vblank took 74us [203.788700] (kms_flip:4716) DEBUG: name = flip last_ts = 204.921707 last_received_ts = 204.921066 last_seq = 3654 current_ts = 204.938370 current_received_ts = 204.937698 current_seq = 3655 count = 59 seq_step = 1 [203.788821] (kms_flip:4716) DEBUG: Vblank took 113us [203.805282] (kms_flip:4716) DEBUG: name = flip last_ts = 204.938370 last_received_ts = 204.937698 last_seq = 3655 current_ts = 204.955032 current_received_ts = 204.954285 current_seq = 3656 count = 60 seq_step = 1 [203.805415] (kms_flip:4716) DEBUG: Vblank took 129us [203.822052] (kms_flip:4716) DEBUG: name = flip last_ts = 204.955032 last_received_ts = 204.954285 last_seq = 3656 current_ts = 204.971695 current_received_ts = 204.971054 current_seq = 3657 count = 61 seq_step = 1 [203.822149] (kms_flip:4716) DEBUG: Vblank took 90us [203.838693] (kms_flip:4716) DEBUG: name = flip last_ts = 204.971695 last_received_ts = 204.971054 last_seq = 3657 current_ts = 204.988373 current_received_ts = 204.987686 current_seq = 3658 count = 62 seq_step = 1 [203.838819] (kms_flip:4716) DEBUG: Vblank took 119us [203.855325] (kms_flip:4716) DEBUG: name = flip last_ts = 204.988373 last_received_ts = 204.987686 last_seq = 3658 current_ts = 205.005035 current_received_ts = 205.004333 current_seq = 3659 count = 63 seq_step = 1 [203.855446] (kms_flip:4716) DEBUG: Vblank took 119us [203.872044] (kms_flip:4716) DEBUG: name = flip last_ts = 205.005035 last_received_ts = 205.004333 last_seq = 3659 current_ts = 205.021698 current_received_ts = 205.021042 current_seq = 3660 count = 64 seq_step = 1 [203.872159] (kms_flip:4716) DEBUG: Vblank took 107us [203.888776] (kms_flip:4716) DEBUG: name = flip last_ts = 205.021698 last_received_ts = 205.021042 last_seq = 3660 current_ts = 205.038361 current_received_ts = 205.037781 current_seq = 3661 count = 65 seq_step = 1 [203.888834] (kms_flip:4716) DEBUG: Vblank took 51us [203.905360] (kms_flip:4716) DEBUG: name = flip last_ts = 205.038361 last_received_ts = 205.037781 last_seq = 3661 current_ts = 205.055023 current_received_ts = 205.054367 current_seq = 3662 count = 66 seq_step = 1 [203.905475] (kms_flip:4716) DEBUG: Vblank took 107us [203.922061] (kms_flip:4716) DEBUG: name = flip last_ts = 205.055023 last_received_ts = 205.054367 last_seq = 3662 current_ts = 205.071686 current_received_ts = 205.071060 current_seq = 3663 count = 67 seq_step = 1 [203.922149] (kms_flip:4716) DEBUG: Vblank took 80us [203.938668] (kms_flip:4716) DEBUG: name = flip last_ts = 205.071686 last_received_ts = 205.071060 last_seq = 3663 current_ts = 205.088364 current_received_ts = 205.087662 current_seq = 3664 count = 68 seq_step = 1 [203.938793] (kms_flip:4716) DEBUG: Vblank took 118us [203.955312] (kms_flip:4716) DEBUG: name = flip last_ts = 205.088364 last_received_ts = 205.087662 last_seq = 3664 current_ts = 205.105026 current_received_ts = 205.104324 current_seq = 3665 count = 69 seq_step = 1 [203.955435] (kms_flip:4716) DEBUG: Vblank took 120us [203.972044] (kms_flip:4716) DEBUG: name = flip last_ts = 205.105026 last_received_ts = 205.104324 last_seq = 3665 current_ts = 205.121689 current_received_ts = 205.121048 current_seq = 3666 count = 70 seq_step = 1 [203.972134] (kms_flip:4716) DEBUG: Vblank took 82us [203.988668] (kms_flip:4716) DEBUG: name = flip last_ts = 205.121689 last_received_ts = 205.121048 last_seq = 3666 current_ts = 205.138351 current_received_ts = 205.137665 current_seq = 3667 count = 71 seq_step = 1 [203.988789] (kms_flip:4716) DEBUG: Vblank took 113us [204.005291] (kms_flip:4716) DEBUG: name = flip last_ts = 205.138351 last_received_ts = 205.137665 last_seq = 3667 current_ts = 205.155014 current_received_ts = 205.154297 current_seq = 3668 count = 72 seq_step = 1 [204.005425] (kms_flip:4716) DEBUG: Vblank took 131us [204.022041] (kms_flip:4716) DEBUG: name = flip last_ts = 205.155014 last_received_ts = 205.154297 last_seq = 3668 current_ts = 205.171677 current_received_ts = 205.171051 current_seq = 3669 count = 73 seq_step = 1 [204.022143] (kms_flip:4716) DEBUG: Vblank took 94us [204.038688] (kms_flip:4716) DEBUG: name = flip last_ts = 205.171677 last_received_ts = 205.171051 last_seq = 3669 current_ts = 205.188354 current_received_ts = 205.187698 current_seq = 3670 count = 74 seq_step = 1 [204.038801] (kms_flip:4716) DEBUG: Vblank took 107us [204.055324] (kms_flip:4716) DEBUG: name = flip last_ts = 205.188354 last_received_ts = 205.187698 last_seq = 3670 current_ts = 205.205002 current_received_ts = 205.204330 current_seq = 3671 count = 75 seq_step = 1 [204.055452] (kms_flip:4716) DEBUG: Vblank took 124us [204.072038] (kms_flip:4716) DEBUG: name = flip last_ts = 205.205002 last_received_ts = 205.204330 last_seq = 3671 current_ts = 205.221664 current_received_ts = 205.221039 current_seq = 3672 count = 76 seq_step = 1 [204.072117] (kms_flip:4716) DEBUG: Vblank took 72us [204.088666] (kms_flip:4716) DEBUG: name = flip last_ts = 205.221664 last_received_ts = 205.221039 last_seq = 3672 current_ts = 205.238342 current_received_ts = 205.237671 current_seq = 3673 count = 77 seq_step = 1 [204.088786] (kms_flip:4716) DEBUG: Vblank took 112us [204.105296] (kms_flip:4716) DEBUG: name = flip last_ts = 205.238342 last_received_ts = 205.237671 last_seq = 3673 current_ts = 205.255005 current_received_ts = 205.254303 current_seq = 3674 count = 78 seq_step = 1 [204.105441] (kms_flip:4716) DEBUG: Vblank took 141us [204.122111] (kms_flip:4716) DEBUG: name = flip last_ts = 205.255005 last_received_ts = 205.254303 last_seq = 3674 current_ts = 205.271667 current_received_ts = 205.271118 current_seq = 3675 count = 79 seq_step = 1 [204.122150] (kms_flip:4716) DEBUG: Vblank took 31us [204.138671] (kms_flip:4716) DEBUG: name = flip last_ts = 205.271667 last_received_ts = 205.271118 last_seq = 3675 current_ts = 205.288330 current_received_ts = 205.287674 current_seq = 3676 count = 80 seq_step = 1 [204.138726] (kms_flip:4716) DEBUG: Vblank took 44us [204.155321] (kms_flip:4716) DEBUG: name = flip last_ts = 205.288330 last_received_ts = 205.287674 last_seq = 3676 current_ts = 205.304993 current_received_ts = 205.304337 current_seq = 3677 count = 81 seq_step = 1 [204.155434] (kms_flip:4716) DEBUG: Vblank took 104us [204.172043] (kms_flip:4716) DEBUG: name = flip last_ts = 205.304993 last_received_ts = 205.304337 last_seq = 3677 current_ts = 205.321671 current_received_ts = 205.321060 current_seq = 3678 count = 82 seq_step = 1 [204.172123] (kms_flip:4716) DEBUG: Vblank took 72us [204.188648] (kms_flip:4716) DEBUG: name = flip last_ts = 205.321671 last_received_ts = 205.321060 last_seq = 3678 current_ts = 205.338333 current_received_ts = 205.337662 current_seq = 3679 count = 83 seq_step = 1 [204.188771] (kms_flip:4716) DEBUG: Vblank took 115us [204.205290] (kms_flip:4716) DEBUG: name = flip last_ts = 205.338333 last_received_ts = 205.337662 last_seq = 3679 current_ts = 205.354996 current_received_ts = 205.354309 current_seq = 3680 count = 84 seq_step = 1 [204.205421] (kms_flip:4716) DEBUG: Vblank took 127us [204.222042] (kms_flip:4716) DEBUG: name = flip last_ts = 205.354996 last_received_ts = 205.354309 last_seq = 3680 current_ts = 205.371658 current_received_ts = 205.371048 current_seq = 3681 count = 85 seq_step = 1 [204.222107] (kms_flip:4716) DEBUG: Vblank took 58us [204.238646] (kms_flip:4716) DEBUG: name = flip last_ts = 205.371658 last_received_ts = 205.371048 last_seq = 3681 current_ts = 205.388321 current_received_ts = 205.387665 current_seq = 3682 count = 86 seq_step = 1 [204.238780] (kms_flip:4716) DEBUG: Vblank took 127us [204.255253] (kms_flip:4716) DEBUG: name = flip last_ts = 205.388321 last_received_ts = 205.387665 last_seq = 3682 current_ts = 205.404984 current_received_ts = 205.404282 current_seq = 3683 count = 87 seq_step = 1 [204.255376] (kms_flip:4716) DEBUG: Vblank took 120us [204.272037] (kms_flip:4716) DEBUG: name = flip last_ts = 205.404984 last_received_ts = 205.404282 last_seq = 3683 current_ts = 205.421646 current_received_ts = 205.421051 current_seq = 3684 count = 88 seq_step = 1 [204.272098] (kms_flip:4716) DEBUG: Vblank took 53us [204.288628] (kms_flip:4716) DEBUG: name = flip last_ts = 205.421646 last_received_ts = 205.421051 last_seq = 3684 current_ts = 205.438309 current_received_ts = 205.437637 current_seq = 3685 count = 89 seq_step = 1 [204.288745] (kms_flip:4716) DEBUG: Vblank took 109us [204.305244] (kms_flip:4716) DEBUG: name = flip last_ts = 205.438309 last_received_ts = 205.437637 last_seq = 3685 current_ts = 205.454987 current_received_ts = 205.454269 current_seq = 3686 count = 90 seq_step = 1 [204.305372] (kms_flip:4716) DEBUG: Vblank took 125us [204.322017] (kms_flip:4716) DEBUG: name = flip last_ts = 205.454987 last_received_ts = 205.454269 last_seq = 3686 current_ts = 205.471649 current_received_ts = 205.471039 current_seq = 3687 count = 91 seq_step = 1 [204.322075] (kms_flip:4716) DEBUG: Vblank took 50us [204.338609] (kms_flip:4716) DEBUG: name = flip last_ts = 205.471649 last_received_ts = 205.471039 last_seq = 3687 current_ts = 205.488312 current_received_ts = 205.487625 current_seq = 3688 count = 92 seq_step = 1 [204.338730] (kms_flip:4716) DEBUG: Vblank took 114us [204.355270] (kms_flip:4716) DEBUG: name = flip last_ts = 205.488312 last_received_ts = 205.487625 last_seq = 3688 current_ts = 205.504974 current_received_ts = 205.504303 current_seq = 3689 count = 93 seq_step = 1 [204.355396] (kms_flip:4716) DEBUG: Vblank took 123us [204.372032] (kms_flip:4716) DEBUG: name = flip last_ts = 205.504974 last_received_ts = 205.504303 last_seq = 3689 current_ts = 205.521637 current_received_ts = 205.521057 current_seq = 3690 count = 94 seq_step = 1 [204.372094] (kms_flip:4716) DEBUG: Vblank took 55us [204.388622] (kms_flip:4716) DEBUG: name = flip last_ts = 205.521637 last_received_ts = 205.521057 last_seq = 3690 current_ts = 205.538300 current_received_ts = 205.537643 current_seq = 3691 count = 95 seq_step = 1 [204.388750] (kms_flip:4716) DEBUG: Vblank took 121us [204.405244] (kms_flip:4716) DEBUG: name = flip last_ts = 205.538300 last_received_ts = 205.537643 last_seq = 3691 current_ts = 205.554977 current_received_ts = 205.554276 current_seq = 3692 count = 96 seq_step = 1 [204.405370] (kms_flip:4716) DEBUG: Vblank took 123us [204.422015] (kms_flip:4716) DEBUG: name = flip last_ts = 205.554977 last_received_ts = 205.554276 last_seq = 3692 current_ts = 205.571640 current_received_ts = 205.571030 current_seq = 3693 count = 97 seq_step = 1 [204.422126] (kms_flip:4716) DEBUG: Vblank took 103us [204.438595] (kms_flip:4716) DEBUG: name = flip last_ts = 205.571640 last_received_ts = 205.571030 last_seq = 3693 current_ts = 205.588303 current_received_ts = 205.587616 current_seq = 3694 count = 98 seq_step = 1 [204.438716] (kms_flip:4716) DEBUG: Vblank took 113us [204.455227] (kms_flip:4716) DEBUG: name = flip last_ts = 205.588303 last_received_ts = 205.587616 last_seq = 3694 current_ts = 205.604965 current_received_ts = 205.604263 current_seq = 3695 count = 99 seq_step = 1 [204.455351] (kms_flip:4716) DEBUG: Vblank took 121us [204.471861] (kms_flip:4716) DEBUG: name = flip last_ts = 205.604965 last_received_ts = 205.604263 last_seq = 3695 current_ts = 205.621628 current_received_ts = 205.620895 current_seq = 3696 count = 100 seq_step = 1 [204.471904] (kms_flip:4716) DEBUG: Vblank took 41us [204.488598] (kms_flip:4716) DEBUG: name = flip last_ts = 205.621628 last_received_ts = 205.620895 last_seq = 3696 current_ts = 205.638290 current_received_ts = 205.637619 current_seq = 3697 count = 101 seq_step = 1 [204.488713] (kms_flip:4716) DEBUG: Vblank took 107us [204.505248] (kms_flip:4716) DEBUG: name = flip last_ts = 205.638290 last_received_ts = 205.637619 last_seq = 3697 current_ts = 205.654968 current_received_ts = 205.654282 current_seq = 3698 count = 102 seq_step = 1 [204.505375] (kms_flip:4716) DEBUG: Vblank took 124us [204.522006] (kms_flip:4716) DEBUG: name = flip last_ts = 205.654968 last_received_ts = 205.654282 last_seq = 3698 current_ts = 205.671631 current_received_ts = 205.671036 current_seq = 3699 count = 103 seq_step = 1 [204.522071] (kms_flip:4716) DEBUG: Vblank took 57us [204.538577] (kms_flip:4716) DEBUG: name = flip last_ts = 205.671631 last_received_ts = 205.671036 last_seq = 3699 current_ts = 205.688293 current_received_ts = 205.687607 current_seq = 3700 count = 104 seq_step = 1 [204.538710] (kms_flip:4716) DEBUG: Vblank took 125us [204.555215] (kms_flip:4716) DEBUG: name = flip last_ts = 205.688293 last_received_ts = 205.687607 last_seq = 3700 current_ts = 205.704956 current_received_ts = 205.704254 current_seq = 3701 count = 105 seq_step = 1 [204.555366] (kms_flip:4716) DEBUG: Vblank took 149us [204.572023] (kms_flip:4716) DEBUG: name = flip last_ts = 205.704956 last_received_ts = 205.704254 last_seq = 3701 current_ts = 205.721619 current_received_ts = 205.721054 current_seq = 3702 count = 106 seq_step = 1 [204.572085] (kms_flip:4716) DEBUG: Vblank took 55us [204.588717] (kms_flip:4716) DEBUG: name = flip last_ts = 205.721619 last_received_ts = 205.721054 last_seq = 3702 current_ts = 205.738281 current_received_ts = 205.737747 current_seq = 3703 count = 107 seq_step = 1 [204.588784] (kms_flip:4716) DEBUG: Vblank took 60us [204.605317] (kms_flip:4716) DEBUG: name = flip last_ts = 205.738281 last_received_ts = 205.737747 last_seq = 3703 current_ts = 205.754944 current_received_ts = 205.754349 current_seq = 3704 count = 108 seq_step = 1 [204.605444] (kms_flip:4716) DEBUG: Vblank took 119us [204.622015] (kms_flip:4716) DEBUG: name = flip last_ts = 205.754944 last_received_ts = 205.754349 last_seq = 3704 current_ts = 205.771606 current_received_ts = 205.771042 current_seq = 3705 count = 109 seq_step = 1 [204.622091] (kms_flip:4716) DEBUG: Vblank took 68us [204.638668] (kms_flip:4716) DEBUG: name = flip last_ts = 205.771606 last_received_ts = 205.771042 last_seq = 3705 current_ts = 205.788284 current_received_ts = 205.787704 current_seq = 3706 count = 110 seq_step = 1 [204.638734] (kms_flip:4716) DEBUG: Vblank took 59us [204.655308] (kms_flip:4716) DEBUG: name = flip last_ts = 205.788284 last_received_ts = 205.787704 last_seq = 3706 current_ts = 205.804947 current_received_ts = 205.804337 current_seq = 3707 count = 111 seq_step = 1 [204.655438] (kms_flip:4716) DEBUG: Vblank took 123us [204.672011] (kms_flip:4716) DEBUG: name = flip last_ts = 205.804947 last_received_ts = 205.804337 last_seq = 3707 current_ts = 205.821609 current_received_ts = 205.821045 current_seq = 3708 count = 112 seq_step = 1 [204.672078] (kms_flip:4716) DEBUG: Vblank took 59us [204.688663] (kms_flip:4716) DEBUG: name = flip last_ts = 205.821609 last_received_ts = 205.821045 last_seq = 3708 current_ts = 205.838272 current_received_ts = 205.837692 current_seq = 3709 count = 113 seq_step = 1 [204.688731] (kms_flip:4716) DEBUG: Vblank took 61us [204.705329] (kms_flip:4716) DEBUG: name = flip last_ts = 205.838272 last_received_ts = 205.837692 last_seq = 3709 current_ts = 205.854935 current_received_ts = 205.854370 current_seq = 3710 count = 114 seq_step = 1 [204.705472] (kms_flip:4716) DEBUG: Vblank took 135us [204.722016] (kms_flip:4716) DEBUG: name = flip last_ts = 205.854935 last_received_ts = 205.854370 last_seq = 3710 current_ts = 205.871597 current_received_ts = 205.871048 current_seq = 3711 count = 115 seq_step = 1 [204.722086] (kms_flip:4716) DEBUG: Vblank took 62us [204.738650] (kms_flip:4716) DEBUG: name = flip last_ts = 205.871597 last_received_ts = 205.871048 last_seq = 3711 current_ts = 205.888260 current_received_ts = 205.887695 current_seq = 3712 count = 116 seq_step = 1 [204.738717] (kms_flip:4716) DEBUG: Vblank took 60us [204.755319] (kms_flip:4716) DEBUG: name = flip last_ts = 205.888260 last_received_ts = 205.887695 last_seq = 3712 current_ts = 205.904922 current_received_ts = 205.904358 current_seq = 3713 count = 117 seq_step = 1 [204.755459] (kms_flip:4716) DEBUG: Vblank took 133us [204.771994] (kms_flip:4716) DEBUG: name = flip last_ts = 205.904922 last_received_ts = 205.904358 last_seq = 3713 current_ts = 205.921585 current_received_ts = 205.921036 current_seq = 3714 count = 118 seq_step = 1 [204.772060] (kms_flip:4716) DEBUG: Vblank took 59us [204.788655] (kms_flip:4716) DEBUG: name = flip last_ts = 205.921585 last_received_ts = 205.921036 last_seq = 3714 current_ts = 205.938263 current_received_ts = 205.937698 current_seq = 3715 count = 119 seq_step = 1 [204.788722] (kms_flip:4716) DEBUG: Vblank took 60us [204.805314] (kms_flip:4716) DEBUG: name = flip last_ts = 205.938263 last_received_ts = 205.937698 last_seq = 3715 current_ts = 205.954926 current_received_ts = 205.954361 current_seq = 3716 count = 120 seq_step = 1 [204.805445] (kms_flip:4716) DEBUG: Vblank took 123us [204.821999] (kms_flip:4716) DEBUG: name = flip last_ts = 205.954926 last_received_ts = 205.954361 last_seq = 3716 current_ts = 205.971588 current_received_ts = 205.971039 current_seq = 3717 count = 121 seq_step = 1 [204.822075] (kms_flip:4716) DEBUG: Vblank took 68us [204.838635] (kms_flip:4716) DEBUG: name = flip last_ts = 205.971588 last_received_ts = 205.971039 last_seq = 3717 current_ts = 205.988251 current_received_ts = 205.987671 current_seq = 3718 count = 122 seq_step = 1 [204.838701] (kms_flip:4716) DEBUG: Vblank took 59us [204.855278] (kms_flip:4716) DEBUG: name = flip last_ts = 205.988251 last_received_ts = 205.987671 last_seq = 3718 current_ts = 206.004913 current_received_ts = 206.004318 current_seq = 3719 count = 123 seq_step = 1 [204.855424] (kms_flip:4716) DEBUG: Vblank took 139us [204.871982] (kms_flip:4716) DEBUG: name = flip last_ts = 206.004913 last_received_ts = 206.004318 last_seq = 3719 current_ts = 206.021576 current_received_ts = 206.021027 current_seq = 3720 count = 124 seq_step = 1 [204.872049] (kms_flip:4716) DEBUG: Vblank took 59us [204.888657] (kms_flip:4716) DEBUG: name = flip last_ts = 206.021576 last_received_ts = 206.021027 last_seq = 3720 current_ts = 206.038239 current_received_ts = 206.037704 current_seq = 3721 count = 125 seq_step = 1 [204.888727] (kms_flip:4716) DEBUG: Vblank took 62us [204.905255] (kms_flip:4716) DEBUG: name = flip last_ts = 206.038239 last_received_ts = 206.037704 last_seq = 3721 current_ts = 206.054916 current_received_ts = 206.054306 current_seq = 3722 count = 126 seq_step = 1 [204.905385] (kms_flip:4716) DEBUG: Vblank took 122us [204.922008] (kms_flip:4716) DEBUG: name = flip last_ts = 206.054916 last_received_ts = 206.054306 last_seq = 3722 current_ts = 206.071579 current_received_ts = 206.071060 current_seq = 3723 count = 127 seq_step = 1 [204.922076] (kms_flip:4716) DEBUG: Vblank took 61us [204.938628] (kms_flip:4716) DEBUG: name = flip last_ts = 206.071579 last_received_ts = 206.071060 last_seq = 3723 current_ts = 206.088242 current_received_ts = 206.087677 current_seq = 3724 count = 128 seq_step = 1 [204.938694] (kms_flip:4716) DEBUG: Vblank took 60us [204.955266] (kms_flip:4716) DEBUG: name = flip last_ts = 206.088242 last_received_ts = 206.087677 last_seq = 3724 current_ts = 206.104904 current_received_ts = 206.104309 current_seq = 3725 count = 129 seq_step = 1 [204.955410] (kms_flip:4716) DEBUG: Vblank took 137us [204.971933] (kms_flip:4716) DEBUG: name = flip last_ts = 206.104904 last_received_ts = 206.104309 last_seq = 3725 current_ts = 206.121567 current_received_ts = 206.120987 current_seq = 3726 count = 130 seq_step = 1 [204.972025] (kms_flip:4716) DEBUG: Vblank took 84us [204.988609] (kms_flip:4716) DEBUG: name = flip last_ts = 206.121567 last_received_ts = 206.120987 last_seq = 3726 current_ts = 206.138229 current_received_ts = 206.137665 current_seq = 3727 count = 131 seq_step = 1 [204.988678] (kms_flip:4716) DEBUG: Vblank took 61us [205.005247] (kms_flip:4716) DEBUG: name = flip last_ts = 206.138229 last_received_ts = 206.137665 last_seq = 3727 current_ts = 206.154892 current_received_ts = 206.154297 current_seq = 3728 count = 132 seq_step = 1 [205.005395] (kms_flip:4716) DEBUG: Vblank took 140us [205.021934] (kms_flip:4716) DEBUG: name = flip last_ts = 206.154892 last_received_ts = 206.154297 last_seq = 3728 current_ts = 206.171570 current_received_ts = 206.170990 current_seq = 3729 count = 133 seq_step = 1 [205.022033] (kms_flip:4716) DEBUG: Vblank took 65us [205.038607] (kms_flip:4716) DEBUG: name = flip last_ts = 206.171570 last_received_ts = 206.170990 last_seq = 3729 current_ts = 206.188232 current_received_ts = 206.187653 current_seq = 3730 count = 134 seq_step = 1 [205.038676] (kms_flip:4716) DEBUG: Vblank took 62us [205.055268] (kms_flip:4716) DEBUG: name = flip last_ts = 206.188232 last_received_ts = 206.187653 last_seq = 3730 current_ts = 206.204895 current_received_ts = 206.204315 current_seq = 3731 count = 135 seq_step = 1 [205.055406] (kms_flip:4716) DEBUG: Vblank took 131us [205.071933] (kms_flip:4716) DEBUG: name = flip last_ts = 206.204895 last_received_ts = 206.204315 last_seq = 3731 current_ts = 206.221558 current_received_ts = 206.220993 current_seq = 3732 count = 136 seq_step = 1 [205.072027] (kms_flip:4716) DEBUG: Vblank took 61us [205.088615] (kms_flip:4716) DEBUG: name = flip last_ts = 206.221558 last_received_ts = 206.220993 last_seq = 3732 current_ts = 206.238220 current_received_ts = 206.237671 current_seq = 3733 count = 137 seq_step = 1 [205.088687] (kms_flip:4716) DEBUG: Vblank took 64us [205.105260] (kms_flip:4716) DEBUG: name = flip last_ts = 206.238220 last_received_ts = 206.237671 last_seq = 3733 current_ts = 206.254898 current_received_ts = 206.254318 current_seq = 3734 count = 138 seq_step = 1 [205.105403] (kms_flip:4716) DEBUG: Vblank took 135us [205.121906] (kms_flip:4716) DEBUG: name = flip last_ts = 206.254898 last_received_ts = 206.254318 last_seq = 3734 current_ts = 206.271545 current_received_ts = 206.270966 current_seq = 3735 count = 139 seq_step = 1 [205.122000] (kms_flip:4716) DEBUG: Vblank took 87us [205.138670] (kms_flip:4716) DEBUG: name = flip last_ts = 206.271545 last_received_ts = 206.270966 last_seq = 3735 current_ts = 206.288223 current_received_ts = 206.287689 current_seq = 3736 count = 140 seq_step = 1 [205.138845] (kms_flip:4716) DEBUG: Vblank took 147us [205.155302] (kms_flip:4716) DEBUG: name = flip last_ts = 206.288223 last_received_ts = 206.287689 last_seq = 3736 current_ts = 206.304886 current_received_ts = 206.304352 current_seq = 3737 count = 141 seq_step = 1 [205.155428] (kms_flip:4716) DEBUG: Vblank took 110us [205.172007] (kms_flip:4716) DEBUG: name = flip last_ts = 206.304886 last_received_ts = 206.304352 last_seq = 3737 current_ts = 206.321548 current_received_ts = 206.321045 current_seq = 3738 count = 142 seq_step = 1 [205.172147] (kms_flip:4716) DEBUG: Vblank took 121us [205.188596] (kms_flip:4716) DEBUG: name = flip last_ts = 206.321548 last_received_ts = 206.321045 last_seq = 3738 current_ts = 206.338211 current_received_ts = 206.337646 current_seq = 3739 count = 143 seq_step = 1 [205.188700] (kms_flip:4716) DEBUG: Vblank took 95us [205.205262] (kms_flip:4716) DEBUG: name = flip last_ts = 206.338211 last_received_ts = 206.337646 last_seq = 3739 current_ts = 206.354889 current_received_ts = 206.354324 current_seq = 3740 count = 144 seq_step = 1 [205.205350] (kms_flip:4716) DEBUG: Vblank took 80us [205.221959] (kms_flip:4716) DEBUG: name = flip last_ts = 206.354889 last_received_ts = 206.354324 last_seq = 3740 current_ts = 206.371536 current_received_ts = 206.370987 current_seq = 3741 count = 145 seq_step = 1 [205.222047] (kms_flip:4716) DEBUG: Vblank took 81us [205.238596] (kms_flip:4716) DEBUG: name = flip last_ts = 206.371536 last_received_ts = 206.370987 last_seq = 3741 current_ts = 206.388199 current_received_ts = 206.387650 current_seq = 3742 count = 146 seq_step = 1 [205.238676] (kms_flip:4716) DEBUG: Vblank took 73us [205.255256] (kms_flip:4716) DEBUG: name = flip last_ts = 206.388199 last_received_ts = 206.387650 last_seq = 3742 current_ts = 206.404877 current_received_ts = 206.404312 current_seq = 3743 count = 147 seq_step = 1 [205.255336] (kms_flip:4716) DEBUG: Vblank took 75us [205.271972] (kms_flip:4716) DEBUG: name = flip last_ts = 206.404877 last_received_ts = 206.404312 last_seq = 3743 current_ts = 206.421539 current_received_ts = 206.421036 current_seq = 3744 count = 148 seq_step = 1 [205.272053] (kms_flip:4716) DEBUG: Vblank took 73us [205.288600] (kms_flip:4716) DEBUG: name = flip last_ts = 206.421539 last_received_ts = 206.421036 last_seq = 3744 current_ts = 206.438202 current_received_ts = 206.437668 current_seq = 3745 count = 149 seq_step = 1 [205.288682] (kms_flip:4716) DEBUG: Vblank took 76us [205.305261] (kms_flip:4716) DEBUG: name = flip last_ts = 206.438202 last_received_ts = 206.437668 last_seq = 3745 current_ts = 206.454865 current_received_ts = 206.454330 current_seq = 3746 count = 150 seq_step = 1 [205.305345] (kms_flip:4716) DEBUG: Vblank took 76us [205.321908] (kms_flip:4716) DEBUG: name = flip last_ts = 206.454865 last_received_ts = 206.454330 last_seq = 3746 current_ts = 206.471527 current_received_ts = 206.470978 current_seq = 3747 count = 151 seq_step = 1 [205.322020] (kms_flip:4716) DEBUG: Vblank took 105us [205.338482] (kms_flip:4716) DEBUG: name = flip last_ts = 206.471527 last_received_ts = 206.470978 last_seq = 3747 current_ts = 206.488190 current_received_ts = 206.487549 current_seq = 3748 count = 152 seq_step = 1 [205.338577] (kms_flip:4716) DEBUG: Vblank took 82us [205.355169] (kms_flip:4716) DEBUG: name = flip last_ts = 206.488190 last_received_ts = 206.487549 last_seq = 3748 current_ts = 206.504868 current_received_ts = 206.504227 current_seq = 3749 count = 153 seq_step = 1 [205.355271] (kms_flip:4716) DEBUG: Vblank took 91us [205.371914] (kms_flip:4716) DEBUG: name = flip last_ts = 206.504868 last_received_ts = 206.504227 last_seq = 3749 current_ts = 206.521530 current_received_ts = 206.520981 current_seq = 3750 count = 154 seq_step = 1 [205.373275] (kms_flip:4716) DEBUG: Vblank took 1351us [205.373284] (kms_flip:4716) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [205.373425] (kms_flip:4716) CRITICAL: Failed assertion: end - start < 500 [205.380848] (kms_flip:4716) igt_core-INFO: Stack trace: [205.399897] (kms_flip:4716) igt_core-INFO: #0 ../lib/igt_core.c:2106 __igt_fail_assert() [205.401852] (kms_flip:4716) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [205.402070] (kms_flip:4716) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [205.402130] (kms_flip:4716) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() [205.402195] (kms_flip:4716) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [205.407706] (kms_flip:4716) igt_core-INFO: #5 [__libc_init_first+0x8a] [205.409200] (kms_flip:4716) igt_core-INFO: #6 [__libc_start_main+0x8b] [205.409561] (kms_flip:4716) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-eDP1: FAIL (4.007s)
Dmesg	<6> [203.232296] Console: switching to colour dummy device 80x25 <6> [203.232614] [IGT] kms_flip: executing <7> [203.239655] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [203.239667] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [203.239846] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [203.239963] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [203.240171] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [203.240173] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [203.240290] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [203.240378] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [203.240585] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [203.240587] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [203.240726] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [203.240834] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <7> [203.241073] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] <7> [203.241076] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:393:eDP-1] <7> [203.241526] xe 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [xe]] DSC DPCD: 00 11 00 76 0b 01 01 80 00 01 06 66 08 00 00 00 <7> [203.241907] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000 <7> [203.242068] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [203.242191] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [203.242325] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Supported Monitor Refresh rate range is 40 Hz - 120 Hz <5> [203.242332] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [203.242334] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [203.242335] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00 <7> [203.242337] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc. <5> [203.242339] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [203.242341] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor <5> [203.242343] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [203.242344] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0 <5> [203.242346] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [203.242360] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes <7> [203.242469] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps <7> [203.242642] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no <5> [203.243057] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [203.243060] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [203.243062] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [203.243126] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes: <7> [203.243133] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [203.243139] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 120 695310 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [203.243167] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [203.243174] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [203.243398] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [203.243416] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [203.243420] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [203.243611] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [203.243631] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [203.243636] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [203.243789] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <6> [203.244436] [IGT] kms_flip: starting subtest flip-vs-expired-vblank <6> [203.245842] [IGT] kms_flip: starting dynamic subtest A-eDP1 <7> [203.246834] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430] <7> [203.247324] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [203.328889] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [203.329166] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [203.329549] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [203.329862] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [203.330118] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [203.330366] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [203.330609] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [203.330993] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [203.331254] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [203.331468] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [203.331921] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [203.332140] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [203.332344] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [203.332539] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [203.332750] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [203.332930] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [203.333098] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [203.333264] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [203.333430] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [203.333590] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [203.333771] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [203.333922] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [203.334071] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [203.334215] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [203.334359] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [203.334504] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [203.334676] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [203.334810] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [203.334943] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [203.335079] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [203.335208] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [203.335335] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [203.335461] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [203.335583] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [203.335717] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [203.335839] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [203.335954] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [203.336067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [203.336188] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [203.336302] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [203.336429] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [203.336605] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [203.336737] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [203.336851] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0 <7> [203.336935] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [203.337015] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm <7> [203.337091] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 1, 13, 13, 13, 13, 13, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [203.337166] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 24, 313, 313, 313, 313, 313, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [203.337248] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 28, 346, 346, 346, 346, 346, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [203.337360] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [203.337481] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 34060 required 0 qgv_peak_bw: 38400 <7> [203.337586] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [203.337705] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [203.337815] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [203.337919] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [203.338016] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [203.338142] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [203.338252] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [203.338348] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [203.338443] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [203.338564] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [203.338693] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [203.338800] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [203.338906] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [203.339001] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [203.339089] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [203.339173] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [203.339306] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [203.340023] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [203.340173] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [203.340906] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [203.341025] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [203.547723] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [203.548179] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [203.558999] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [203.559386] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [203.559851] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [203.610992] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [203.611324] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [203.612032] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [203.612340] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [203.612738] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [203.612678] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [203.613122] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [203.613479] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [203.613787] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [203.613999] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [203.614207] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [203.614413] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [203.614646] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [203.614906] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [203.615113] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [203.615340] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [203.615550] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [203.615802] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [203.616016] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [203.616240] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [203.616450] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [203.616783] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [203.617013] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [203.617229] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [203.617675] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [203.618045] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [203.618447] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [203.618776] 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> [203.619151] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [203.619418] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [203.620252] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [203.620593] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [203.620903] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [203.620966] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [203.621124] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [203.621503] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:151:pipe A] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [203.621864] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [203.622196] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [203.622557] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:151:pipe A] <7> [203.622939] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [203.623247] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [203.623536] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [203.623867] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [203.624140] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [203.624413] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [203.624688] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [203.624972] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [203.625201] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [203.625423] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [203.625647] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [203.625858] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [203.626073] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [203.626278] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [203.626476] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [203.626678] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [203.626856] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [203.627030] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [203.627205] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [203.627379] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [203.627545] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [203.627731] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [203.627897] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [203.628057] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [203.628213] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [203.628370] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [203.628521] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [203.628688] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [203.628831] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [203.628970] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [203.629128] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [203.629275] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [203.629417] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [203.629553] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [203.629697] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [203.629815] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [203.629932] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [203.630049] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 0, found 432000) <7> [203.630176] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [203.630341] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [203.630430] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x1 <7> [203.630541] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [203.630649] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [203.630739] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [203.630818] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [203.630895] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [203.630971] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [203.631066] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1 <7> [203.631182] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23529 required 1461 qgv_peak_bw: 38400 <7> [203.631291] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36259 required 1461 qgv_peak_bw: 38400 <7> [203.631398] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [203.631502] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [203.631608] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [203.631723] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 0 kHz -> 173855 kHz <7> [203.631855] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [203.631974] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [203.632080] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [203.632186] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [203.632292] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0 <7> [203.632392] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0 <7> [203.632494] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: yes [modeset] <7> [203.632679] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [203.632795] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: A, pipe bpp: 30, dithering: 0 <7> [203.632901] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [203.632992] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [203.633074] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [203.633154] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [203.633233] 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> [203.633314] 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> [203.633393] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [203.633471] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [203.633548] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [203.633635] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [203.633739] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [203.633839] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [203.633935] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [203.634012] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [203.634090] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [203.634167] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [203.634243] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [203.634320] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [203.634395] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [203.634472] 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: 37 vsync start: 103, vsync end: 97 <7> [203.634561] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1869, vmax vblank: 1869, vmin vtotal: 1906, vmax vtotal: 1906 <7> [203.634674] 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> [203.634782] 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> [203.634886] 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> [203.634988] 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> [203.635081] 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> [203.635163] 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> [203.635238] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0 <7> [203.635314] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [203.635387] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [203.635462] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [203.635540] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [203.635643] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [203.635744] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [203.635839] 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> [203.635935] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [203.636031] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [203.636112] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [203.636190] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [203.636264] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [203.636336] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [203.636408] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [203.636481] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [203.636564] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [203.636661] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [203.636768] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [203.636879] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [203.636977] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [203.637057] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [203.637132] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [203.637208] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [203.637283] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [203.637359] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [203.637445] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [203.637523] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [203.637607] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [203.637707] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [FB:430] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [203.637807] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [203.637902] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [203.637991] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [203.638063] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [203.638134] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [203.638206] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [203.638280] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [203.638955] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A <7> [203.639124] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xa8000000) <7> [203.639232] 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> [203.639363] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [203.639468] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [203.639553] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [203.639636] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [203.639727] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [203.639808] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [203.639879] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [203.639947] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [203.640011] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [203.640078] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [203.640159] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [203.640224] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [203.640286] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [203.640351] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [203.640419] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [203.640507] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [203.640682] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [203.640766] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [203.640893] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [203.641683] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A] <7> [203.641821] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [203.643846] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [203.643982] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (468 ms remaining) <7> [203.649007] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [203.649178] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [203.649258] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [203.649354] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [204.116096] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [204.226180] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [204.226642] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [204.226997] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [204.263349] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [204.263772] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [204.264125] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [204.264949] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [204.291648] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [204.291791] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [204.291862] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [204.440103] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [204.440444] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [204.440788] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [204.442787] 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> [204.444265] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [204.445022] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [204.446092] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [204.447399] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [204.448525] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [204.448961] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [204.450425] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [204.450831] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [204.451639] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A <7> [204.452141] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [204.452503] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A <7> [204.452934] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 13892 <7> [204.485819] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [204.487381] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [204.487719] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [207.043565] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off <7> [207.044231] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [207.102510] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [207.103097] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [207.103600] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [207.253861] [IGT] kms_flip: finished subtest A-eDP1, FAIL

Detail

Value

Duration

4.01 seconds

Hostname

shard-lnl-1

Igt-Version

IGT-Version: 2.4-ge322bfd77 (x86_64) (Linux: 7.1.0-rc6-lgci-xe-xe-pw-167864v1-debug+ x86_64)

Out

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

Err

Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
[205.373284] (kms_flip:4716) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[205.373425] (kms_flip:4716) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
[203.355428] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.488419
last_received_ts = 204.487747
last_seq = 3628
current_ts = 204.505081
current_received_ts = 204.504410
current_seq = 3629
count = 33
seq_step = 1
[203.355569] (kms_flip:4716) DEBUG: Vblank took 138us
[203.372087] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.505081
last_received_ts = 204.504410
last_seq = 3629
current_ts = 204.521744
current_received_ts = 204.521057
current_seq = 3630
count = 34
seq_step = 1
[203.372150] (kms_flip:4716) DEBUG: Vblank took 56us
[203.388675] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.521744
last_received_ts = 204.521057
last_seq = 3630
current_ts = 204.538422
current_received_ts = 204.537659
current_seq = 3631
count = 35
seq_step = 1
[203.388802] (kms_flip:4716) DEBUG: Vblank took 123us
[203.405438] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.538422
last_received_ts = 204.537659
last_seq = 3631
current_ts = 204.555084
current_received_ts = 204.554413
current_seq = 3632
count = 36
seq_step = 1
[203.405573] (kms_flip:4716) DEBUG: Vblank took 125us
[203.422070] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.555084
last_received_ts = 204.554413
last_seq = 3632
current_ts = 204.571747
current_received_ts = 204.571060
current_seq = 3633
count = 37
seq_step = 1
[203.422128] (kms_flip:4716) DEBUG: Vblank took 53us
[203.438747] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.571747
last_received_ts = 204.571060
last_seq = 3633
current_ts = 204.588409
current_received_ts = 204.587738
current_seq = 3634
count = 38
seq_step = 1
[203.438858] (kms_flip:4716) DEBUG: Vblank took 108us
[203.455416] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.588409
last_received_ts = 204.587738
last_seq = 3634
current_ts = 204.605072
current_received_ts = 204.604401
current_seq = 3635
count = 39
seq_step = 1
[203.455544] (kms_flip:4716) DEBUG: Vblank took 121us
[203.472135] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.605072
last_received_ts = 204.604401
last_seq = 3635
current_ts = 204.621735
current_received_ts = 204.621109
current_seq = 3636
count = 40
seq_step = 1
[203.472215] (kms_flip:4716) DEBUG: Vblank took 72us
[203.488881] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.621735
last_received_ts = 204.621109
last_seq = 3636
current_ts = 204.638412
current_received_ts = 204.637863
current_seq = 3637
count = 41
seq_step = 1
[203.488950] (kms_flip:4716) DEBUG: Vblank took 60us
[203.505399] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.638412
last_received_ts = 204.637863
last_seq = 3637
current_ts = 204.655075
current_received_ts = 204.654373
current_seq = 3638
count = 42
seq_step = 1
[203.505521] (kms_flip:4716) DEBUG: Vblank took 116us
[203.522125] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.655075
last_received_ts = 204.654373
last_seq = 3638
current_ts = 204.671738
current_received_ts = 204.671112
current_seq = 3639
count = 43
seq_step = 1
[203.522208] (kms_flip:4716) DEBUG: Vblank took 75us
[203.538848] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.671738
last_received_ts = 204.671112
last_seq = 3639
current_ts = 204.688400
current_received_ts = 204.687836
current_seq = 3640
count = 44
seq_step = 1
[203.538914] (kms_flip:4716) DEBUG: Vblank took 58us
[203.555413] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.688400
last_received_ts = 204.687836
last_seq = 3640
current_ts = 204.705078
current_received_ts = 204.704391
current_seq = 3641
count = 45
seq_step = 1
[203.555552] (kms_flip:4716) DEBUG: Vblank took 133us
[203.572135] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.705078
last_received_ts = 204.704391
last_seq = 3641
current_ts = 204.721741
current_received_ts = 204.721115
current_seq = 3642
count = 46
seq_step = 1
[203.572207] (kms_flip:4716) DEBUG: Vblank took 65us
[203.588810] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.721741
last_received_ts = 204.721115
last_seq = 3642
current_ts = 204.738388
current_received_ts = 204.737793
current_seq = 3643
count = 47
seq_step = 1
[203.588868] (kms_flip:4716) DEBUG: Vblank took 51us
[203.605403] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.738388
last_received_ts = 204.737793
last_seq = 3643
current_ts = 204.755066
current_received_ts = 204.754395
current_seq = 3644
count = 48
seq_step = 1
[203.605545] (kms_flip:4716) DEBUG: Vblank took 134us
[203.622117] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.755066
last_received_ts = 204.754395
last_seq = 3644
current_ts = 204.771729
current_received_ts = 204.771103
current_seq = 3645
count = 49
seq_step = 1
[203.622189] (kms_flip:4716) DEBUG: Vblank took 64us
[203.638822] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.771729
last_received_ts = 204.771103
last_seq = 3645
current_ts = 204.788391
current_received_ts = 204.787811
current_seq = 3646
count = 50
seq_step = 1
[203.638883] (kms_flip:4716) DEBUG: Vblank took 54us
[203.655383] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.788391
last_received_ts = 204.787811
last_seq = 3646
current_ts = 204.805054
current_received_ts = 204.804367
current_seq = 3647
count = 51
seq_step = 1
[203.655505] (kms_flip:4716) DEBUG: Vblank took 115us
[203.672139] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.805054
last_received_ts = 204.804367
last_seq = 3647
current_ts = 204.821716
current_received_ts = 204.821121
current_seq = 3648
count = 52
seq_step = 1
[203.672200] (kms_flip:4716) DEBUG: Vblank took 54us
[203.688810] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.821716
last_received_ts = 204.821121
last_seq = 3648
current_ts = 204.838379
current_received_ts = 204.837799
current_seq = 3649
count = 53
seq_step = 1
[203.688869] (kms_flip:4716) DEBUG: Vblank took 51us
[203.705393] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.838379
last_received_ts = 204.837799
last_seq = 3649
current_ts = 204.855057
current_received_ts = 204.854385
current_seq = 3650
count = 54
seq_step = 1
[203.705512] (kms_flip:4716) DEBUG: Vblank took 113us
[203.722058] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.855057
last_received_ts = 204.854385
last_seq = 3650
current_ts = 204.871719
current_received_ts = 204.871048
current_seq = 3651
count = 55
seq_step = 1
[203.722186] (kms_flip:4716) DEBUG: Vblank took 120us
[203.738714] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.871719
last_received_ts = 204.871048
last_seq = 3651
current_ts = 204.888382
current_received_ts = 204.887711
current_seq = 3652
count = 56
seq_step = 1
[203.738831] (kms_flip:4716) DEBUG: Vblank took 109us
[203.755397] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.888382
last_received_ts = 204.887711
last_seq = 3652
current_ts = 204.905045
current_received_ts = 204.904388
current_seq = 3653
count = 57
seq_step = 1
[203.755518] (kms_flip:4716) DEBUG: Vblank took 113us
[203.772068] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.905045
last_received_ts = 204.904388
last_seq = 3653
current_ts = 204.921707
current_received_ts = 204.921066
current_seq = 3654
count = 58
seq_step = 1
[203.772149] (kms_flip:4716) DEBUG: Vblank took 74us
[203.788700] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.921707
last_received_ts = 204.921066
last_seq = 3654
current_ts = 204.938370
current_received_ts = 204.937698
current_seq = 3655
count = 59
seq_step = 1
[203.788821] (kms_flip:4716) DEBUG: Vblank took 113us
[203.805282] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.938370
last_received_ts = 204.937698
last_seq = 3655
current_ts = 204.955032
current_received_ts = 204.954285
current_seq = 3656
count = 60
seq_step = 1
[203.805415] (kms_flip:4716) DEBUG: Vblank took 129us
[203.822052] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.955032
last_received_ts = 204.954285
last_seq = 3656
current_ts = 204.971695
current_received_ts = 204.971054
current_seq = 3657
count = 61
seq_step = 1
[203.822149] (kms_flip:4716) DEBUG: Vblank took 90us
[203.838693] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.971695
last_received_ts = 204.971054
last_seq = 3657
current_ts = 204.988373
current_received_ts = 204.987686
current_seq = 3658
count = 62
seq_step = 1
[203.838819] (kms_flip:4716) DEBUG: Vblank took 119us
[203.855325] (kms_flip:4716) DEBUG: name = flip
last_ts = 204.988373
last_received_ts = 204.987686
last_seq = 3658
current_ts = 205.005035
current_received_ts = 205.004333
current_seq = 3659
count = 63
seq_step = 1
[203.855446] (kms_flip:4716) DEBUG: Vblank took 119us
[203.872044] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.005035
last_received_ts = 205.004333
last_seq = 3659
current_ts = 205.021698
current_received_ts = 205.021042
current_seq = 3660
count = 64
seq_step = 1
[203.872159] (kms_flip:4716) DEBUG: Vblank took 107us
[203.888776] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.021698
last_received_ts = 205.021042
last_seq = 3660
current_ts = 205.038361
current_received_ts = 205.037781
current_seq = 3661
count = 65
seq_step = 1
[203.888834] (kms_flip:4716) DEBUG: Vblank took 51us
[203.905360] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.038361
last_received_ts = 205.037781
last_seq = 3661
current_ts = 205.055023
current_received_ts = 205.054367
current_seq = 3662
count = 66
seq_step = 1
[203.905475] (kms_flip:4716) DEBUG: Vblank took 107us
[203.922061] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.055023
last_received_ts = 205.054367
last_seq = 3662
current_ts = 205.071686
current_received_ts = 205.071060
current_seq = 3663
count = 67
seq_step = 1
[203.922149] (kms_flip:4716) DEBUG: Vblank took 80us
[203.938668] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.071686
last_received_ts = 205.071060
last_seq = 3663
current_ts = 205.088364
current_received_ts = 205.087662
current_seq = 3664
count = 68
seq_step = 1
[203.938793] (kms_flip:4716) DEBUG: Vblank took 118us
[203.955312] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.088364
last_received_ts = 205.087662
last_seq = 3664
current_ts = 205.105026
current_received_ts = 205.104324
current_seq = 3665
count = 69
seq_step = 1
[203.955435] (kms_flip:4716) DEBUG: Vblank took 120us
[203.972044] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.105026
last_received_ts = 205.104324
last_seq = 3665
current_ts = 205.121689
current_received_ts = 205.121048
current_seq = 3666
count = 70
seq_step = 1
[203.972134] (kms_flip:4716) DEBUG: Vblank took 82us
[203.988668] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.121689
last_received_ts = 205.121048
last_seq = 3666
current_ts = 205.138351
current_received_ts = 205.137665
current_seq = 3667
count = 71
seq_step = 1
[203.988789] (kms_flip:4716) DEBUG: Vblank took 113us
[204.005291] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.138351
last_received_ts = 205.137665
last_seq = 3667
current_ts = 205.155014
current_received_ts = 205.154297
current_seq = 3668
count = 72
seq_step = 1
[204.005425] (kms_flip:4716) DEBUG: Vblank took 131us
[204.022041] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.155014
last_received_ts = 205.154297
last_seq = 3668
current_ts = 205.171677
current_received_ts = 205.171051
current_seq = 3669
count = 73
seq_step = 1
[204.022143] (kms_flip:4716) DEBUG: Vblank took 94us
[204.038688] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.171677
last_received_ts = 205.171051
last_seq = 3669
current_ts = 205.188354
current_received_ts = 205.187698
current_seq = 3670
count = 74
seq_step = 1
[204.038801] (kms_flip:4716) DEBUG: Vblank took 107us
[204.055324] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.188354
last_received_ts = 205.187698
last_seq = 3670
current_ts = 205.205002
current_received_ts = 205.204330
current_seq = 3671
count = 75
seq_step = 1
[204.055452] (kms_flip:4716) DEBUG: Vblank took 124us
[204.072038] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.205002
last_received_ts = 205.204330
last_seq = 3671
current_ts = 205.221664
current_received_ts = 205.221039
current_seq = 3672
count = 76
seq_step = 1
[204.072117] (kms_flip:4716) DEBUG: Vblank took 72us
[204.088666] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.221664
last_received_ts = 205.221039
last_seq = 3672
current_ts = 205.238342
current_received_ts = 205.237671
current_seq = 3673
count = 77
seq_step = 1
[204.088786] (kms_flip:4716) DEBUG: Vblank took 112us
[204.105296] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.238342
last_received_ts = 205.237671
last_seq = 3673
current_ts = 205.255005
current_received_ts = 205.254303
current_seq = 3674
count = 78
seq_step = 1
[204.105441] (kms_flip:4716) DEBUG: Vblank took 141us
[204.122111] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.255005
last_received_ts = 205.254303
last_seq = 3674
current_ts = 205.271667
current_received_ts = 205.271118
current_seq = 3675
count = 79
seq_step = 1
[204.122150] (kms_flip:4716) DEBUG: Vblank took 31us
[204.138671] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.271667
last_received_ts = 205.271118
last_seq = 3675
current_ts = 205.288330
current_received_ts = 205.287674
current_seq = 3676
count = 80
seq_step = 1
[204.138726] (kms_flip:4716) DEBUG: Vblank took 44us
[204.155321] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.288330
last_received_ts = 205.287674
last_seq = 3676
current_ts = 205.304993
current_received_ts = 205.304337
current_seq = 3677
count = 81
seq_step = 1
[204.155434] (kms_flip:4716) DEBUG: Vblank took 104us
[204.172043] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.304993
last_received_ts = 205.304337
last_seq = 3677
current_ts = 205.321671
current_received_ts = 205.321060
current_seq = 3678
count = 82
seq_step = 1
[204.172123] (kms_flip:4716) DEBUG: Vblank took 72us
[204.188648] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.321671
last_received_ts = 205.321060
last_seq = 3678
current_ts = 205.338333
current_received_ts = 205.337662
current_seq = 3679
count = 83
seq_step = 1
[204.188771] (kms_flip:4716) DEBUG: Vblank took 115us
[204.205290] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.338333
last_received_ts = 205.337662
last_seq = 3679
current_ts = 205.354996
current_received_ts = 205.354309
current_seq = 3680
count = 84
seq_step = 1
[204.205421] (kms_flip:4716) DEBUG: Vblank took 127us
[204.222042] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.354996
last_received_ts = 205.354309
last_seq = 3680
current_ts = 205.371658
current_received_ts = 205.371048
current_seq = 3681
count = 85
seq_step = 1
[204.222107] (kms_flip:4716) DEBUG: Vblank took 58us
[204.238646] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.371658
last_received_ts = 205.371048
last_seq = 3681
current_ts = 205.388321
current_received_ts = 205.387665
current_seq = 3682
count = 86
seq_step = 1
[204.238780] (kms_flip:4716) DEBUG: Vblank took 127us
[204.255253] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.388321
last_received_ts = 205.387665
last_seq = 3682
current_ts = 205.404984
current_received_ts = 205.404282
current_seq = 3683
count = 87
seq_step = 1
[204.255376] (kms_flip:4716) DEBUG: Vblank took 120us
[204.272037] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.404984
last_received_ts = 205.404282
last_seq = 3683
current_ts = 205.421646
current_received_ts = 205.421051
current_seq = 3684
count = 88
seq_step = 1
[204.272098] (kms_flip:4716) DEBUG: Vblank took 53us
[204.288628] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.421646
last_received_ts = 205.421051
last_seq = 3684
current_ts = 205.438309
current_received_ts = 205.437637
current_seq = 3685
count = 89
seq_step = 1
[204.288745] (kms_flip:4716) DEBUG: Vblank took 109us
[204.305244] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.438309
last_received_ts = 205.437637
last_seq = 3685
current_ts = 205.454987
current_received_ts = 205.454269
current_seq = 3686
count = 90
seq_step = 1
[204.305372] (kms_flip:4716) DEBUG: Vblank took 125us
[204.322017] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.454987
last_received_ts = 205.454269
last_seq = 3686
current_ts = 205.471649
current_received_ts = 205.471039
current_seq = 3687
count = 91
seq_step = 1
[204.322075] (kms_flip:4716) DEBUG: Vblank took 50us
[204.338609] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.471649
last_received_ts = 205.471039
last_seq = 3687
current_ts = 205.488312
current_received_ts = 205.487625
current_seq = 3688
count = 92
seq_step = 1
[204.338730] (kms_flip:4716) DEBUG: Vblank took 114us
[204.355270] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.488312
last_received_ts = 205.487625
last_seq = 3688
current_ts = 205.504974
current_received_ts = 205.504303
current_seq = 3689
count = 93
seq_step = 1
[204.355396] (kms_flip:4716) DEBUG: Vblank took 123us
[204.372032] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.504974
last_received_ts = 205.504303
last_seq = 3689
current_ts = 205.521637
current_received_ts = 205.521057
current_seq = 3690
count = 94
seq_step = 1
[204.372094] (kms_flip:4716) DEBUG: Vblank took 55us
[204.388622] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.521637
last_received_ts = 205.521057
last_seq = 3690
current_ts = 205.538300
current_received_ts = 205.537643
current_seq = 3691
count = 95
seq_step = 1
[204.388750] (kms_flip:4716) DEBUG: Vblank took 121us
[204.405244] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.538300
last_received_ts = 205.537643
last_seq = 3691
current_ts = 205.554977
current_received_ts = 205.554276
current_seq = 3692
count = 96
seq_step = 1
[204.405370] (kms_flip:4716) DEBUG: Vblank took 123us
[204.422015] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.554977
last_received_ts = 205.554276
last_seq = 3692
current_ts = 205.571640
current_received_ts = 205.571030
current_seq = 3693
count = 97
seq_step = 1
[204.422126] (kms_flip:4716) DEBUG: Vblank took 103us
[204.438595] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.571640
last_received_ts = 205.571030
last_seq = 3693
current_ts = 205.588303
current_received_ts = 205.587616
current_seq = 3694
count = 98
seq_step = 1
[204.438716] (kms_flip:4716) DEBUG: Vblank took 113us
[204.455227] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.588303
last_received_ts = 205.587616
last_seq = 3694
current_ts = 205.604965
current_received_ts = 205.604263
current_seq = 3695
count = 99
seq_step = 1
[204.455351] (kms_flip:4716) DEBUG: Vblank took 121us
[204.471861] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.604965
last_received_ts = 205.604263
last_seq = 3695
current_ts = 205.621628
current_received_ts = 205.620895
current_seq = 3696
count = 100
seq_step = 1
[204.471904] (kms_flip:4716) DEBUG: Vblank took 41us
[204.488598] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.621628
last_received_ts = 205.620895
last_seq = 3696
current_ts = 205.638290
current_received_ts = 205.637619
current_seq = 3697
count = 101
seq_step = 1
[204.488713] (kms_flip:4716) DEBUG: Vblank took 107us
[204.505248] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.638290
last_received_ts = 205.637619
last_seq = 3697
current_ts = 205.654968
current_received_ts = 205.654282
current_seq = 3698
count = 102
seq_step = 1
[204.505375] (kms_flip:4716) DEBUG: Vblank took 124us
[204.522006] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.654968
last_received_ts = 205.654282
last_seq = 3698
current_ts = 205.671631
current_received_ts = 205.671036
current_seq = 3699
count = 103
seq_step = 1
[204.522071] (kms_flip:4716) DEBUG: Vblank took 57us
[204.538577] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.671631
last_received_ts = 205.671036
last_seq = 3699
current_ts = 205.688293
current_received_ts = 205.687607
current_seq = 3700
count = 104
seq_step = 1
[204.538710] (kms_flip:4716) DEBUG: Vblank took 125us
[204.555215] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.688293
last_received_ts = 205.687607
last_seq = 3700
current_ts = 205.704956
current_received_ts = 205.704254
current_seq = 3701
count = 105
seq_step = 1
[204.555366] (kms_flip:4716) DEBUG: Vblank took 149us
[204.572023] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.704956
last_received_ts = 205.704254
last_seq = 3701
current_ts = 205.721619
current_received_ts = 205.721054
current_seq = 3702
count = 106
seq_step = 1
[204.572085] (kms_flip:4716) DEBUG: Vblank took 55us
[204.588717] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.721619
last_received_ts = 205.721054
last_seq = 3702
current_ts = 205.738281
current_received_ts = 205.737747
current_seq = 3703
count = 107
seq_step = 1
[204.588784] (kms_flip:4716) DEBUG: Vblank took 60us
[204.605317] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.738281
last_received_ts = 205.737747
last_seq = 3703
current_ts = 205.754944
current_received_ts = 205.754349
current_seq = 3704
count = 108
seq_step = 1
[204.605444] (kms_flip:4716) DEBUG: Vblank took 119us
[204.622015] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.754944
last_received_ts = 205.754349
last_seq = 3704
current_ts = 205.771606
current_received_ts = 205.771042
current_seq = 3705
count = 109
seq_step = 1
[204.622091] (kms_flip:4716) DEBUG: Vblank took 68us
[204.638668] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.771606
last_received_ts = 205.771042
last_seq = 3705
current_ts = 205.788284
current_received_ts = 205.787704
current_seq = 3706
count = 110
seq_step = 1
[204.638734] (kms_flip:4716) DEBUG: Vblank took 59us
[204.655308] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.788284
last_received_ts = 205.787704
last_seq = 3706
current_ts = 205.804947
current_received_ts = 205.804337
current_seq = 3707
count = 111
seq_step = 1
[204.655438] (kms_flip:4716) DEBUG: Vblank took 123us
[204.672011] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.804947
last_received_ts = 205.804337
last_seq = 3707
current_ts = 205.821609
current_received_ts = 205.821045
current_seq = 3708
count = 112
seq_step = 1
[204.672078] (kms_flip:4716) DEBUG: Vblank took 59us
[204.688663] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.821609
last_received_ts = 205.821045
last_seq = 3708
current_ts = 205.838272
current_received_ts = 205.837692
current_seq = 3709
count = 113
seq_step = 1
[204.688731] (kms_flip:4716) DEBUG: Vblank took 61us
[204.705329] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.838272
last_received_ts = 205.837692
last_seq = 3709
current_ts = 205.854935
current_received_ts = 205.854370
current_seq = 3710
count = 114
seq_step = 1
[204.705472] (kms_flip:4716) DEBUG: Vblank took 135us
[204.722016] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.854935
last_received_ts = 205.854370
last_seq = 3710
current_ts = 205.871597
current_received_ts = 205.871048
current_seq = 3711
count = 115
seq_step = 1
[204.722086] (kms_flip:4716) DEBUG: Vblank took 62us
[204.738650] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.871597
last_received_ts = 205.871048
last_seq = 3711
current_ts = 205.888260
current_received_ts = 205.887695
current_seq = 3712
count = 116
seq_step = 1
[204.738717] (kms_flip:4716) DEBUG: Vblank took 60us
[204.755319] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.888260
last_received_ts = 205.887695
last_seq = 3712
current_ts = 205.904922
current_received_ts = 205.904358
current_seq = 3713
count = 117
seq_step = 1
[204.755459] (kms_flip:4716) DEBUG: Vblank took 133us
[204.771994] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.904922
last_received_ts = 205.904358
last_seq = 3713
current_ts = 205.921585
current_received_ts = 205.921036
current_seq = 3714
count = 118
seq_step = 1
[204.772060] (kms_flip:4716) DEBUG: Vblank took 59us
[204.788655] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.921585
last_received_ts = 205.921036
last_seq = 3714
current_ts = 205.938263
current_received_ts = 205.937698
current_seq = 3715
count = 119
seq_step = 1
[204.788722] (kms_flip:4716) DEBUG: Vblank took 60us
[204.805314] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.938263
last_received_ts = 205.937698
last_seq = 3715
current_ts = 205.954926
current_received_ts = 205.954361
current_seq = 3716
count = 120
seq_step = 1
[204.805445] (kms_flip:4716) DEBUG: Vblank took 123us
[204.821999] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.954926
last_received_ts = 205.954361
last_seq = 3716
current_ts = 205.971588
current_received_ts = 205.971039
current_seq = 3717
count = 121
seq_step = 1
[204.822075] (kms_flip:4716) DEBUG: Vblank took 68us
[204.838635] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.971588
last_received_ts = 205.971039
last_seq = 3717
current_ts = 205.988251
current_received_ts = 205.987671
current_seq = 3718
count = 122
seq_step = 1
[204.838701] (kms_flip:4716) DEBUG: Vblank took 59us
[204.855278] (kms_flip:4716) DEBUG: name = flip
last_ts = 205.988251
last_received_ts = 205.987671
last_seq = 3718
current_ts = 206.004913
current_received_ts = 206.004318
current_seq = 3719
count = 123
seq_step = 1
[204.855424] (kms_flip:4716) DEBUG: Vblank took 139us
[204.871982] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.004913
last_received_ts = 206.004318
last_seq = 3719
current_ts = 206.021576
current_received_ts = 206.021027
current_seq = 3720
count = 124
seq_step = 1
[204.872049] (kms_flip:4716) DEBUG: Vblank took 59us
[204.888657] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.021576
last_received_ts = 206.021027
last_seq = 3720
current_ts = 206.038239
current_received_ts = 206.037704
current_seq = 3721
count = 125
seq_step = 1
[204.888727] (kms_flip:4716) DEBUG: Vblank took 62us
[204.905255] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.038239
last_received_ts = 206.037704
last_seq = 3721
current_ts = 206.054916
current_received_ts = 206.054306
current_seq = 3722
count = 126
seq_step = 1
[204.905385] (kms_flip:4716) DEBUG: Vblank took 122us
[204.922008] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.054916
last_received_ts = 206.054306
last_seq = 3722
current_ts = 206.071579
current_received_ts = 206.071060
current_seq = 3723
count = 127
seq_step = 1
[204.922076] (kms_flip:4716) DEBUG: Vblank took 61us
[204.938628] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.071579
last_received_ts = 206.071060
last_seq = 3723
current_ts = 206.088242
current_received_ts = 206.087677
current_seq = 3724
count = 128
seq_step = 1
[204.938694] (kms_flip:4716) DEBUG: Vblank took 60us
[204.955266] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.088242
last_received_ts = 206.087677
last_seq = 3724
current_ts = 206.104904
current_received_ts = 206.104309
current_seq = 3725
count = 129
seq_step = 1
[204.955410] (kms_flip:4716) DEBUG: Vblank took 137us
[204.971933] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.104904
last_received_ts = 206.104309
last_seq = 3725
current_ts = 206.121567
current_received_ts = 206.120987
current_seq = 3726
count = 130
seq_step = 1
[204.972025] (kms_flip:4716) DEBUG: Vblank took 84us
[204.988609] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.121567
last_received_ts = 206.120987
last_seq = 3726
current_ts = 206.138229
current_received_ts = 206.137665
current_seq = 3727
count = 131
seq_step = 1
[204.988678] (kms_flip:4716) DEBUG: Vblank took 61us
[205.005247] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.138229
last_received_ts = 206.137665
last_seq = 3727
current_ts = 206.154892
current_received_ts = 206.154297
current_seq = 3728
count = 132
seq_step = 1
[205.005395] (kms_flip:4716) DEBUG: Vblank took 140us
[205.021934] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.154892
last_received_ts = 206.154297
last_seq = 3728
current_ts = 206.171570
current_received_ts = 206.170990
current_seq = 3729
count = 133
seq_step = 1
[205.022033] (kms_flip:4716) DEBUG: Vblank took 65us
[205.038607] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.171570
last_received_ts = 206.170990
last_seq = 3729
current_ts = 206.188232
current_received_ts = 206.187653
current_seq = 3730
count = 134
seq_step = 1
[205.038676] (kms_flip:4716) DEBUG: Vblank took 62us
[205.055268] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.188232
last_received_ts = 206.187653
last_seq = 3730
current_ts = 206.204895
current_received_ts = 206.204315
current_seq = 3731
count = 135
seq_step = 1
[205.055406] (kms_flip:4716) DEBUG: Vblank took 131us
[205.071933] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.204895
last_received_ts = 206.204315
last_seq = 3731
current_ts = 206.221558
current_received_ts = 206.220993
current_seq = 3732
count = 136
seq_step = 1
[205.072027] (kms_flip:4716) DEBUG: Vblank took 61us
[205.088615] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.221558
last_received_ts = 206.220993
last_seq = 3732
current_ts = 206.238220
current_received_ts = 206.237671
current_seq = 3733
count = 137
seq_step = 1
[205.088687] (kms_flip:4716) DEBUG: Vblank took 64us
[205.105260] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.238220
last_received_ts = 206.237671
last_seq = 3733
current_ts = 206.254898
current_received_ts = 206.254318
current_seq = 3734
count = 138
seq_step = 1
[205.105403] (kms_flip:4716) DEBUG: Vblank took 135us
[205.121906] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.254898
last_received_ts = 206.254318
last_seq = 3734
current_ts = 206.271545
current_received_ts = 206.270966
current_seq = 3735
count = 139
seq_step = 1
[205.122000] (kms_flip:4716) DEBUG: Vblank took 87us
[205.138670] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.271545
last_received_ts = 206.270966
last_seq = 3735
current_ts = 206.288223
current_received_ts = 206.287689
current_seq = 3736
count = 140
seq_step = 1
[205.138845] (kms_flip:4716) DEBUG: Vblank took 147us
[205.155302] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.288223
last_received_ts = 206.287689
last_seq = 3736
current_ts = 206.304886
current_received_ts = 206.304352
current_seq = 3737
count = 141
seq_step = 1
[205.155428] (kms_flip:4716) DEBUG: Vblank took 110us
[205.172007] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.304886
last_received_ts = 206.304352
last_seq = 3737
current_ts = 206.321548
current_received_ts = 206.321045
current_seq = 3738
count = 142
seq_step = 1
[205.172147] (kms_flip:4716) DEBUG: Vblank took 121us
[205.188596] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.321548
last_received_ts = 206.321045
last_seq = 3738
current_ts = 206.338211
current_received_ts = 206.337646
current_seq = 3739
count = 143
seq_step = 1
[205.188700] (kms_flip:4716) DEBUG: Vblank took 95us
[205.205262] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.338211
last_received_ts = 206.337646
last_seq = 3739
current_ts = 206.354889
current_received_ts = 206.354324
current_seq = 3740
count = 144
seq_step = 1
[205.205350] (kms_flip:4716) DEBUG: Vblank took 80us
[205.221959] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.354889
last_received_ts = 206.354324
last_seq = 3740
current_ts = 206.371536
current_received_ts = 206.370987
current_seq = 3741
count = 145
seq_step = 1
[205.222047] (kms_flip:4716) DEBUG: Vblank took 81us
[205.238596] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.371536
last_received_ts = 206.370987
last_seq = 3741
current_ts = 206.388199
current_received_ts = 206.387650
current_seq = 3742
count = 146
seq_step = 1
[205.238676] (kms_flip:4716) DEBUG: Vblank took 73us
[205.255256] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.388199
last_received_ts = 206.387650
last_seq = 3742
current_ts = 206.404877
current_received_ts = 206.404312
current_seq = 3743
count = 147
seq_step = 1
[205.255336] (kms_flip:4716) DEBUG: Vblank took 75us
[205.271972] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.404877
last_received_ts = 206.404312
last_seq = 3743
current_ts = 206.421539
current_received_ts = 206.421036
current_seq = 3744
count = 148
seq_step = 1
[205.272053] (kms_flip:4716) DEBUG: Vblank took 73us
[205.288600] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.421539
last_received_ts = 206.421036
last_seq = 3744
current_ts = 206.438202
current_received_ts = 206.437668
current_seq = 3745
count = 149
seq_step = 1
[205.288682] (kms_flip:4716) DEBUG: Vblank took 76us
[205.305261] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.438202
last_received_ts = 206.437668
last_seq = 3745
current_ts = 206.454865
current_received_ts = 206.454330
current_seq = 3746
count = 150
seq_step = 1
[205.305345] (kms_flip:4716) DEBUG: Vblank took 76us
[205.321908] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.454865
last_received_ts = 206.454330
last_seq = 3746
current_ts = 206.471527
current_received_ts = 206.470978
current_seq = 3747
count = 151
seq_step = 1
[205.322020] (kms_flip:4716) DEBUG: Vblank took 105us
[205.338482] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.471527
last_received_ts = 206.470978
last_seq = 3747
current_ts = 206.488190
current_received_ts = 206.487549
current_seq = 3748
count = 152
seq_step = 1
[205.338577] (kms_flip:4716) DEBUG: Vblank took 82us
[205.355169] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.488190
last_received_ts = 206.487549
last_seq = 3748
current_ts = 206.504868
current_received_ts = 206.504227
current_seq = 3749
count = 153
seq_step = 1
[205.355271] (kms_flip:4716) DEBUG: Vblank took 91us
[205.371914] (kms_flip:4716) DEBUG: name = flip
last_ts = 206.504868
last_received_ts = 206.504227
last_seq = 3749
current_ts = 206.521530
current_received_ts = 206.520981
current_seq = 3750
count = 154
seq_step = 1
[205.373275] (kms_flip:4716) DEBUG: Vblank took 1351us
[205.373284] (kms_flip:4716) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[205.373425] (kms_flip:4716) CRITICAL: Failed assertion: end - start < 500
[205.380848] (kms_flip:4716) igt_core-INFO: Stack trace:
[205.399897] (kms_flip:4716) igt_core-INFO:   #0 ../lib/igt_core.c:2106 __igt_fail_assert()
[205.401852] (kms_flip:4716) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[205.402070] (kms_flip:4716) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[205.402130] (kms_flip:4716) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
[205.402195] (kms_flip:4716) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[205.407706] (kms_flip:4716) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[205.409200] (kms_flip:4716) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[205.409561] (kms_flip:4716) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (4.007s)

Dmesg

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [203.634472] 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: 37 vsync start: 103, vsync end: 97

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

<7> [203.634674] 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> [203.634782] 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> [203.634886] 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> [203.634988] 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> [203.635081] 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> [203.635163] 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> [203.635238] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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