igt@kms_flip@flip-vs-expired-vblank@c-edp1 on re-lnl-5@xe-3827-690ed0728a0e31e6b2a309029af5ba224981ff60 Test details

Detail	Value
Duration	3.90 seconds
Igt-Version	IGT-Version: 2.1-g162a06a82 (x86_64) (Linux: 6.17.0-rc7-lgci-xe-xe-3827-690ed0728a0e31e6b+ x86_64)
Out	Starting dynamic subtest: C-eDP1 1920x1200: 120 317250 1920 1968 2000 2080 1200 1203 1209 1271 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1884 run_test() #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040() #4 ../tests/kms_flip.c:2040 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest C-eDP1: FAIL (3.896s)
Err	Starting dynamic subtest: C-eDP1 (kms_flip:3251) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:3251) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest C-eDP1 failed. ** DEBUG (kms_flip:3251) DEBUG: name = flip last_ts = 555.277283 last_received_ts = 555.277222 last_seq = 5778 current_ts = 555.285583 current_received_ts = 555.285522 current_seq = 5779 count = 178 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 111us (kms_flip:3251) DEBUG: name = flip last_ts = 555.285583 last_received_ts = 555.285522 last_seq = 5779 current_ts = 555.293945 current_received_ts = 555.293884 current_seq = 5780 count = 179 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 143us (kms_flip:3251) DEBUG: name = flip last_ts = 555.293945 last_received_ts = 555.293884 last_seq = 5780 current_ts = 555.302246 current_received_ts = 555.302185 current_seq = 5781 count = 180 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 120us (kms_flip:3251) DEBUG: name = flip last_ts = 555.302246 last_received_ts = 555.302185 last_seq = 5781 current_ts = 555.310608 current_received_ts = 555.310547 current_seq = 5782 count = 181 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 96us (kms_flip:3251) DEBUG: name = flip last_ts = 555.310608 last_received_ts = 555.310547 last_seq = 5782 current_ts = 555.318909 current_received_ts = 555.318848 current_seq = 5783 count = 182 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 144us (kms_flip:3251) DEBUG: name = flip last_ts = 555.318909 last_received_ts = 555.318848 last_seq = 5783 current_ts = 555.327271 current_received_ts = 555.327209 current_seq = 5784 count = 183 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 110us (kms_flip:3251) DEBUG: name = flip last_ts = 555.327271 last_received_ts = 555.327209 last_seq = 5784 current_ts = 555.335571 current_received_ts = 555.335571 current_seq = 5785 count = 184 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 65us (kms_flip:3251) DEBUG: name = flip last_ts = 555.335571 last_received_ts = 555.335571 last_seq = 5785 current_ts = 555.343933 current_received_ts = 555.343872 current_seq = 5786 count = 185 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 96us (kms_flip:3251) DEBUG: name = flip last_ts = 555.343933 last_received_ts = 555.343872 last_seq = 5786 current_ts = 555.352234 current_received_ts = 555.352173 current_seq = 5787 count = 186 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 114us (kms_flip:3251) DEBUG: name = flip last_ts = 555.352234 last_received_ts = 555.352173 last_seq = 5787 current_ts = 555.360596 current_received_ts = 555.360535 current_seq = 5788 count = 187 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 112us (kms_flip:3251) DEBUG: name = flip last_ts = 555.360596 last_received_ts = 555.360535 last_seq = 5788 current_ts = 555.368896 current_received_ts = 555.368896 current_seq = 5789 count = 188 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 96us (kms_flip:3251) DEBUG: name = flip last_ts = 555.368896 last_received_ts = 555.368896 last_seq = 5789 current_ts = 555.377258 current_received_ts = 555.377197 current_seq = 5790 count = 189 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 97us (kms_flip:3251) DEBUG: name = flip last_ts = 555.377258 last_received_ts = 555.377197 last_seq = 5790 current_ts = 555.385620 current_received_ts = 555.385498 current_seq = 5791 count = 190 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 102us (kms_flip:3251) DEBUG: name = flip last_ts = 555.385620 last_received_ts = 555.385498 last_seq = 5791 current_ts = 555.393921 current_received_ts = 555.393860 current_seq = 5792 count = 191 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 144us (kms_flip:3251) DEBUG: name = flip last_ts = 555.393921 last_received_ts = 555.393860 last_seq = 5792 current_ts = 555.402283 current_received_ts = 555.402161 current_seq = 5793 count = 192 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 97us (kms_flip:3251) DEBUG: name = flip last_ts = 555.402283 last_received_ts = 555.402161 last_seq = 5793 current_ts = 555.410583 current_received_ts = 555.410522 current_seq = 5794 count = 193 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 96us (kms_flip:3251) DEBUG: name = flip last_ts = 555.410583 last_received_ts = 555.410522 last_seq = 5794 current_ts = 555.418945 current_received_ts = 555.418884 current_seq = 5795 count = 194 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 149us (kms_flip:3251) DEBUG: name = flip last_ts = 555.418945 last_received_ts = 555.418884 last_seq = 5795 current_ts = 555.427246 current_received_ts = 555.427185 current_seq = 5796 count = 195 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 101us (kms_flip:3251) DEBUG: name = flip last_ts = 555.427246 last_received_ts = 555.427185 last_seq = 5796 current_ts = 555.435608 current_received_ts = 555.435547 current_seq = 5797 count = 196 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 117us (kms_flip:3251) DEBUG: name = flip last_ts = 555.435608 last_received_ts = 555.435547 last_seq = 5797 current_ts = 555.443909 current_received_ts = 555.443848 current_seq = 5798 count = 197 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 72us (kms_flip:3251) DEBUG: name = flip last_ts = 555.443909 last_received_ts = 555.443848 last_seq = 5798 current_ts = 555.452271 current_received_ts = 555.452209 current_seq = 5799 count = 198 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 111us (kms_flip:3251) DEBUG: name = flip last_ts = 555.452271 last_received_ts = 555.452209 last_seq = 5799 current_ts = 555.460571 current_received_ts = 555.460510 current_seq = 5800 count = 199 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 101us (kms_flip:3251) DEBUG: name = flip last_ts = 555.460571 last_received_ts = 555.460510 last_seq = 5800 current_ts = 555.468933 current_received_ts = 555.468872 current_seq = 5801 count = 200 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 147us (kms_flip:3251) DEBUG: name = flip last_ts = 555.468933 last_received_ts = 555.468872 last_seq = 5801 current_ts = 555.477234 current_received_ts = 555.477173 current_seq = 5802 count = 201 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 110us (kms_flip:3251) DEBUG: name = flip last_ts = 555.477234 last_received_ts = 555.477173 last_seq = 5802 current_ts = 555.485596 current_received_ts = 555.485535 current_seq = 5803 count = 202 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 95us (kms_flip:3251) DEBUG: name = flip last_ts = 555.485596 last_received_ts = 555.485535 last_seq = 5803 current_ts = 555.493958 current_received_ts = 555.493835 current_seq = 5804 count = 203 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 142us (kms_flip:3251) DEBUG: name = flip last_ts = 555.493958 last_received_ts = 555.493835 last_seq = 5804 current_ts = 555.502258 current_received_ts = 555.502197 current_seq = 5805 count = 204 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 110us (kms_flip:3251) DEBUG: name = flip last_ts = 555.502258 last_received_ts = 555.502197 last_seq = 5805 current_ts = 555.510620 current_received_ts = 555.510498 current_seq = 5806 count = 205 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 109us (kms_flip:3251) DEBUG: name = flip last_ts = 555.510620 last_received_ts = 555.510498 last_seq = 5806 current_ts = 555.518921 current_received_ts = 555.518921 current_seq = 5807 count = 206 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 182us (kms_flip:3251) DEBUG: name = flip last_ts = 555.518921 last_received_ts = 555.518921 last_seq = 5807 current_ts = 555.527283 current_received_ts = 555.527222 current_seq = 5808 count = 207 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 113us (kms_flip:3251) DEBUG: name = flip last_ts = 555.527283 last_received_ts = 555.527222 last_seq = 5808 current_ts = 555.535583 current_received_ts = 555.535522 current_seq = 5809 count = 208 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 113us (kms_flip:3251) DEBUG: name = flip last_ts = 555.535583 last_received_ts = 555.535522 last_seq = 5809 current_ts = 555.543945 current_received_ts = 555.543884 current_seq = 5810 count = 209 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 152us (kms_flip:3251) DEBUG: name = flip last_ts = 555.543945 last_received_ts = 555.543884 last_seq = 5810 current_ts = 555.552246 current_received_ts = 555.552185 current_seq = 5811 count = 210 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 112us (kms_flip:3251) DEBUG: name = flip last_ts = 555.552246 last_received_ts = 555.552185 last_seq = 5811 current_ts = 555.560608 current_received_ts = 555.560547 current_seq = 5812 count = 211 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 65us (kms_flip:3251) DEBUG: name = flip last_ts = 555.560608 last_received_ts = 555.560547 last_seq = 5812 current_ts = 555.568909 current_received_ts = 555.568909 current_seq = 5813 count = 212 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 135us (kms_flip:3251) DEBUG: name = flip last_ts = 555.568909 last_received_ts = 555.568909 last_seq = 5813 current_ts = 555.577271 current_received_ts = 555.577209 current_seq = 5814 count = 213 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 101us (kms_flip:3251) DEBUG: name = flip last_ts = 555.577271 last_received_ts = 555.577209 last_seq = 5814 current_ts = 555.585571 current_received_ts = 555.585510 current_seq = 5815 count = 214 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 110us (kms_flip:3251) DEBUG: name = flip last_ts = 555.585571 last_received_ts = 555.585510 last_seq = 5815 current_ts = 555.593933 current_received_ts = 555.593872 current_seq = 5816 count = 215 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 149us (kms_flip:3251) DEBUG: name = flip last_ts = 555.593933 last_received_ts = 555.593872 last_seq = 5816 current_ts = 555.602295 current_received_ts = 555.602173 current_seq = 5817 count = 216 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 102us (kms_flip:3251) DEBUG: name = flip last_ts = 555.602295 last_received_ts = 555.602173 last_seq = 5817 current_ts = 555.610596 current_received_ts = 555.610535 current_seq = 5818 count = 217 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 117us (kms_flip:3251) DEBUG: name = flip last_ts = 555.610596 last_received_ts = 555.610535 last_seq = 5818 current_ts = 555.618958 current_received_ts = 555.618896 current_seq = 5819 count = 218 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 148us (kms_flip:3251) DEBUG: name = flip last_ts = 555.618958 last_received_ts = 555.618896 last_seq = 5819 current_ts = 555.627258 current_received_ts = 555.627197 current_seq = 5820 count = 219 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 102us (kms_flip:3251) DEBUG: name = flip last_ts = 555.627258 last_received_ts = 555.627197 last_seq = 5820 current_ts = 555.635620 current_received_ts = 555.635559 current_seq = 5821 count = 220 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 114us (kms_flip:3251) DEBUG: name = flip last_ts = 555.635620 last_received_ts = 555.635559 last_seq = 5821 current_ts = 555.643921 current_received_ts = 555.643860 current_seq = 5822 count = 221 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 146us (kms_flip:3251) DEBUG: name = flip last_ts = 555.643921 last_received_ts = 555.643860 last_seq = 5822 current_ts = 555.652283 current_received_ts = 555.652161 current_seq = 5823 count = 222 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 70us (kms_flip:3251) DEBUG: name = flip last_ts = 555.652283 last_received_ts = 555.652161 last_seq = 5823 current_ts = 555.660583 current_received_ts = 555.660522 current_seq = 5824 count = 223 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 110us (kms_flip:3251) DEBUG: name = flip last_ts = 555.660583 last_received_ts = 555.660522 last_seq = 5824 current_ts = 555.668945 current_received_ts = 555.668884 current_seq = 5825 count = 224 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 147us (kms_flip:3251) DEBUG: name = flip last_ts = 555.668945 last_received_ts = 555.668884 last_seq = 5825 current_ts = 555.677246 current_received_ts = 555.677185 current_seq = 5826 count = 225 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 110us (kms_flip:3251) DEBUG: name = flip last_ts = 555.677246 last_received_ts = 555.677185 last_seq = 5826 current_ts = 555.685608 current_received_ts = 555.685547 current_seq = 5827 count = 226 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 96us (kms_flip:3251) DEBUG: name = flip last_ts = 555.685608 last_received_ts = 555.685547 last_seq = 5827 current_ts = 555.693909 current_received_ts = 555.693848 current_seq = 5828 count = 227 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 146us (kms_flip:3251) DEBUG: name = flip last_ts = 555.693909 last_received_ts = 555.693848 last_seq = 5828 current_ts = 555.702271 current_received_ts = 555.702209 current_seq = 5829 count = 228 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 96us (kms_flip:3251) DEBUG: name = flip last_ts = 555.702271 last_received_ts = 555.702209 last_seq = 5829 current_ts = 555.710571 current_received_ts = 555.710510 current_seq = 5830 count = 229 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 111us (kms_flip:3251) DEBUG: name = flip last_ts = 555.710571 last_received_ts = 555.710510 last_seq = 5830 current_ts = 555.718933 current_received_ts = 555.718872 current_seq = 5831 count = 230 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 122us (kms_flip:3251) DEBUG: name = flip last_ts = 555.718933 last_received_ts = 555.718872 last_seq = 5831 current_ts = 555.727295 current_received_ts = 555.727173 current_seq = 5832 count = 231 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 112us (kms_flip:3251) DEBUG: name = flip last_ts = 555.727295 last_received_ts = 555.727173 last_seq = 5832 current_ts = 555.735596 current_received_ts = 555.735535 current_seq = 5833 count = 232 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 117us (kms_flip:3251) DEBUG: name = flip last_ts = 555.735596 last_received_ts = 555.735535 last_seq = 5833 current_ts = 555.743958 current_received_ts = 555.743896 current_seq = 5834 count = 233 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 144us (kms_flip:3251) DEBUG: name = flip last_ts = 555.743958 last_received_ts = 555.743896 last_seq = 5834 current_ts = 555.752258 current_received_ts = 555.752197 current_seq = 5835 count = 234 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 112us (kms_flip:3251) DEBUG: name = flip last_ts = 555.752258 last_received_ts = 555.752197 last_seq = 5835 current_ts = 555.760620 current_received_ts = 555.760559 current_seq = 5836 count = 235 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 73us (kms_flip:3251) DEBUG: name = flip last_ts = 555.760620 last_received_ts = 555.760559 last_seq = 5836 current_ts = 555.768921 current_received_ts = 555.768860 current_seq = 5837 count = 236 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 136us (kms_flip:3251) DEBUG: name = flip last_ts = 555.768921 last_received_ts = 555.768860 last_seq = 5837 current_ts = 555.777283 current_received_ts = 555.777161 current_seq = 5838 count = 237 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 112us (kms_flip:3251) DEBUG: name = flip last_ts = 555.777283 last_received_ts = 555.777161 last_seq = 5838 current_ts = 555.785583 current_received_ts = 555.785522 current_seq = 5839 count = 238 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 78us (kms_flip:3251) DEBUG: name = flip last_ts = 555.785583 last_received_ts = 555.785522 last_seq = 5839 current_ts = 555.793945 current_received_ts = 555.793884 current_seq = 5840 count = 239 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 126us (kms_flip:3251) DEBUG: name = flip last_ts = 555.793945 last_received_ts = 555.793884 last_seq = 5840 current_ts = 555.802246 current_received_ts = 555.802185 current_seq = 5841 count = 240 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 109us (kms_flip:3251) DEBUG: name = flip last_ts = 555.802246 last_received_ts = 555.802185 last_seq = 5841 current_ts = 555.810608 current_received_ts = 555.810486 current_seq = 5842 count = 241 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 96us (kms_flip:3251) DEBUG: name = flip last_ts = 555.810608 last_received_ts = 555.810486 last_seq = 5842 current_ts = 555.818909 current_received_ts = 555.818848 current_seq = 5843 count = 242 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 125us (kms_flip:3251) DEBUG: name = flip last_ts = 555.818909 last_received_ts = 555.818848 last_seq = 5843 current_ts = 555.827271 current_received_ts = 555.827209 current_seq = 5844 count = 243 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 98us (kms_flip:3251) DEBUG: name = flip last_ts = 555.827271 last_received_ts = 555.827209 last_seq = 5844 current_ts = 555.835632 current_received_ts = 555.835510 current_seq = 5845 count = 244 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 117us (kms_flip:3251) DEBUG: name = flip last_ts = 555.835632 last_received_ts = 555.835510 last_seq = 5845 current_ts = 555.843933 current_received_ts = 555.843872 current_seq = 5846 count = 245 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 135us (kms_flip:3251) DEBUG: name = flip last_ts = 555.843933 last_received_ts = 555.843872 last_seq = 5846 current_ts = 555.852295 current_received_ts = 555.852173 current_seq = 5847 count = 246 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 98us (kms_flip:3251) DEBUG: name = flip last_ts = 555.852295 last_received_ts = 555.852173 last_seq = 5847 current_ts = 555.860596 current_received_ts = 555.860474 current_seq = 5848 count = 247 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 112us (kms_flip:3251) DEBUG: name = flip last_ts = 555.860596 last_received_ts = 555.860474 last_seq = 5848 current_ts = 555.868958 current_received_ts = 555.868896 current_seq = 5849 count = 248 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 149us (kms_flip:3251) DEBUG: name = flip last_ts = 555.868958 last_received_ts = 555.868896 last_seq = 5849 current_ts = 555.877258 current_received_ts = 555.877197 current_seq = 5850 count = 249 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 110us (kms_flip:3251) DEBUG: name = flip last_ts = 555.877258 last_received_ts = 555.877197 last_seq = 5850 current_ts = 555.885620 current_received_ts = 555.885559 current_seq = 5851 count = 250 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 65us (kms_flip:3251) DEBUG: name = flip last_ts = 555.885620 last_received_ts = 555.885559 last_seq = 5851 current_ts = 555.893921 current_received_ts = 555.893860 current_seq = 5852 count = 251 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 136us (kms_flip:3251) DEBUG: name = flip last_ts = 555.893921 last_received_ts = 555.893860 last_seq = 5852 current_ts = 555.902283 current_received_ts = 555.902161 current_seq = 5853 count = 252 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 97us (kms_flip:3251) DEBUG: name = flip last_ts = 555.902283 last_received_ts = 555.902161 last_seq = 5853 current_ts = 555.910583 current_received_ts = 555.910522 current_seq = 5854 count = 253 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 101us (kms_flip:3251) DEBUG: name = flip last_ts = 555.910583 last_received_ts = 555.910522 last_seq = 5854 current_ts = 555.918945 current_received_ts = 555.918884 current_seq = 5855 count = 254 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 150us (kms_flip:3251) DEBUG: name = flip last_ts = 555.918945 last_received_ts = 555.918884 last_seq = 5855 current_ts = 555.927246 current_received_ts = 555.927185 current_seq = 5856 count = 255 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 111us (kms_flip:3251) DEBUG: name = flip last_ts = 555.927246 last_received_ts = 555.927185 last_seq = 5856 current_ts = 555.935608 current_received_ts = 555.935547 current_seq = 5857 count = 256 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 96us (kms_flip:3251) DEBUG: name = flip last_ts = 555.935608 last_received_ts = 555.935547 last_seq = 5857 current_ts = 555.943909 current_received_ts = 555.943909 current_seq = 5858 count = 257 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 151us (kms_flip:3251) DEBUG: name = flip last_ts = 555.943909 last_received_ts = 555.943909 last_seq = 5858 current_ts = 555.952271 current_received_ts = 555.952209 current_seq = 5859 count = 258 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 116us (kms_flip:3251) DEBUG: name = flip last_ts = 555.952271 last_received_ts = 555.952209 last_seq = 5859 current_ts = 555.960632 current_received_ts = 555.960510 current_seq = 5860 count = 259 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 108us (kms_flip:3251) DEBUG: name = flip last_ts = 555.960632 last_received_ts = 555.960510 last_seq = 5860 current_ts = 555.968933 current_received_ts = 555.968872 current_seq = 5861 count = 260 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 139us (kms_flip:3251) DEBUG: name = flip last_ts = 555.968933 last_received_ts = 555.968872 last_seq = 5861 current_ts = 555.977295 current_received_ts = 555.977173 current_seq = 5862 count = 261 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 117us (kms_flip:3251) DEBUG: name = flip last_ts = 555.977295 last_received_ts = 555.977173 last_seq = 5862 current_ts = 555.985596 current_received_ts = 555.985535 current_seq = 5863 count = 262 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 76us (kms_flip:3251) DEBUG: name = flip last_ts = 555.985596 last_received_ts = 555.985535 last_seq = 5863 current_ts = 555.993958 current_received_ts = 555.993896 current_seq = 5864 count = 263 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 125us (kms_flip:3251) DEBUG: name = flip last_ts = 555.993958 last_received_ts = 555.993896 last_seq = 5864 current_ts = 556.002258 current_received_ts = 556.002197 current_seq = 5865 count = 264 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 111us (kms_flip:3251) DEBUG: name = flip last_ts = 556.002258 last_received_ts = 556.002197 last_seq = 5865 current_ts = 556.010620 current_received_ts = 556.010559 current_seq = 5866 count = 265 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 118us (kms_flip:3251) DEBUG: name = flip last_ts = 556.010620 last_received_ts = 556.010559 last_seq = 5866 current_ts = 556.018921 current_received_ts = 556.018860 current_seq = 5867 count = 266 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 145us (kms_flip:3251) DEBUG: name = flip last_ts = 556.018921 last_received_ts = 556.018860 last_seq = 5867 current_ts = 556.027283 current_received_ts = 556.027161 current_seq = 5868 count = 267 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 113us (kms_flip:3251) DEBUG: name = flip last_ts = 556.027283 last_received_ts = 556.027161 last_seq = 5868 current_ts = 556.035583 current_received_ts = 556.035522 current_seq = 5869 count = 268 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 96us (kms_flip:3251) DEBUG: name = flip last_ts = 556.035583 last_received_ts = 556.035522 last_seq = 5869 current_ts = 556.043945 current_received_ts = 556.043884 current_seq = 5870 count = 269 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 145us (kms_flip:3251) DEBUG: name = flip last_ts = 556.043945 last_received_ts = 556.043884 last_seq = 5870 current_ts = 556.052246 current_received_ts = 556.052185 current_seq = 5871 count = 270 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 115us (kms_flip:3251) DEBUG: name = flip last_ts = 556.052246 last_received_ts = 556.052185 last_seq = 5871 current_ts = 556.060608 current_received_ts = 556.060547 current_seq = 5872 count = 271 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 101us (kms_flip:3251) DEBUG: name = flip last_ts = 556.060608 last_received_ts = 556.060547 last_seq = 5872 current_ts = 556.068970 current_received_ts = 556.068909 current_seq = 5873 count = 272 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 130us (kms_flip:3251) DEBUG: name = flip last_ts = 556.068970 last_received_ts = 556.068909 last_seq = 5873 current_ts = 556.077271 current_received_ts = 556.077209 current_seq = 5874 count = 273 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 73us (kms_flip:3251) DEBUG: name = flip last_ts = 556.077271 last_received_ts = 556.077209 last_seq = 5874 current_ts = 556.085632 current_received_ts = 556.085571 current_seq = 5875 count = 274 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 112us (kms_flip:3251) DEBUG: name = flip last_ts = 556.085632 last_received_ts = 556.085571 last_seq = 5875 current_ts = 556.093933 current_received_ts = 556.093872 current_seq = 5876 count = 275 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 136us (kms_flip:3251) DEBUG: name = flip last_ts = 556.093933 last_received_ts = 556.093872 last_seq = 5876 current_ts = 556.102295 current_received_ts = 556.102173 current_seq = 5877 count = 276 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 121us (kms_flip:3251) DEBUG: name = flip last_ts = 556.102295 last_received_ts = 556.102173 last_seq = 5877 current_ts = 556.110596 current_received_ts = 556.110474 current_seq = 5878 count = 277 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 111us (kms_flip:3251) DEBUG: name = flip last_ts = 556.110596 last_received_ts = 556.110474 last_seq = 5878 current_ts = 556.118958 current_received_ts = 556.118896 current_seq = 5879 count = 278 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 124us (kms_flip:3251) DEBUG: name = flip last_ts = 556.118958 last_received_ts = 556.118896 last_seq = 5879 current_ts = 556.127258 current_received_ts = 556.127197 current_seq = 5880 count = 279 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 98us (kms_flip:3251) DEBUG: name = flip last_ts = 556.127258 last_received_ts = 556.127197 last_seq = 5880 current_ts = 556.135620 current_received_ts = 556.135559 current_seq = 5881 count = 280 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 118us (kms_flip:3251) DEBUG: name = flip last_ts = 556.135620 last_received_ts = 556.135559 last_seq = 5881 current_ts = 556.143921 current_received_ts = 556.143860 current_seq = 5882 count = 281 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 150us (kms_flip:3251) DEBUG: name = flip last_ts = 556.143921 last_received_ts = 556.143860 last_seq = 5882 current_ts = 556.152283 current_received_ts = 556.152161 current_seq = 5883 count = 282 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 97us (kms_flip:3251) DEBUG: name = flip last_ts = 556.152283 last_received_ts = 556.152161 last_seq = 5883 current_ts = 556.160583 current_received_ts = 556.160522 current_seq = 5884 count = 283 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 112us (kms_flip:3251) DEBUG: name = flip last_ts = 556.160583 last_received_ts = 556.160522 last_seq = 5884 current_ts = 556.168945 current_received_ts = 556.168884 current_seq = 5885 count = 284 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 145us (kms_flip:3251) DEBUG: name = flip last_ts = 556.168945 last_received_ts = 556.168884 last_seq = 5885 current_ts = 556.177307 current_received_ts = 556.177185 current_seq = 5886 count = 285 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 78us (kms_flip:3251) DEBUG: name = flip last_ts = 556.177307 last_received_ts = 556.177185 last_seq = 5886 current_ts = 556.185608 current_received_ts = 556.185547 current_seq = 5887 count = 286 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 96us (kms_flip:3251) DEBUG: name = flip last_ts = 556.185608 last_received_ts = 556.185547 last_seq = 5887 current_ts = 556.193970 current_received_ts = 556.193909 current_seq = 5888 count = 287 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 130us (kms_flip:3251) DEBUG: name = flip last_ts = 556.193970 last_received_ts = 556.193909 last_seq = 5888 current_ts = 556.202271 current_received_ts = 556.202209 current_seq = 5889 count = 288 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 107us (kms_flip:3251) DEBUG: name = flip last_ts = 556.202271 last_received_ts = 556.202209 last_seq = 5889 current_ts = 556.210632 current_received_ts = 556.210571 current_seq = 5890 count = 289 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 109us (kms_flip:3251) DEBUG: name = flip last_ts = 556.210632 last_received_ts = 556.210571 last_seq = 5890 current_ts = 556.218933 current_received_ts = 556.218872 current_seq = 5891 count = 290 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 125us (kms_flip:3251) DEBUG: name = flip last_ts = 556.218933 last_received_ts = 556.218872 last_seq = 5891 current_ts = 556.227295 current_received_ts = 556.227173 current_seq = 5892 count = 291 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 109us (kms_flip:3251) DEBUG: name = flip last_ts = 556.227295 last_received_ts = 556.227173 last_seq = 5892 current_ts = 556.235596 current_received_ts = 556.235535 current_seq = 5893 count = 292 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 111us (kms_flip:3251) DEBUG: name = flip last_ts = 556.235596 last_received_ts = 556.235535 last_seq = 5893 current_ts = 556.243958 current_received_ts = 556.243896 current_seq = 5894 count = 293 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 128us (kms_flip:3251) DEBUG: name = flip last_ts = 556.243958 last_received_ts = 556.243896 last_seq = 5894 current_ts = 556.252258 current_received_ts = 556.252197 current_seq = 5895 count = 294 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 96us (kms_flip:3251) DEBUG: name = flip last_ts = 556.252258 last_received_ts = 556.252197 last_seq = 5895 current_ts = 556.260620 current_received_ts = 556.260559 current_seq = 5896 count = 295 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 111us (kms_flip:3251) DEBUG: name = flip last_ts = 556.260620 last_received_ts = 556.260559 last_seq = 5896 current_ts = 556.268921 current_received_ts = 556.268860 current_seq = 5897 count = 296 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 130us (kms_flip:3251) DEBUG: name = flip last_ts = 556.268921 last_received_ts = 556.268860 last_seq = 5897 current_ts = 556.277283 current_received_ts = 556.277161 current_seq = 5898 count = 297 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 84us (kms_flip:3251) DEBUG: name = flip last_ts = 556.277283 last_received_ts = 556.277161 last_seq = 5898 current_ts = 556.285583 current_received_ts = 556.285522 current_seq = 5899 count = 298 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 112us (kms_flip:3251) DEBUG: name = flip last_ts = 556.285583 last_received_ts = 556.285522 last_seq = 5899 current_ts = 556.293945 current_received_ts = 556.293884 current_seq = 5900 count = 299 seq_step = 1 (kms_flip:3251) DEBUG: Vblank took 1182us (kms_flip:3251) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:3251) CRITICAL: Failed assertion: end - start < 500 (kms_flip:3251) igt_core-INFO: Stack trace: (kms_flip:3251) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:3251) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:3251) igt_core-INFO: #2 ../tests/kms_flip.c:1884 run_test() (kms_flip:3251) igt_core-INFO: #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040() (kms_flip:3251) igt_core-INFO: #4 ../tests/kms_flip.c:2040 main() (kms_flip:3251) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:3251) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:3251) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest C-eDP1: FAIL (3.896s)
Dmesg	<6> [552.620595] [IGT] kms_flip: starting dynamic subtest C-eDP1 <7> [552.622500] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:241] <7> [552.623752] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:243] <7> [552.632679] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [552.633124] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [552.633495] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [552.693566] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:88:pipe A] <7> [552.693925] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [552.694448] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [552.695203] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B] <7> [552.695421] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [552.695890] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [552.696267] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1) <7> [552.696658] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in lane_count (expected 2, found 0) <7> [552.697034] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in dp_m_n (expected tu 64 data 7392460/8388608 link 308019/524288, found tu 0, data 0/0 link 0/0) <7> [552.697356] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [552.697685] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [552.697969] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [552.698248] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2080, found 0) <7> [552.698503] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [552.698804] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2080, found 0) <7> [552.699075] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1968, found 0) <7> [552.699306] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2000, found 0) <7> [552.699554] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1200, found 0) <7> [552.699819] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1200, found 0) <7> [552.700032] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1203, found 0) <7> [552.700244] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1209, found 0) <7> [552.700488] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1271, found 0) <7> [552.700720] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1271, found 0) <7> [552.700919] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [552.701114] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2080, found 0) <7> [552.701342] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [552.701564] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2080, found 0) <7> [552.701777] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1968, found 0) <7> [552.701956] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2000, found 0) <7> [552.702133] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1200, found 0) <7> [552.702301] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1200, found 0) <7> [552.702465] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1203, found 0) <7> [552.702678] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1209, found 0) <7> [552.702853] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1271, found 0) <7> [552.703008] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1271, found 0) <7> [552.703158] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [552.703303] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [552.703448] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [552.703615] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [552.703775] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [552.703912] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 317250, found 0) <7> [552.704042] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 317250, found 0) <7> [552.704173] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in port_clock (expected 540000, found 0) <7> [552.704302] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:145:pipe B] fastset requirement not met, forcing full modeset <7> [552.704582] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [552.704693] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:145:pipe B] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x2 -> 0x0 <7> [552.704835] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:140:cursor B] ddb (4037 - 4096) -> ( 0 - 0), size 59 -> 0 <7> [552.704970] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via squashing <7> [552.705108] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [552.705241] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 0, actual 0 <7> [552.705401] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:145:pipe B] enable: no [modeset] <7> [552.705562] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:90:plane 1B] fb: [NOFB], visible: no <7> [552.705688] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:100:plane 2B] fb: [NOFB], visible: no <7> [552.705807] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:110:plane 3B] fb: [NOFB], visible: no <7> [552.705921] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:120:plane 4B] fb: [NOFB], visible: no <7> [552.706032] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:130:plane 5B] fb: [NOFB], visible: no <7> [552.706142] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:140:cursor B] fb: [NOFB], visible: no <7> [552.706398] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [552.706516] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [552.908604] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 0 <7> [552.909270] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe B <7> [552.919924] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power off <7> [552.920369] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power off time <7> [552.920353] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [552.920850] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [552.920868] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - short <7> [552.974056] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [552.974480] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - long <7> [552.974912] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [552.980566] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [552.981113] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:204:DDI A/PHY A] <7> [552.981163] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [552.981745] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:204:DDI A/PHY A] <7> [552.981865] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A] <7> [552.982335] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1] <7> [552.982782] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A] <7> [552.983165] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B] <7> [552.983589] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C] <7> [552.983959] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2] <7> [552.984367] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A] <7> [552.984866] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B] <7> [552.985241] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C] <7> [552.985623] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3] <7> [552.985963] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A] <7> [552.986303] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B] <7> [552.986680] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C] <7> [552.987009] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1] <7> [552.987387] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [552.987855] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [552.988197] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [552.988849] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_B <7> [552.989355] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_2 <7> [552.989963] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:145:pipe B] <7> [552.990357] 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> [552.990889] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [552.991255] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [552.992194] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C] <7> [552.992629] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C] <7> [552.992713] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:205:eDP-1] <7> [552.992893] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:205:eDP-1] Limiting display bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36) <7> [552.993311] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:204:DDI A/PHY A][CRTC:202:pipe C] DP link limits: pixel clock 317250 kHz DSC off max lanes 2 max rate 540000 max pipe_bpp 24 max link_bpp 24.0000 <7> [552.993703] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 2 clock 540000 bpp input 24 compressed 0.0000 link rate required 951750 available 1080000 <7> [552.994065] xe 0000:00:02.0: [drm:intel_psr_compute_config [xe]] PSR2 not supported in transcoder C <7> [552.994345] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:202:pipe C] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [552.994728] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:204:DDI A/PHY A] [CRTC:202:pipe C] <7> [552.995030] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [552.995324] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [552.995634] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [552.995958] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in lane_count (expected 0, found 2) <7> [552.996205] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7392460/8388608 link 308019/524288) <7> [552.996523] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [552.996788] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [552.997020] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [552.997238] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2080) <7> [552.997449] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [552.997682] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2080) <7> [552.997881] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1968) <7> [552.998067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2000) <7> [552.998246] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1200) <7> [552.998425] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1200) <7> [552.998626] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1203) <7> [552.998814] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1209) <7> [552.998981] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1271) <7> [552.999136] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1271) <7> [552.999286] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [552.999436] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2080) <7> [552.999603] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [552.999742] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2080) <7> [552.999898] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1968) <7> [553.000031] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2000) <7> [553.000159] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1200) <7> [553.000282] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1200) <7> [553.000405] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1203) <7> [553.000547] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1209) <7> [553.000675] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1271) <7> [553.000799] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1271) <7> [553.000929] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [553.001064] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [553.001182] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [553.001290] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [553.001399] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in dpll_hw_state.cx0pll C20 <7> [553.001518] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] expected: <7> [553.001636] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c20pll_hw_state: <7> [553.001762] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000 <7> [553.001876] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [553.001979] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[0] = 0x10d2 <7> [553.002078] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[1] = 0x2108 <7> [553.002176] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[2] = 0x8d98 <7> [553.002273] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[3] = 0xbfc1 <7> [553.002370] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[4] = 0x7166 <7> [553.002468] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[5] = 0x5f42 <7> [553.002604] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[6] = 0x2000 <7> [553.002705] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[7] = 0x0001 <7> [553.002800] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[8] = 0x7800 <7> [553.002893] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[9] = 0x0000 <7> [553.002976] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[10] = 0x0000 <7> [553.003057] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] found: <7> [553.003138] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_hw_state: fracen: yes, <7> [553.003216] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] quot: 40960, rem: 0, den: 1, <7> [553.003295] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] multiplier: 140, tx_clk_div: 0. <7> [553.003372] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_rawhw_state: <7> [553.003448] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx: 0x10, cmn: 0x21 <7> [553.003531] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[0] = 0xf4, pll[1] = 0x0, pll[2] = 0xf8, pll[3] = 0x0 <7> [553.003624] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [553.003712] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [553.003799] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[12] = 0xa0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x0 <7> [553.003885] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[16] = 0x84, pll[17] = 0x4f, pll[18] = 0xe5, pll[19] = 0x23 <7> [553.003956] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [553.004027] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 317250) <7> [553.004096] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 317250) <7> [553.004166] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in port_clock (expected 0, found 540000) <7> [553.004237] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:202:pipe C] fastset requirement not met, forcing full modeset <7> [553.004327] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no <7> [553.004391] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:202:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4 <7> [553.004474] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:147:plane 1C] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989 <7> [553.004555] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:197:cursor C] ddb ( 0 - 0) -> (1989 - 2048), size 0 -> 59 <7> [553.004633] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [553.004706] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 17, 17, 17, 17, 17, 0, 0, 0, 4, 0 <7> [553.004779] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 261, 261, 261, 261, 261, 0, 0, 137, 62, 137 <7> [553.004848] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 367, 367, 367, 367, 367, 0, 0, 138, 123, 138 <7> [553.004923] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:202:pipe C] data rate 1269000 num active planes 1 <7> [553.005005] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1333 qgv_peak_bw: 38400 <7> [553.005082] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1333 qgv_peak_bw: 38400 <7> [553.005157] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1333 qgv_peak_bw: 38400 <7> [553.005232] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1333 qgv_peak_bw: 38400 <7> [553.005306] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1333 <7> [553.005395] xe 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [xe]] [PLANE:147:plane 1C] min cdclk (158625 kHz) > [CRTC:202:pipe C] min cdclk (0 kHz) <7> [553.005457] xe 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [xe]] new bandwidth min cdclk (24786 kHz) > old min cdclk (0 kHz) <7> [553.005547] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via squashing <7> [553.005647] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz <7> [553.005742] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 0, actual 0 <7> [553.005854] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:202:pipe C] enable: yes [modeset] <7> [553.005940] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [553.006020] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: C, pipe bpp: 24, dithering: 0 <7> [553.006100] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [553.006180] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [553.006253] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [553.006326] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [553.006398] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 2; data_m: 7392460, data_n: 8388608, link_m: 308019, link_n: 524288, tu: 64 <7> [553.006469] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 2; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [553.006558] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled <7> [553.006655] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [553.006748] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: disabled, panel replay: disabled, selective fetch: disabled <7> [553.006838] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [553.006918] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [553.006987] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 2, length 8 <7> [553.007056] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [553.007124] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [553.007192] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [553.007258] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [553.007325] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [553.007395] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [553.007460] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0 <7> [553.007536] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1271, vmax: 1271, flipline: 1271, pipeline full: 0, guardband: 71 vsync start: 68, vsync end: 62 <7> [553.007622] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1200, vmax vblank: 1200, vmin vtotal: 1271, vmax vtotal: 1271 <7> [553.007708] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "1920x1200": 120 317250 1920 1968 2000 2080 1200 1203 1209 1271 0x48 0xa <7> [553.007794] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "1920x1200": 120 317250 1920 1968 2000 2080 1200 1203 1209 1271 0x48 0xa <7> [553.007877] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=317250, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1200 vb=1200-1271 vs=1203-1209 vt=1271, flags=0xa <7> [553.007946] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "1920x1200": 120 317250 1920 1968 2000 2080 1200 1203 1209 1271 0x40 0xa <7> [553.008011] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=317250, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1200 vb=1200-1271 vs=1203-1209 vt=1271, flags=0xa <7> [553.008078] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 540000, pipe src: 1920x1200+0+0, pixel rate 317250 <7> [553.008143] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 53, ips linetime: 0 <7> [553.008208] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [553.008273] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [553.008339] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [553.008403] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0x83d60, dpll_md: 0xf42110, fp0: 0xf8, fp1: 0x1000000 <7> [553.008468] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [553.008549] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [553.008638] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [553.008726] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [553.008814] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [553.008896] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [553.008963] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [553.009029] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [553.009094] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [553.009160] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [553.009226] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [553.009291] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [553.009356] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:147:plane 1C] fb: [FB:241] 1920x1200 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [553.009423] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [553.009489] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1200.000000+0.000000+0.000000 dst: 1920x1200+0+0 <7> [553.009584] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:157:plane 2C] fb: [NOFB], visible: no <7> [553.009595] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [553.009671] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:167:plane 3C] fb: [NOFB], visible: no <7> [553.009755] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:177:plane 4C] fb: [NOFB], visible: no <7> [553.009741] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [553.009839] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:187:plane 5C] fb: [NOFB], visible: no <7> [553.009866] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [553.009920] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:197:cursor C] fb: [NOFB], visible: no <7> [553.009994] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [553.010251] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [553.010329] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [553.010575] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [553.010728] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [553.010868] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_C <7> [553.011001] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 172800 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [553.011084] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [553.011166] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=432 <7> [553.011242] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A] <7> [553.011304] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1] <7> [553.011364] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A] <7> [553.011423] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B] <7> [553.011481] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C] <7> [553.011557] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2] <7> [553.011634] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A] <7> [553.011708] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B] <7> [553.011781] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C] <7> [553.011856] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3] <7> [553.011925] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A] <7> [553.011983] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B] <7> [553.012041] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C] <7> [553.012098] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xd <7> [553.012249] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [553.012353] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [553.013571] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power on <7> [553.013662] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power cycle (468 ms remaining) <7> [553.484677] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [553.546157] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [553.546604] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power on <7> [553.546974] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [553.582497] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [553.582861] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - long <7> [553.583178] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [553.583551] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:204:DDI A/PHY A] <7> [553.758949] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [553.761329] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD on <7> [553.761911] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [553.764053] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c2 41 00 00 01 c0 02 00 00 00 00 0b 00 <7> [553.765244] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [553.766430] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 07 <7> [553.768016] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 2, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [553.769270] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [553.770671] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Clock recovery OK <7> [553.771236] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS3 <7> [553.772976] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [553.773546] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Link Training passed at link rate = 540000, lane count = 2 <7> [553.774637] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe C <7> [553.775264] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [553.775796] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe C <7> [553.776343] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 13892 <7> [553.777828] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] reserved 9830400 bytes of contiguous stolen space for FBC, limit: 1 <7> [553.778166] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] Enabling FBC on [PLANE:147:plane 1C] <7> [553.783784] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR1 <7> [553.785465] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1] <7> [553.786096] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:202:pipe C] <7> [556.292464] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD off <7> [556.293007] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <6> [556.517565] [IGT] kms_flip: finished subtest C-eDP1, FAIL

Detail

Value

Duration

3.90 seconds

Igt-Version

IGT-Version: 2.1-g162a06a82 (x86_64) (Linux: 6.17.0-rc7-lgci-xe-xe-3827-690ed0728a0e31e6b+ x86_64)

Out

Starting dynamic subtest: C-eDP1
  1920x1200: 120 317250 1920 1968 2000 2080 1200 1203 1209 1271 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1884 run_test()
  #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-eDP1: FAIL (3.896s)

Err

Starting dynamic subtest: C-eDP1
(kms_flip:3251) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:3251) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.277283
last_received_ts = 555.277222
last_seq = 5778
current_ts = 555.285583
current_received_ts = 555.285522
current_seq = 5779
count = 178
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 111us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.285583
last_received_ts = 555.285522
last_seq = 5779
current_ts = 555.293945
current_received_ts = 555.293884
current_seq = 5780
count = 179
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 143us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.293945
last_received_ts = 555.293884
last_seq = 5780
current_ts = 555.302246
current_received_ts = 555.302185
current_seq = 5781
count = 180
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 120us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.302246
last_received_ts = 555.302185
last_seq = 5781
current_ts = 555.310608
current_received_ts = 555.310547
current_seq = 5782
count = 181
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 96us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.310608
last_received_ts = 555.310547
last_seq = 5782
current_ts = 555.318909
current_received_ts = 555.318848
current_seq = 5783
count = 182
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 144us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.318909
last_received_ts = 555.318848
last_seq = 5783
current_ts = 555.327271
current_received_ts = 555.327209
current_seq = 5784
count = 183
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 110us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.327271
last_received_ts = 555.327209
last_seq = 5784
current_ts = 555.335571
current_received_ts = 555.335571
current_seq = 5785
count = 184
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 65us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.335571
last_received_ts = 555.335571
last_seq = 5785
current_ts = 555.343933
current_received_ts = 555.343872
current_seq = 5786
count = 185
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 96us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.343933
last_received_ts = 555.343872
last_seq = 5786
current_ts = 555.352234
current_received_ts = 555.352173
current_seq = 5787
count = 186
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 114us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.352234
last_received_ts = 555.352173
last_seq = 5787
current_ts = 555.360596
current_received_ts = 555.360535
current_seq = 5788
count = 187
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 112us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.360596
last_received_ts = 555.360535
last_seq = 5788
current_ts = 555.368896
current_received_ts = 555.368896
current_seq = 5789
count = 188
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 96us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.368896
last_received_ts = 555.368896
last_seq = 5789
current_ts = 555.377258
current_received_ts = 555.377197
current_seq = 5790
count = 189
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 97us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.377258
last_received_ts = 555.377197
last_seq = 5790
current_ts = 555.385620
current_received_ts = 555.385498
current_seq = 5791
count = 190
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 102us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.385620
last_received_ts = 555.385498
last_seq = 5791
current_ts = 555.393921
current_received_ts = 555.393860
current_seq = 5792
count = 191
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 144us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.393921
last_received_ts = 555.393860
last_seq = 5792
current_ts = 555.402283
current_received_ts = 555.402161
current_seq = 5793
count = 192
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 97us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.402283
last_received_ts = 555.402161
last_seq = 5793
current_ts = 555.410583
current_received_ts = 555.410522
current_seq = 5794
count = 193
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 96us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.410583
last_received_ts = 555.410522
last_seq = 5794
current_ts = 555.418945
current_received_ts = 555.418884
current_seq = 5795
count = 194
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 149us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.418945
last_received_ts = 555.418884
last_seq = 5795
current_ts = 555.427246
current_received_ts = 555.427185
current_seq = 5796
count = 195
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 101us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.427246
last_received_ts = 555.427185
last_seq = 5796
current_ts = 555.435608
current_received_ts = 555.435547
current_seq = 5797
count = 196
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 117us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.435608
last_received_ts = 555.435547
last_seq = 5797
current_ts = 555.443909
current_received_ts = 555.443848
current_seq = 5798
count = 197
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 72us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.443909
last_received_ts = 555.443848
last_seq = 5798
current_ts = 555.452271
current_received_ts = 555.452209
current_seq = 5799
count = 198
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 111us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.452271
last_received_ts = 555.452209
last_seq = 5799
current_ts = 555.460571
current_received_ts = 555.460510
current_seq = 5800
count = 199
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 101us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.460571
last_received_ts = 555.460510
last_seq = 5800
current_ts = 555.468933
current_received_ts = 555.468872
current_seq = 5801
count = 200
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 147us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.468933
last_received_ts = 555.468872
last_seq = 5801
current_ts = 555.477234
current_received_ts = 555.477173
current_seq = 5802
count = 201
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 110us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.477234
last_received_ts = 555.477173
last_seq = 5802
current_ts = 555.485596
current_received_ts = 555.485535
current_seq = 5803
count = 202
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 95us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.485596
last_received_ts = 555.485535
last_seq = 5803
current_ts = 555.493958
current_received_ts = 555.493835
current_seq = 5804
count = 203
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 142us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.493958
last_received_ts = 555.493835
last_seq = 5804
current_ts = 555.502258
current_received_ts = 555.502197
current_seq = 5805
count = 204
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 110us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.502258
last_received_ts = 555.502197
last_seq = 5805
current_ts = 555.510620
current_received_ts = 555.510498
current_seq = 5806
count = 205
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 109us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.510620
last_received_ts = 555.510498
last_seq = 5806
current_ts = 555.518921
current_received_ts = 555.518921
current_seq = 5807
count = 206
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 182us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.518921
last_received_ts = 555.518921
last_seq = 5807
current_ts = 555.527283
current_received_ts = 555.527222
current_seq = 5808
count = 207
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 113us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.527283
last_received_ts = 555.527222
last_seq = 5808
current_ts = 555.535583
current_received_ts = 555.535522
current_seq = 5809
count = 208
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 113us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.535583
last_received_ts = 555.535522
last_seq = 5809
current_ts = 555.543945
current_received_ts = 555.543884
current_seq = 5810
count = 209
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 152us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.543945
last_received_ts = 555.543884
last_seq = 5810
current_ts = 555.552246
current_received_ts = 555.552185
current_seq = 5811
count = 210
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 112us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.552246
last_received_ts = 555.552185
last_seq = 5811
current_ts = 555.560608
current_received_ts = 555.560547
current_seq = 5812
count = 211
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 65us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.560608
last_received_ts = 555.560547
last_seq = 5812
current_ts = 555.568909
current_received_ts = 555.568909
current_seq = 5813
count = 212
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 135us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.568909
last_received_ts = 555.568909
last_seq = 5813
current_ts = 555.577271
current_received_ts = 555.577209
current_seq = 5814
count = 213
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 101us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.577271
last_received_ts = 555.577209
last_seq = 5814
current_ts = 555.585571
current_received_ts = 555.585510
current_seq = 5815
count = 214
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 110us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.585571
last_received_ts = 555.585510
last_seq = 5815
current_ts = 555.593933
current_received_ts = 555.593872
current_seq = 5816
count = 215
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 149us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.593933
last_received_ts = 555.593872
last_seq = 5816
current_ts = 555.602295
current_received_ts = 555.602173
current_seq = 5817
count = 216
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 102us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.602295
last_received_ts = 555.602173
last_seq = 5817
current_ts = 555.610596
current_received_ts = 555.610535
current_seq = 5818
count = 217
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 117us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.610596
last_received_ts = 555.610535
last_seq = 5818
current_ts = 555.618958
current_received_ts = 555.618896
current_seq = 5819
count = 218
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 148us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.618958
last_received_ts = 555.618896
last_seq = 5819
current_ts = 555.627258
current_received_ts = 555.627197
current_seq = 5820
count = 219
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 102us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.627258
last_received_ts = 555.627197
last_seq = 5820
current_ts = 555.635620
current_received_ts = 555.635559
current_seq = 5821
count = 220
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 114us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.635620
last_received_ts = 555.635559
last_seq = 5821
current_ts = 555.643921
current_received_ts = 555.643860
current_seq = 5822
count = 221
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 146us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.643921
last_received_ts = 555.643860
last_seq = 5822
current_ts = 555.652283
current_received_ts = 555.652161
current_seq = 5823
count = 222
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 70us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.652283
last_received_ts = 555.652161
last_seq = 5823
current_ts = 555.660583
current_received_ts = 555.660522
current_seq = 5824
count = 223
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 110us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.660583
last_received_ts = 555.660522
last_seq = 5824
current_ts = 555.668945
current_received_ts = 555.668884
current_seq = 5825
count = 224
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 147us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.668945
last_received_ts = 555.668884
last_seq = 5825
current_ts = 555.677246
current_received_ts = 555.677185
current_seq = 5826
count = 225
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 110us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.677246
last_received_ts = 555.677185
last_seq = 5826
current_ts = 555.685608
current_received_ts = 555.685547
current_seq = 5827
count = 226
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 96us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.685608
last_received_ts = 555.685547
last_seq = 5827
current_ts = 555.693909
current_received_ts = 555.693848
current_seq = 5828
count = 227
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 146us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.693909
last_received_ts = 555.693848
last_seq = 5828
current_ts = 555.702271
current_received_ts = 555.702209
current_seq = 5829
count = 228
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 96us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.702271
last_received_ts = 555.702209
last_seq = 5829
current_ts = 555.710571
current_received_ts = 555.710510
current_seq = 5830
count = 229
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 111us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.710571
last_received_ts = 555.710510
last_seq = 5830
current_ts = 555.718933
current_received_ts = 555.718872
current_seq = 5831
count = 230
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 122us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.718933
last_received_ts = 555.718872
last_seq = 5831
current_ts = 555.727295
current_received_ts = 555.727173
current_seq = 5832
count = 231
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 112us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.727295
last_received_ts = 555.727173
last_seq = 5832
current_ts = 555.735596
current_received_ts = 555.735535
current_seq = 5833
count = 232
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 117us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.735596
last_received_ts = 555.735535
last_seq = 5833
current_ts = 555.743958
current_received_ts = 555.743896
current_seq = 5834
count = 233
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 144us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.743958
last_received_ts = 555.743896
last_seq = 5834
current_ts = 555.752258
current_received_ts = 555.752197
current_seq = 5835
count = 234
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 112us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.752258
last_received_ts = 555.752197
last_seq = 5835
current_ts = 555.760620
current_received_ts = 555.760559
current_seq = 5836
count = 235
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 73us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.760620
last_received_ts = 555.760559
last_seq = 5836
current_ts = 555.768921
current_received_ts = 555.768860
current_seq = 5837
count = 236
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 136us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.768921
last_received_ts = 555.768860
last_seq = 5837
current_ts = 555.777283
current_received_ts = 555.777161
current_seq = 5838
count = 237
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 112us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.777283
last_received_ts = 555.777161
last_seq = 5838
current_ts = 555.785583
current_received_ts = 555.785522
current_seq = 5839
count = 238
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 78us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.785583
last_received_ts = 555.785522
last_seq = 5839
current_ts = 555.793945
current_received_ts = 555.793884
current_seq = 5840
count = 239
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 126us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.793945
last_received_ts = 555.793884
last_seq = 5840
current_ts = 555.802246
current_received_ts = 555.802185
current_seq = 5841
count = 240
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 109us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.802246
last_received_ts = 555.802185
last_seq = 5841
current_ts = 555.810608
current_received_ts = 555.810486
current_seq = 5842
count = 241
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 96us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.810608
last_received_ts = 555.810486
last_seq = 5842
current_ts = 555.818909
current_received_ts = 555.818848
current_seq = 5843
count = 242
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 125us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.818909
last_received_ts = 555.818848
last_seq = 5843
current_ts = 555.827271
current_received_ts = 555.827209
current_seq = 5844
count = 243
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 98us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.827271
last_received_ts = 555.827209
last_seq = 5844
current_ts = 555.835632
current_received_ts = 555.835510
current_seq = 5845
count = 244
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 117us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.835632
last_received_ts = 555.835510
last_seq = 5845
current_ts = 555.843933
current_received_ts = 555.843872
current_seq = 5846
count = 245
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 135us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.843933
last_received_ts = 555.843872
last_seq = 5846
current_ts = 555.852295
current_received_ts = 555.852173
current_seq = 5847
count = 246
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 98us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.852295
last_received_ts = 555.852173
last_seq = 5847
current_ts = 555.860596
current_received_ts = 555.860474
current_seq = 5848
count = 247
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 112us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.860596
last_received_ts = 555.860474
last_seq = 5848
current_ts = 555.868958
current_received_ts = 555.868896
current_seq = 5849
count = 248
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 149us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.868958
last_received_ts = 555.868896
last_seq = 5849
current_ts = 555.877258
current_received_ts = 555.877197
current_seq = 5850
count = 249
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 110us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.877258
last_received_ts = 555.877197
last_seq = 5850
current_ts = 555.885620
current_received_ts = 555.885559
current_seq = 5851
count = 250
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 65us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.885620
last_received_ts = 555.885559
last_seq = 5851
current_ts = 555.893921
current_received_ts = 555.893860
current_seq = 5852
count = 251
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 136us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.893921
last_received_ts = 555.893860
last_seq = 5852
current_ts = 555.902283
current_received_ts = 555.902161
current_seq = 5853
count = 252
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 97us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.902283
last_received_ts = 555.902161
last_seq = 5853
current_ts = 555.910583
current_received_ts = 555.910522
current_seq = 5854
count = 253
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 101us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.910583
last_received_ts = 555.910522
last_seq = 5854
current_ts = 555.918945
current_received_ts = 555.918884
current_seq = 5855
count = 254
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 150us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.918945
last_received_ts = 555.918884
last_seq = 5855
current_ts = 555.927246
current_received_ts = 555.927185
current_seq = 5856
count = 255
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 111us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.927246
last_received_ts = 555.927185
last_seq = 5856
current_ts = 555.935608
current_received_ts = 555.935547
current_seq = 5857
count = 256
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 96us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.935608
last_received_ts = 555.935547
last_seq = 5857
current_ts = 555.943909
current_received_ts = 555.943909
current_seq = 5858
count = 257
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 151us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.943909
last_received_ts = 555.943909
last_seq = 5858
current_ts = 555.952271
current_received_ts = 555.952209
current_seq = 5859
count = 258
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 116us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.952271
last_received_ts = 555.952209
last_seq = 5859
current_ts = 555.960632
current_received_ts = 555.960510
current_seq = 5860
count = 259
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 108us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.960632
last_received_ts = 555.960510
last_seq = 5860
current_ts = 555.968933
current_received_ts = 555.968872
current_seq = 5861
count = 260
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 139us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.968933
last_received_ts = 555.968872
last_seq = 5861
current_ts = 555.977295
current_received_ts = 555.977173
current_seq = 5862
count = 261
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 117us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.977295
last_received_ts = 555.977173
last_seq = 5862
current_ts = 555.985596
current_received_ts = 555.985535
current_seq = 5863
count = 262
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 76us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.985596
last_received_ts = 555.985535
last_seq = 5863
current_ts = 555.993958
current_received_ts = 555.993896
current_seq = 5864
count = 263
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 125us
(kms_flip:3251) DEBUG: name = flip
last_ts = 555.993958
last_received_ts = 555.993896
last_seq = 5864
current_ts = 556.002258
current_received_ts = 556.002197
current_seq = 5865
count = 264
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 111us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.002258
last_received_ts = 556.002197
last_seq = 5865
current_ts = 556.010620
current_received_ts = 556.010559
current_seq = 5866
count = 265
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 118us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.010620
last_received_ts = 556.010559
last_seq = 5866
current_ts = 556.018921
current_received_ts = 556.018860
current_seq = 5867
count = 266
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 145us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.018921
last_received_ts = 556.018860
last_seq = 5867
current_ts = 556.027283
current_received_ts = 556.027161
current_seq = 5868
count = 267
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 113us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.027283
last_received_ts = 556.027161
last_seq = 5868
current_ts = 556.035583
current_received_ts = 556.035522
current_seq = 5869
count = 268
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 96us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.035583
last_received_ts = 556.035522
last_seq = 5869
current_ts = 556.043945
current_received_ts = 556.043884
current_seq = 5870
count = 269
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 145us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.043945
last_received_ts = 556.043884
last_seq = 5870
current_ts = 556.052246
current_received_ts = 556.052185
current_seq = 5871
count = 270
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 115us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.052246
last_received_ts = 556.052185
last_seq = 5871
current_ts = 556.060608
current_received_ts = 556.060547
current_seq = 5872
count = 271
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 101us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.060608
last_received_ts = 556.060547
last_seq = 5872
current_ts = 556.068970
current_received_ts = 556.068909
current_seq = 5873
count = 272
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 130us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.068970
last_received_ts = 556.068909
last_seq = 5873
current_ts = 556.077271
current_received_ts = 556.077209
current_seq = 5874
count = 273
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 73us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.077271
last_received_ts = 556.077209
last_seq = 5874
current_ts = 556.085632
current_received_ts = 556.085571
current_seq = 5875
count = 274
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 112us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.085632
last_received_ts = 556.085571
last_seq = 5875
current_ts = 556.093933
current_received_ts = 556.093872
current_seq = 5876
count = 275
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 136us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.093933
last_received_ts = 556.093872
last_seq = 5876
current_ts = 556.102295
current_received_ts = 556.102173
current_seq = 5877
count = 276
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 121us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.102295
last_received_ts = 556.102173
last_seq = 5877
current_ts = 556.110596
current_received_ts = 556.110474
current_seq = 5878
count = 277
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 111us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.110596
last_received_ts = 556.110474
last_seq = 5878
current_ts = 556.118958
current_received_ts = 556.118896
current_seq = 5879
count = 278
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 124us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.118958
last_received_ts = 556.118896
last_seq = 5879
current_ts = 556.127258
current_received_ts = 556.127197
current_seq = 5880
count = 279
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 98us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.127258
last_received_ts = 556.127197
last_seq = 5880
current_ts = 556.135620
current_received_ts = 556.135559
current_seq = 5881
count = 280
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 118us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.135620
last_received_ts = 556.135559
last_seq = 5881
current_ts = 556.143921
current_received_ts = 556.143860
current_seq = 5882
count = 281
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 150us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.143921
last_received_ts = 556.143860
last_seq = 5882
current_ts = 556.152283
current_received_ts = 556.152161
current_seq = 5883
count = 282
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 97us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.152283
last_received_ts = 556.152161
last_seq = 5883
current_ts = 556.160583
current_received_ts = 556.160522
current_seq = 5884
count = 283
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 112us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.160583
last_received_ts = 556.160522
last_seq = 5884
current_ts = 556.168945
current_received_ts = 556.168884
current_seq = 5885
count = 284
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 145us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.168945
last_received_ts = 556.168884
last_seq = 5885
current_ts = 556.177307
current_received_ts = 556.177185
current_seq = 5886
count = 285
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 78us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.177307
last_received_ts = 556.177185
last_seq = 5886
current_ts = 556.185608
current_received_ts = 556.185547
current_seq = 5887
count = 286
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 96us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.185608
last_received_ts = 556.185547
last_seq = 5887
current_ts = 556.193970
current_received_ts = 556.193909
current_seq = 5888
count = 287
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 130us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.193970
last_received_ts = 556.193909
last_seq = 5888
current_ts = 556.202271
current_received_ts = 556.202209
current_seq = 5889
count = 288
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 107us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.202271
last_received_ts = 556.202209
last_seq = 5889
current_ts = 556.210632
current_received_ts = 556.210571
current_seq = 5890
count = 289
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 109us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.210632
last_received_ts = 556.210571
last_seq = 5890
current_ts = 556.218933
current_received_ts = 556.218872
current_seq = 5891
count = 290
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 125us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.218933
last_received_ts = 556.218872
last_seq = 5891
current_ts = 556.227295
current_received_ts = 556.227173
current_seq = 5892
count = 291
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 109us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.227295
last_received_ts = 556.227173
last_seq = 5892
current_ts = 556.235596
current_received_ts = 556.235535
current_seq = 5893
count = 292
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 111us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.235596
last_received_ts = 556.235535
last_seq = 5893
current_ts = 556.243958
current_received_ts = 556.243896
current_seq = 5894
count = 293
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 128us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.243958
last_received_ts = 556.243896
last_seq = 5894
current_ts = 556.252258
current_received_ts = 556.252197
current_seq = 5895
count = 294
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 96us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.252258
last_received_ts = 556.252197
last_seq = 5895
current_ts = 556.260620
current_received_ts = 556.260559
current_seq = 5896
count = 295
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 111us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.260620
last_received_ts = 556.260559
last_seq = 5896
current_ts = 556.268921
current_received_ts = 556.268860
current_seq = 5897
count = 296
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 130us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.268921
last_received_ts = 556.268860
last_seq = 5897
current_ts = 556.277283
current_received_ts = 556.277161
current_seq = 5898
count = 297
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 84us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.277283
last_received_ts = 556.277161
last_seq = 5898
current_ts = 556.285583
current_received_ts = 556.285522
current_seq = 5899
count = 298
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 112us
(kms_flip:3251) DEBUG: name = flip
last_ts = 556.285583
last_received_ts = 556.285522
last_seq = 5899
current_ts = 556.293945
current_received_ts = 556.293884
current_seq = 5900
count = 299
seq_step = 1
(kms_flip:3251) DEBUG: Vblank took 1182us
(kms_flip:3251) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:3251) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3251) igt_core-INFO: Stack trace:
(kms_flip:3251) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:3251) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:3251) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:3251) igt_core-INFO:   #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
(kms_flip:3251) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:3251) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3251) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3251) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (3.896s)

Dmesg

<6> [552.620595] [IGT] kms_flip: starting dynamic subtest C-eDP1

<7> [552.622500] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:241]

<7> [552.623752] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:243]

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

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

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

<7> [552.693566] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:88:pipe A]

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

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

<7> [552.695203] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [552.703615] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in enhanced_framing (expected yes, found no)

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

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

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

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

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

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

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

<7> [552.704835] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:140:cursor B] ddb (4037 - 4096) -> ( 0 - 0), size 59 -> 0

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

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

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

<7> [552.705401] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:145:pipe B] enable: no [modeset]

<7> [552.705562] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:90:plane 1B] fb: [NOFB], visible: no

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

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

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

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

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

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

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

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

<7> [552.909270] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe B

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [552.988849] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_B

<7> [552.989355] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_2

<7> [552.989963] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:145:pipe B]

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

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

<7> [552.992194] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C]

<7> [552.992629] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C]

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

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

<7> [552.993311] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:204:DDI A/PHY A][CRTC:202:pipe C] DP link limits: pixel clock 317250 kHz DSC off max lanes 2 max rate 540000 max pipe_bpp 24 max link_bpp 24.0000

<7> [552.993703] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 2 clock 540000 bpp input 24 compressed 0.0000 link rate required 951750 available 1080000

<7> [552.994065] xe 0000:00:02.0: [drm:intel_psr_compute_config [xe]] PSR2 not supported in transcoder C

<7> [552.994345] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:202:pipe C] hw max bpp: 24, pipe bpp: 24, dithering: 0

<7> [552.994728] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:204:DDI A/PHY A] [CRTC:202:pipe C]

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

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

<7> [552.995634] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2)

<7> [552.995958] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in lane_count (expected 0, found 2)

<7> [552.996205] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7392460/8388608 link 308019/524288)

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

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

<7> [552.997020] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920)

<7> [552.997238] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2080)

<7> [552.997449] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920)

<7> [552.997682] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2080)

<7> [552.997881] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1968)

<7> [552.998067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2000)

<7> [552.998246] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1200)

<7> [552.998425] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1200)

<7> [552.998626] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1203)

<7> [552.998814] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1209)

<7> [552.998981] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1271)

<7> [552.999136] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1271)

<7> [552.999286] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920)

<7> [552.999436] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2080)

<7> [552.999603] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920)

<7> [552.999742] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2080)

<7> [552.999898] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1968)

<7> [553.000031] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2000)

<7> [553.000159] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1200)

<7> [553.000282] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1200)

<7> [553.000405] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1203)

<7> [553.000547] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1209)

<7> [553.000675] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1271)

<7> [553.000799] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1271)

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

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

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

<7> [553.001290] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes)

<7> [553.001399] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in dpll_hw_state.cx0pll C20

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

<7> [553.001636] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c20pll_hw_state:

<7> [553.001762] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000

<7> [553.001876] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [553.001979] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[0] = 0x10d2

<7> [553.002078] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[1] = 0x2108

<7> [553.002176] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[2] = 0x8d98

<7> [553.002273] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[3] = 0xbfc1

<7> [553.002370] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[4] = 0x7166

<7> [553.002468] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[5] = 0x5f42

<7> [553.002604] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[6] = 0x2000

<7> [553.002705] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[7] = 0x0001

<7> [553.002800] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[8] = 0x7800

<7> [553.002893] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[9] = 0x0000

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

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

<7> [553.003138] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_hw_state: fracen: yes,

<7> [553.003216] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] quot: 40960, rem: 0, den: 1,

<7> [553.003295] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] multiplier: 140, tx_clk_div: 0.

<7> [553.003372] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_rawhw_state:

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

<7> [553.003531] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[0] = 0xf4, pll[1] = 0x0, pll[2] = 0xf8, pll[3] = 0x0

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

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

<7> [553.003799] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[12] = 0xa0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x0

<7> [553.003885] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[16] = 0x84, pll[17] = 0x4f, pll[18] = 0xe5, pll[19] = 0x23

<7> [553.003956] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 24)

<7> [553.004027] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 317250)

<7> [553.004096] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 317250)

<7> [553.004166] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:202:pipe C] fastset requirement not met in port_clock (expected 0, found 540000)

<7> [553.004237] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:202:pipe C] fastset requirement not met, forcing full modeset

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

<7> [553.004391] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:202:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4

<7> [553.004474] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:147:plane 1C] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989

<7> [553.004555] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:197:cursor C] ddb ( 0 - 0) -> (1989 - 2048), size 0 -> 59

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

<7> [553.004706] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 17, 17, 17, 17, 17, 0, 0, 0, 4, 0

<7> [553.004779] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 261, 261, 261, 261, 261, 0, 0, 137, 62, 137

<7> [553.004848] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:147:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 367, 367, 367, 367, 367, 0, 0, 138, 123, 138

<7> [553.004923] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:202:pipe C] data rate 1269000 num active planes 1

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

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

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

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

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

<7> [553.005395] xe 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [xe]] [PLANE:147:plane 1C] min cdclk (158625 kHz) > [CRTC:202:pipe C] min cdclk (0 kHz)

<7> [553.005457] xe 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [xe]] new bandwidth min cdclk (24786 kHz) > old min cdclk (0 kHz)

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

<7> [553.005647] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz

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

<7> [553.005854] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:202:pipe C] enable: yes [modeset]

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

<7> [553.006020] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: C, pipe bpp: 24, dithering: 0

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

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

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

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

<7> [553.006398] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 2; data_m: 7392460, data_n: 8388608, link_m: 308019, link_n: 524288, tu: 64

<7> [553.006469] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 2; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0

<7> [553.006558] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled

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

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

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

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

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

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

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

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

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

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

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

<7> [553.007460] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0

<7> [553.007536] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1271, vmax: 1271, flipline: 1271, pipeline full: 0, guardband: 71 vsync start: 68, vsync end: 62

<7> [553.007622] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1200, vmax vblank: 1200, vmin vtotal: 1271, vmax vtotal: 1271

<7> [553.007708] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "1920x1200": 120 317250 1920 1968 2000 2080 1200 1203 1209 1271 0x48 0xa

<7> [553.007794] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "1920x1200": 120 317250 1920 1968 2000 2080 1200 1203 1209 1271 0x48 0xa

<7> [553.007877] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=317250, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1200 vb=1200-1271 vs=1203-1209 vt=1271, flags=0xa

<7> [553.007946] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "1920x1200": 120 317250 1920 1968 2000 2080 1200 1203 1209 1271 0x40 0xa

<7> [553.008011] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=317250, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1200 vb=1200-1271 vs=1203-1209 vt=1271, flags=0xa

<7> [553.008078] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 540000, pipe src: 1920x1200+0+0, pixel rate 317250

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

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

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

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

<7> [553.008403] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0x83d60, dpll_md: 0xf42110, fp0: 0xf8, fp1: 0x1000000

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

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

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

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

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

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

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

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

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

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

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

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

<7> [553.009356] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:147:plane 1C] fb: [FB:241] 1920x1200 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes

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

<7> [553.009489] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1200.000000+0.000000+0.000000 dst: 1920x1200+0+0

<7> [553.009584] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:157:plane 2C] fb: [NOFB], visible: no

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

<7> [553.009671] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:167:plane 3C] fb: [NOFB], visible: no

<7> [553.009755] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:177:plane 4C] fb: [NOFB], visible: no

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

<7> [553.009839] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:187:plane 5C] fb: [NOFB], visible: no

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

<7> [553.009920] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:197:cursor C] fb: [NOFB], visible: no

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

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

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

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

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

<7> [553.010868] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_C

<7> [553.011001] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 172800 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [553.764053] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c2 41 00 00 01 c0 02 00 00 00 00 0b 00

<7> [553.765244] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Reloading eDP link rates

<7> [553.766430] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 07

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

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

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

<7> [553.771236] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS3

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

<7> [553.773546] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Link Training passed at link rate = 540000, lane count = 2

<7> [553.774637] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe C

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

<7> [553.775796] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe C

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

<7> [553.777828] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] reserved 9830400 bytes of contiguous stolen space for FBC, limit: 1

<7> [553.778166] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] Enabling FBC on [PLANE:147:plane 1C]

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

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

<7> [553.786096] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:202:pipe C]

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

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

<6> [556.517565] [IGT] kms_flip: finished subtest C-eDP1, FAIL

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