igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1 on shard-lnl@IGTPW

Detail	Value
Duration	5.48 seconds
Hostname	shard-lnl-4
Igt-Version	IGT-Version: 2.4-g5f68f2d83 (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5062-dee34cfbffbfe2196-debug+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2074 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (5.481s)
Err	Starting dynamic subtest: B-eDP1 [336.708815] (kms_flip:6506) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [336.708914] (kms_flip:6506) CRITICAL: Failed assertion: end - start < 500 [336.708974] (kms_flip:6506) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG [334.691096] (kms_flip:6506) DEBUG: Vblank took 58us [334.707708] (kms_flip:6506) DEBUG: name = flip last_ts = 336.183502 last_received_ts = 336.182831 last_seq = 281 current_ts = 336.200165 current_received_ts = 336.199493 current_seq = 282 count = 133 seq_step = 1 [334.707769] (kms_flip:6506) DEBUG: Vblank took 57us [334.724335] (kms_flip:6506) DEBUG: name = flip last_ts = 336.200165 last_received_ts = 336.199493 last_seq = 282 current_ts = 336.216827 current_received_ts = 336.216125 current_seq = 283 count = 134 seq_step = 1 [334.724392] (kms_flip:6506) DEBUG: Vblank took 54us [334.741026] (kms_flip:6506) DEBUG: name = flip last_ts = 336.216827 last_received_ts = 336.216125 last_seq = 283 current_ts = 336.233490 current_received_ts = 336.232819 current_seq = 284 count = 135 seq_step = 1 [334.741083] (kms_flip:6506) DEBUG: Vblank took 55us [334.757699] (kms_flip:6506) DEBUG: name = flip last_ts = 336.233490 last_received_ts = 336.232819 last_seq = 284 current_ts = 336.250153 current_received_ts = 336.249481 current_seq = 285 count = 136 seq_step = 1 [334.757787] (kms_flip:6506) DEBUG: Vblank took 84us [334.774341] (kms_flip:6506) DEBUG: name = flip last_ts = 336.250153 last_received_ts = 336.249481 last_seq = 285 current_ts = 336.266815 current_received_ts = 336.266113 current_seq = 286 count = 137 seq_step = 1 [334.774407] (kms_flip:6506) DEBUG: Vblank took 62us [334.790925] (kms_flip:6506) DEBUG: name = flip last_ts = 336.266815 last_received_ts = 336.266113 last_seq = 286 current_ts = 336.283478 current_received_ts = 336.282715 current_seq = 287 count = 138 seq_step = 1 [334.790976] (kms_flip:6506) DEBUG: Vblank took 46us [334.807570] (kms_flip:6506) DEBUG: name = flip last_ts = 336.283478 last_received_ts = 336.282715 last_seq = 287 current_ts = 336.300140 current_received_ts = 336.299347 current_seq = 288 count = 139 seq_step = 1 [334.807628] (kms_flip:6506) DEBUG: Vblank took 56us [334.824335] (kms_flip:6506) DEBUG: name = flip last_ts = 336.300140 last_received_ts = 336.299347 last_seq = 288 current_ts = 336.316803 current_received_ts = 336.316101 current_seq = 289 count = 140 seq_step = 1 [334.824393] (kms_flip:6506) DEBUG: Vblank took 55us [334.841025] (kms_flip:6506) DEBUG: name = flip last_ts = 336.316803 last_received_ts = 336.316101 last_seq = 289 current_ts = 336.333466 current_received_ts = 336.332794 current_seq = 290 count = 141 seq_step = 1 [334.841089] (kms_flip:6506) DEBUG: Vblank took 60us [334.857669] (kms_flip:6506) DEBUG: name = flip last_ts = 336.333466 last_received_ts = 336.332794 last_seq = 290 current_ts = 336.350128 current_received_ts = 336.349457 current_seq = 291 count = 142 seq_step = 1 [334.857734] (kms_flip:6506) DEBUG: Vblank took 60us [334.874336] (kms_flip:6506) DEBUG: name = flip last_ts = 336.350128 last_received_ts = 336.349457 last_seq = 291 current_ts = 336.366791 current_received_ts = 336.366119 current_seq = 292 count = 143 seq_step = 1 [334.874400] (kms_flip:6506) DEBUG: Vblank took 61us [334.891005] (kms_flip:6506) DEBUG: name = flip last_ts = 336.366791 last_received_ts = 336.366119 last_seq = 292 current_ts = 336.383453 current_received_ts = 336.382782 current_seq = 293 count = 144 seq_step = 1 [334.891068] (kms_flip:6506) DEBUG: Vblank took 59us [334.907676] (kms_flip:6506) DEBUG: name = flip last_ts = 336.383453 last_received_ts = 336.382782 last_seq = 293 current_ts = 336.400116 current_received_ts = 336.399445 current_seq = 294 count = 145 seq_step = 1 [334.907737] (kms_flip:6506) DEBUG: Vblank took 57us [334.924337] (kms_flip:6506) DEBUG: name = flip last_ts = 336.400116 last_received_ts = 336.399445 last_seq = 294 current_ts = 336.416779 current_received_ts = 336.416107 current_seq = 295 count = 146 seq_step = 1 [334.924409] (kms_flip:6506) DEBUG: Vblank took 67us [334.940996] (kms_flip:6506) DEBUG: name = flip last_ts = 336.416779 last_received_ts = 336.416107 last_seq = 295 current_ts = 336.433441 current_received_ts = 336.432770 current_seq = 296 count = 147 seq_step = 1 [334.941050] (kms_flip:6506) DEBUG: Vblank took 51us [334.957674] (kms_flip:6506) DEBUG: name = flip last_ts = 336.433441 last_received_ts = 336.432770 last_seq = 296 current_ts = 336.450104 current_received_ts = 336.449432 current_seq = 297 count = 148 seq_step = 1 [334.957734] (kms_flip:6506) DEBUG: Vblank took 56us [334.974233] (kms_flip:6506) DEBUG: name = flip last_ts = 336.450104 last_received_ts = 336.449432 last_seq = 297 current_ts = 336.466766 current_received_ts = 336.465973 current_seq = 298 count = 149 seq_step = 1 [334.974364] (kms_flip:6506) DEBUG: Vblank took 84us [334.990888] (kms_flip:6506) DEBUG: name = flip last_ts = 336.466766 last_received_ts = 336.465973 last_seq = 298 current_ts = 336.483429 current_received_ts = 336.482635 current_seq = 299 count = 150 seq_step = 1 [334.990950] (kms_flip:6506) DEBUG: Vblank took 56us [335.007534] (kms_flip:6506) DEBUG: name = flip last_ts = 336.483429 last_received_ts = 336.482635 last_seq = 299 current_ts = 336.500092 current_received_ts = 336.499298 current_seq = 300 count = 151 seq_step = 1 [335.007601] (kms_flip:6506) DEBUG: Vblank took 62us [335.024333] (kms_flip:6506) DEBUG: name = flip last_ts = 336.500092 last_received_ts = 336.499298 last_seq = 300 current_ts = 336.516754 current_received_ts = 336.516083 current_seq = 301 count = 152 seq_step = 1 [335.024403] (kms_flip:6506) DEBUG: Vblank took 65us [335.040996] (kms_flip:6506) DEBUG: name = flip last_ts = 336.516754 last_received_ts = 336.516083 last_seq = 301 current_ts = 336.533417 current_received_ts = 336.532745 current_seq = 302 count = 153 seq_step = 1 [335.041064] (kms_flip:6506) DEBUG: Vblank took 65us [335.057679] (kms_flip:6506) DEBUG: name = flip last_ts = 336.533417 last_received_ts = 336.532745 last_seq = 302 current_ts = 336.550079 current_received_ts = 336.549438 current_seq = 303 count = 154 seq_step = 1 [335.057739] (kms_flip:6506) DEBUG: Vblank took 55us [335.074328] (kms_flip:6506) DEBUG: name = flip last_ts = 336.550079 last_received_ts = 336.549438 last_seq = 303 current_ts = 336.566742 current_received_ts = 336.566071 current_seq = 304 count = 155 seq_step = 1 [335.074392] (kms_flip:6506) DEBUG: Vblank took 59us [335.090970] (kms_flip:6506) DEBUG: name = flip last_ts = 336.566742 last_received_ts = 336.566071 last_seq = 304 current_ts = 336.583405 current_received_ts = 336.582703 current_seq = 305 count = 156 seq_step = 1 [335.091034] (kms_flip:6506) DEBUG: Vblank took 59us [335.107563] (kms_flip:6506) DEBUG: name = flip last_ts = 336.583405 last_received_ts = 336.582703 last_seq = 305 current_ts = 336.600067 current_received_ts = 336.599304 current_seq = 306 count = 157 seq_step = 1 [335.107617] (kms_flip:6506) DEBUG: Vblank took 51us [335.124316] (kms_flip:6506) DEBUG: name = flip last_ts = 336.600067 last_received_ts = 336.599304 last_seq = 306 current_ts = 336.616730 current_received_ts = 336.616058 current_seq = 307 count = 158 seq_step = 1 [335.124379] (kms_flip:6506) DEBUG: Vblank took 60us [335.140996] (kms_flip:6506) DEBUG: name = flip last_ts = 336.616730 last_received_ts = 336.616058 last_seq = 307 current_ts = 336.633392 current_received_ts = 336.632721 current_seq = 308 count = 159 seq_step = 1 [335.141057] (kms_flip:6506) DEBUG: Vblank took 57us [335.157628] (kms_flip:6506) DEBUG: name = flip last_ts = 336.633392 last_received_ts = 336.632721 last_seq = 308 current_ts = 336.650055 current_received_ts = 336.649353 current_seq = 309 count = 160 seq_step = 1 [335.157685] (kms_flip:6506) DEBUG: Vblank took 54us [335.174316] (kms_flip:6506) DEBUG: name = flip last_ts = 336.650055 last_received_ts = 336.649353 last_seq = 309 current_ts = 336.666687 current_received_ts = 336.666046 current_seq = 310 count = 161 seq_step = 1 [335.174381] (kms_flip:6506) DEBUG: Vblank took 61us [335.190867] (kms_flip:6506) DEBUG: name = flip last_ts = 336.666687 last_received_ts = 336.666046 last_seq = 310 current_ts = 336.683350 current_received_ts = 336.682587 current_seq = 311 count = 162 seq_step = 1 [335.190923] (kms_flip:6506) DEBUG: Vblank took 52us [335.207620] (kms_flip:6506) DEBUG: name = flip last_ts = 336.683350 last_received_ts = 336.682587 last_seq = 311 current_ts = 336.700043 current_received_ts = 336.699341 current_seq = 312 count = 163 seq_step = 1 [335.207677] (kms_flip:6506) DEBUG: Vblank took 53us [335.224296] (kms_flip:6506) DEBUG: name = flip last_ts = 336.700043 last_received_ts = 336.699341 last_seq = 312 current_ts = 336.716675 current_received_ts = 336.716003 current_seq = 313 count = 164 seq_step = 1 [335.224342] (kms_flip:6506) DEBUG: Vblank took 41us [335.240985] (kms_flip:6506) DEBUG: name = flip last_ts = 336.716675 last_received_ts = 336.716003 last_seq = 313 current_ts = 336.733337 current_received_ts = 336.732697 current_seq = 314 count = 165 seq_step = 1 [335.241067] (kms_flip:6506) DEBUG: Vblank took 77us [335.257623] (kms_flip:6506) DEBUG: name = flip last_ts = 336.733337 last_received_ts = 336.732697 last_seq = 314 current_ts = 336.750000 current_received_ts = 336.749329 current_seq = 315 count = 166 seq_step = 1 [335.257688] (kms_flip:6506) DEBUG: Vblank took 60us [335.274323] (kms_flip:6506) DEBUG: name = flip last_ts = 336.750000 last_received_ts = 336.749329 last_seq = 315 current_ts = 336.766663 current_received_ts = 336.766052 current_seq = 316 count = 167 seq_step = 1 [335.274390] (kms_flip:6506) DEBUG: Vblank took 62us [335.290955] (kms_flip:6506) DEBUG: name = flip last_ts = 336.766663 last_received_ts = 336.766052 last_seq = 316 current_ts = 336.783325 current_received_ts = 336.782684 current_seq = 317 count = 168 seq_step = 1 [335.291016] (kms_flip:6506) DEBUG: Vblank took 58us [335.307619] (kms_flip:6506) DEBUG: name = flip last_ts = 336.783325 last_received_ts = 336.782684 last_seq = 317 current_ts = 336.799988 current_received_ts = 336.799347 current_seq = 318 count = 169 seq_step = 1 [335.307675] (kms_flip:6506) DEBUG: Vblank took 51us [335.324268] (kms_flip:6506) DEBUG: name = flip last_ts = 336.799988 last_received_ts = 336.799347 last_seq = 318 current_ts = 336.816650 current_received_ts = 336.815979 current_seq = 319 count = 170 seq_step = 1 [335.324358] (kms_flip:6506) DEBUG: Vblank took 86us [335.340952] (kms_flip:6506) DEBUG: name = flip last_ts = 336.816650 last_received_ts = 336.815979 last_seq = 319 current_ts = 336.833313 current_received_ts = 336.832672 current_seq = 320 count = 171 seq_step = 1 [335.341038] (kms_flip:6506) DEBUG: Vblank took 83us [335.357605] (kms_flip:6506) DEBUG: name = flip last_ts = 336.833313 last_received_ts = 336.832672 last_seq = 320 current_ts = 336.849976 current_received_ts = 336.849304 current_seq = 321 count = 172 seq_step = 1 [335.357668] (kms_flip:6506) DEBUG: Vblank took 60us [335.374155] (kms_flip:6506) DEBUG: name = flip last_ts = 336.849976 last_received_ts = 336.849304 last_seq = 321 current_ts = 336.866638 current_received_ts = 336.865845 current_seq = 322 count = 173 seq_step = 1 [335.374225] (kms_flip:6506) DEBUG: Vblank took 65us [335.390958] (kms_flip:6506) DEBUG: name = flip last_ts = 336.866638 last_received_ts = 336.865845 last_seq = 322 current_ts = 336.883301 current_received_ts = 336.882660 current_seq = 323 count = 174 seq_step = 1 [335.391031] (kms_flip:6506) DEBUG: Vblank took 68us [335.407595] (kms_flip:6506) DEBUG: name = flip last_ts = 336.883301 last_received_ts = 336.882660 last_seq = 323 current_ts = 336.899963 current_received_ts = 336.899292 current_seq = 324 count = 175 seq_step = 1 [335.407667] (kms_flip:6506) DEBUG: Vblank took 68us [335.424245] (kms_flip:6506) DEBUG: name = flip last_ts = 336.899963 last_received_ts = 336.899292 last_seq = 324 current_ts = 336.916626 current_received_ts = 336.915955 current_seq = 325 count = 176 seq_step = 1 [335.424328] (kms_flip:6506) DEBUG: Vblank took 79us [335.440898] (kms_flip:6506) DEBUG: name = flip last_ts = 336.916626 last_received_ts = 336.915955 last_seq = 325 current_ts = 336.933289 current_received_ts = 336.932587 current_seq = 326 count = 177 seq_step = 1 [335.440958] (kms_flip:6506) DEBUG: Vblank took 56us [335.457527] (kms_flip:6506) DEBUG: name = flip last_ts = 336.933289 last_received_ts = 336.932587 last_seq = 326 current_ts = 336.949951 current_received_ts = 336.949188 current_seq = 327 count = 178 seq_step = 1 [335.457713] (kms_flip:6506) DEBUG: Vblank took 169us [335.474160] (kms_flip:6506) DEBUG: name = flip last_ts = 336.949951 last_received_ts = 336.949188 last_seq = 327 current_ts = 336.966614 current_received_ts = 336.965851 current_seq = 328 count = 179 seq_step = 1 [335.474251] (kms_flip:6506) DEBUG: Vblank took 81us [335.490915] (kms_flip:6506) DEBUG: name = flip last_ts = 336.966614 last_received_ts = 336.965851 last_seq = 328 current_ts = 336.983276 current_received_ts = 336.982574 current_seq = 329 count = 180 seq_step = 1 [335.491043] (kms_flip:6506) DEBUG: Vblank took 100us [335.507550] (kms_flip:6506) DEBUG: name = flip last_ts = 336.983276 last_received_ts = 336.982574 last_seq = 329 current_ts = 336.999939 current_received_ts = 336.999207 current_seq = 330 count = 181 seq_step = 1 [335.507685] (kms_flip:6506) DEBUG: Vblank took 108us [335.524216] (kms_flip:6506) DEBUG: name = flip last_ts = 336.999939 last_received_ts = 336.999207 last_seq = 330 current_ts = 337.016602 current_received_ts = 337.015900 current_seq = 331 count = 182 seq_step = 1 [335.524290] (kms_flip:6506) DEBUG: Vblank took 65us [335.540763] (kms_flip:6506) DEBUG: name = flip last_ts = 337.016602 last_received_ts = 337.015900 last_seq = 331 current_ts = 337.033264 current_received_ts = 337.032440 current_seq = 332 count = 183 seq_step = 1 [335.540821] (kms_flip:6506) DEBUG: Vblank took 54us [335.557412] (kms_flip:6506) DEBUG: name = flip last_ts = 337.033264 last_received_ts = 337.032440 last_seq = 332 current_ts = 337.049927 current_received_ts = 337.049103 current_seq = 333 count = 184 seq_step = 1 [335.557469] (kms_flip:6506) DEBUG: Vblank took 48us [335.574109] (kms_flip:6506) DEBUG: name = flip last_ts = 337.049927 last_received_ts = 337.049103 last_seq = 333 current_ts = 337.066589 current_received_ts = 337.065796 current_seq = 334 count = 185 seq_step = 1 [335.574177] (kms_flip:6506) DEBUG: Vblank took 61us [335.590764] (kms_flip:6506) DEBUG: name = flip last_ts = 337.066589 last_received_ts = 337.065796 last_seq = 334 current_ts = 337.083252 current_received_ts = 337.082428 current_seq = 335 count = 186 seq_step = 1 [335.590828] (kms_flip:6506) DEBUG: Vblank took 58us [335.607436] (kms_flip:6506) DEBUG: name = flip last_ts = 337.083252 last_received_ts = 337.082428 last_seq = 335 current_ts = 337.099915 current_received_ts = 337.099121 current_seq = 336 count = 187 seq_step = 1 [335.607475] (kms_flip:6506) DEBUG: Vblank took 34us [335.624246] (kms_flip:6506) DEBUG: name = flip last_ts = 337.099915 last_received_ts = 337.099121 last_seq = 336 current_ts = 337.116577 current_received_ts = 337.115906 current_seq = 337 count = 188 seq_step = 1 [335.624350] (kms_flip:6506) DEBUG: Vblank took 93us [335.640976] (kms_flip:6506) DEBUG: name = flip last_ts = 337.116577 last_received_ts = 337.115906 last_seq = 337 current_ts = 337.133240 current_received_ts = 337.132629 current_seq = 338 count = 189 seq_step = 1 [335.641056] (kms_flip:6506) DEBUG: Vblank took 73us [335.657575] (kms_flip:6506) DEBUG: name = flip last_ts = 337.133240 last_received_ts = 337.132629 last_seq = 338 current_ts = 337.149902 current_received_ts = 337.149231 current_seq = 339 count = 190 seq_step = 1 [335.657646] (kms_flip:6506) DEBUG: Vblank took 65us [335.674248] (kms_flip:6506) DEBUG: name = flip last_ts = 337.149902 last_received_ts = 337.149231 last_seq = 339 current_ts = 337.166534 current_received_ts = 337.165924 current_seq = 340 count = 191 seq_step = 1 [335.674318] (kms_flip:6506) DEBUG: Vblank took 65us [335.690984] (kms_flip:6506) DEBUG: name = flip last_ts = 337.166534 last_received_ts = 337.165924 last_seq = 340 current_ts = 337.183197 current_received_ts = 337.182648 current_seq = 341 count = 192 seq_step = 1 [335.691052] (kms_flip:6506) DEBUG: Vblank took 63us [335.707696] (kms_flip:6506) DEBUG: name = flip last_ts = 337.183197 last_received_ts = 337.182648 last_seq = 341 current_ts = 337.199860 current_received_ts = 337.199341 current_seq = 342 count = 193 seq_step = 1 [335.707757] (kms_flip:6506) DEBUG: Vblank took 56us [335.724245] (kms_flip:6506) DEBUG: name = flip last_ts = 337.199860 last_received_ts = 337.199341 last_seq = 342 current_ts = 337.216522 current_received_ts = 337.215912 current_seq = 343 count = 194 seq_step = 1 [335.724317] (kms_flip:6506) DEBUG: Vblank took 67us [335.740855] (kms_flip:6506) DEBUG: name = flip last_ts = 337.216522 last_received_ts = 337.215912 last_seq = 343 current_ts = 337.233215 current_received_ts = 337.232513 current_seq = 344 count = 195 seq_step = 1 [335.740914] (kms_flip:6506) DEBUG: Vblank took 54us [335.757506] (kms_flip:6506) DEBUG: name = flip last_ts = 337.233215 last_received_ts = 337.232513 last_seq = 344 current_ts = 337.249878 current_received_ts = 337.249146 current_seq = 345 count = 196 seq_step = 1 [335.757553] (kms_flip:6506) DEBUG: Vblank took 42us [335.774235] (kms_flip:6506) DEBUG: name = flip last_ts = 337.249878 last_received_ts = 337.249146 last_seq = 345 current_ts = 337.266510 current_received_ts = 337.265869 current_seq = 346 count = 197 seq_step = 1 [335.774301] (kms_flip:6506) DEBUG: Vblank took 61us [335.790759] (kms_flip:6506) DEBUG: name = flip last_ts = 337.266510 last_received_ts = 337.265869 last_seq = 346 current_ts = 337.283203 current_received_ts = 337.282410 current_seq = 347 count = 198 seq_step = 1 [335.790820] (kms_flip:6506) DEBUG: Vblank took 56us [335.807414] (kms_flip:6506) DEBUG: name = flip last_ts = 337.283203 last_received_ts = 337.282410 last_seq = 347 current_ts = 337.299835 current_received_ts = 337.299072 current_seq = 348 count = 199 seq_step = 1 [335.807475] (kms_flip:6506) DEBUG: Vblank took 56us [335.824156] (kms_flip:6506) DEBUG: name = flip last_ts = 337.299835 last_received_ts = 337.299072 last_seq = 348 current_ts = 337.316498 current_received_ts = 337.315765 current_seq = 349 count = 200 seq_step = 1 [335.824220] (kms_flip:6506) DEBUG: Vblank took 59us [335.840800] (kms_flip:6506) DEBUG: name = flip last_ts = 337.316498 last_received_ts = 337.315765 last_seq = 349 current_ts = 337.333160 current_received_ts = 337.332428 current_seq = 350 count = 201 seq_step = 1 [335.840864] (kms_flip:6506) DEBUG: Vblank took 58us [335.857629] (kms_flip:6506) DEBUG: name = flip last_ts = 337.333160 last_received_ts = 337.332428 last_seq = 350 current_ts = 337.349823 current_received_ts = 337.349274 current_seq = 351 count = 202 seq_step = 1 [335.857685] (kms_flip:6506) DEBUG: Vblank took 52us [335.874130] (kms_flip:6506) DEBUG: name = flip last_ts = 337.349823 last_received_ts = 337.349274 last_seq = 351 current_ts = 337.366486 current_received_ts = 337.365753 current_seq = 352 count = 203 seq_step = 1 [335.874195] (kms_flip:6506) DEBUG: Vblank took 59us [335.890765] (kms_flip:6506) DEBUG: name = flip last_ts = 337.366486 last_received_ts = 337.365753 last_seq = 352 current_ts = 337.383148 current_received_ts = 337.382385 current_seq = 353 count = 204 seq_step = 1 [335.890856] (kms_flip:6506) DEBUG: Vblank took 78us [335.907442] (kms_flip:6506) DEBUG: name = flip last_ts = 337.383148 last_received_ts = 337.382385 last_seq = 353 current_ts = 337.399811 current_received_ts = 337.399078 current_seq = 354 count = 205 seq_step = 1 [335.907516] (kms_flip:6506) DEBUG: Vblank took 66us [335.924102] (kms_flip:6506) DEBUG: name = flip last_ts = 337.399811 last_received_ts = 337.399078 last_seq = 354 current_ts = 337.416473 current_received_ts = 337.415741 current_seq = 355 count = 206 seq_step = 1 [335.924170] (kms_flip:6506) DEBUG: Vblank took 63us [335.940754] (kms_flip:6506) DEBUG: name = flip last_ts = 337.416473 last_received_ts = 337.415741 last_seq = 355 current_ts = 337.433136 current_received_ts = 337.432373 current_seq = 356 count = 207 seq_step = 1 [335.940831] (kms_flip:6506) DEBUG: Vblank took 68us [335.957437] (kms_flip:6506) DEBUG: name = flip last_ts = 337.433136 last_received_ts = 337.432373 last_seq = 356 current_ts = 337.449799 current_received_ts = 337.449066 current_seq = 357 count = 208 seq_step = 1 [335.957510] (kms_flip:6506) DEBUG: Vblank took 67us [335.974042] (kms_flip:6506) DEBUG: name = flip last_ts = 337.449799 last_received_ts = 337.449066 last_seq = 357 current_ts = 337.466461 current_received_ts = 337.465668 current_seq = 358 count = 209 seq_step = 1 [335.974123] (kms_flip:6506) DEBUG: Vblank took 73us [335.990699] (kms_flip:6506) DEBUG: name = flip last_ts = 337.466461 last_received_ts = 337.465668 last_seq = 358 current_ts = 337.483124 current_received_ts = 337.482330 current_seq = 359 count = 210 seq_step = 1 [335.990766] (kms_flip:6506) DEBUG: Vblank took 62us [336.007430] (kms_flip:6506) DEBUG: name = flip last_ts = 337.483124 last_received_ts = 337.482330 last_seq = 359 current_ts = 337.499786 current_received_ts = 337.499054 current_seq = 360 count = 211 seq_step = 1 [336.007499] (kms_flip:6506) DEBUG: Vblank took 63us [336.024051] (kms_flip:6506) DEBUG: name = flip last_ts = 337.499786 last_received_ts = 337.499054 last_seq = 360 current_ts = 337.516449 current_received_ts = 337.515656 current_seq = 361 count = 212 seq_step = 1 [336.024117] (kms_flip:6506) DEBUG: Vblank took 61us [336.040803] (kms_flip:6506) DEBUG: name = flip last_ts = 337.516449 last_received_ts = 337.515656 last_seq = 361 current_ts = 337.533112 current_received_ts = 337.532410 current_seq = 362 count = 213 seq_step = 1 [336.040869] (kms_flip:6506) DEBUG: Vblank took 60us [336.057415] (kms_flip:6506) DEBUG: name = flip last_ts = 337.533112 last_received_ts = 337.532410 last_seq = 362 current_ts = 337.549774 current_received_ts = 337.549011 current_seq = 363 count = 214 seq_step = 1 [336.057482] (kms_flip:6506) DEBUG: Vblank took 60us [336.074082] (kms_flip:6506) DEBUG: name = flip last_ts = 337.549774 last_received_ts = 337.549011 last_seq = 363 current_ts = 337.566437 current_received_ts = 337.565674 current_seq = 364 count = 215 seq_step = 1 [336.074150] (kms_flip:6506) DEBUG: Vblank took 61us [336.090725] (kms_flip:6506) DEBUG: name = flip last_ts = 337.566437 last_received_ts = 337.565674 last_seq = 364 current_ts = 337.583099 current_received_ts = 337.582336 current_seq = 365 count = 216 seq_step = 1 [336.090792] (kms_flip:6506) DEBUG: Vblank took 62us [336.107408] (kms_flip:6506) DEBUG: name = flip last_ts = 337.583099 last_received_ts = 337.582336 last_seq = 365 current_ts = 337.599762 current_received_ts = 337.598999 current_seq = 366 count = 217 seq_step = 1 [336.107481] (kms_flip:6506) DEBUG: Vblank took 68us [336.124070] (kms_flip:6506) DEBUG: name = flip last_ts = 337.599762 last_received_ts = 337.598999 last_seq = 366 current_ts = 337.616425 current_received_ts = 337.615662 current_seq = 367 count = 218 seq_step = 1 [336.124142] (kms_flip:6506) DEBUG: Vblank took 66us [336.140703] (kms_flip:6506) DEBUG: name = flip last_ts = 337.616425 last_received_ts = 337.615662 last_seq = 367 current_ts = 337.633087 current_received_ts = 337.632294 current_seq = 368 count = 219 seq_step = 1 [336.140778] (kms_flip:6506) DEBUG: Vblank took 67us [336.157392] (kms_flip:6506) DEBUG: name = flip last_ts = 337.633087 last_received_ts = 337.632294 last_seq = 368 current_ts = 337.649750 current_received_ts = 337.648987 current_seq = 369 count = 220 seq_step = 1 [336.157474] (kms_flip:6506) DEBUG: Vblank took 76us [336.174134] (kms_flip:6506) DEBUG: name = flip last_ts = 337.649750 last_received_ts = 337.648987 last_seq = 369 current_ts = 337.666412 current_received_ts = 337.665710 current_seq = 370 count = 221 seq_step = 1 [336.174207] (kms_flip:6506) DEBUG: Vblank took 65us [336.190678] (kms_flip:6506) DEBUG: name = flip last_ts = 337.666412 last_received_ts = 337.665710 last_seq = 370 current_ts = 337.683075 current_received_ts = 337.682251 current_seq = 371 count = 222 seq_step = 1 [336.190750] (kms_flip:6506) DEBUG: Vblank took 65us [336.207378] (kms_flip:6506) DEBUG: name = flip last_ts = 337.683075 last_received_ts = 337.682251 last_seq = 371 current_ts = 337.699738 current_received_ts = 337.698975 current_seq = 372 count = 223 seq_step = 1 [336.207474] (kms_flip:6506) DEBUG: Vblank took 92us [336.224030] (kms_flip:6506) DEBUG: name = flip last_ts = 337.699738 last_received_ts = 337.698975 last_seq = 372 current_ts = 337.716400 current_received_ts = 337.715607 current_seq = 373 count = 224 seq_step = 1 [336.224102] (kms_flip:6506) DEBUG: Vblank took 66us [336.240810] (kms_flip:6506) DEBUG: name = flip last_ts = 337.716400 last_received_ts = 337.715607 last_seq = 373 current_ts = 337.733063 current_received_ts = 337.732391 current_seq = 374 count = 225 seq_step = 1 [336.240881] (kms_flip:6506) DEBUG: Vblank took 66us [336.257352] (kms_flip:6506) DEBUG: name = flip last_ts = 337.733063 last_received_ts = 337.732391 last_seq = 374 current_ts = 337.749695 current_received_ts = 337.748932 current_seq = 375 count = 226 seq_step = 1 [336.257439] (kms_flip:6506) DEBUG: Vblank took 80us [336.274032] (kms_flip:6506) DEBUG: name = flip last_ts = 337.749695 last_received_ts = 337.748932 last_seq = 375 current_ts = 337.766388 current_received_ts = 337.765594 current_seq = 376 count = 227 seq_step = 1 [336.274104] (kms_flip:6506) DEBUG: Vblank took 67us [336.290695] (kms_flip:6506) DEBUG: name = flip last_ts = 337.766388 last_received_ts = 337.765594 last_seq = 376 current_ts = 337.783020 current_received_ts = 337.782257 current_seq = 377 count = 228 seq_step = 1 [336.290767] (kms_flip:6506) DEBUG: Vblank took 66us [336.307366] (kms_flip:6506) DEBUG: name = flip last_ts = 337.783020 last_received_ts = 337.782257 last_seq = 377 current_ts = 337.799713 current_received_ts = 337.798950 current_seq = 378 count = 229 seq_step = 1 [336.307494] (kms_flip:6506) DEBUG: Vblank took 121us [336.324032] (kms_flip:6506) DEBUG: name = flip last_ts = 337.799713 last_received_ts = 337.798950 last_seq = 378 current_ts = 337.816345 current_received_ts = 337.815613 current_seq = 379 count = 230 seq_step = 1 [336.324105] (kms_flip:6506) DEBUG: Vblank took 66us [336.340675] (kms_flip:6506) DEBUG: name = flip last_ts = 337.816345 last_received_ts = 337.815613 last_seq = 379 current_ts = 337.833008 current_received_ts = 337.832245 current_seq = 380 count = 231 seq_step = 1 [336.340748] (kms_flip:6506) DEBUG: Vblank took 66us [336.357362] (kms_flip:6506) DEBUG: name = flip last_ts = 337.833008 last_received_ts = 337.832245 last_seq = 380 current_ts = 337.849670 current_received_ts = 337.848938 current_seq = 381 count = 232 seq_step = 1 [336.357452] (kms_flip:6506) DEBUG: Vblank took 84us [336.374020] (kms_flip:6506) DEBUG: name = flip last_ts = 337.849670 last_received_ts = 337.848938 last_seq = 381 current_ts = 337.866333 current_received_ts = 337.865570 current_seq = 382 count = 233 seq_step = 1 [336.374094] (kms_flip:6506) DEBUG: Vblank took 68us [336.390758] (kms_flip:6506) DEBUG: name = flip last_ts = 337.866333 last_received_ts = 337.865570 last_seq = 382 current_ts = 337.882996 current_received_ts = 337.882294 current_seq = 383 count = 234 seq_step = 1 [336.390907] (kms_flip:6506) DEBUG: Vblank took 123us [336.407338] (kms_flip:6506) DEBUG: name = flip last_ts = 337.882996 last_received_ts = 337.882294 last_seq = 383 current_ts = 337.899658 current_received_ts = 337.898895 current_seq = 384 count = 235 seq_step = 1 [336.407411] (kms_flip:6506) DEBUG: Vblank took 67us [336.424116] (kms_flip:6506) DEBUG: name = flip last_ts = 337.899658 last_received_ts = 337.898895 last_seq = 384 current_ts = 337.916321 current_received_ts = 337.915680 current_seq = 385 count = 236 seq_step = 1 [336.424181] (kms_flip:6506) DEBUG: Vblank took 61us [336.440628] (kms_flip:6506) DEBUG: name = flip last_ts = 337.916321 last_received_ts = 337.915680 last_seq = 385 current_ts = 337.932983 current_received_ts = 337.932190 current_seq = 386 count = 237 seq_step = 1 [336.440683] (kms_flip:6506) DEBUG: Vblank took 51us [336.457473] (kms_flip:6506) DEBUG: name = flip last_ts = 337.932983 last_received_ts = 337.932190 last_seq = 386 current_ts = 337.949646 current_received_ts = 337.949036 current_seq = 387 count = 238 seq_step = 1 [336.457519] (kms_flip:6506) DEBUG: Vblank took 43us [336.474089] (kms_flip:6506) DEBUG: name = flip last_ts = 337.949646 last_received_ts = 337.949036 last_seq = 387 current_ts = 337.966309 current_received_ts = 337.965637 current_seq = 388 count = 239 seq_step = 1 [336.474143] (kms_flip:6506) DEBUG: Vblank took 52us [336.490667] (kms_flip:6506) DEBUG: name = flip last_ts = 337.966309 last_received_ts = 337.965637 last_seq = 388 current_ts = 337.982971 current_received_ts = 337.982208 current_seq = 389 count = 240 seq_step = 1 [336.490718] (kms_flip:6506) DEBUG: Vblank took 48us [336.507408] (kms_flip:6506) DEBUG: name = flip last_ts = 337.982971 last_received_ts = 337.982208 last_seq = 389 current_ts = 337.999634 current_received_ts = 337.998962 current_seq = 390 count = 241 seq_step = 1 [336.507469] (kms_flip:6506) DEBUG: Vblank took 57us [336.524056] (kms_flip:6506) DEBUG: name = flip last_ts = 337.999634 last_received_ts = 337.998962 last_seq = 390 current_ts = 338.016296 current_received_ts = 338.015594 current_seq = 391 count = 242 seq_step = 1 [336.524109] (kms_flip:6506) DEBUG: Vblank took 49us [336.540720] (kms_flip:6506) DEBUG: name = flip last_ts = 338.016296 last_received_ts = 338.015594 last_seq = 391 current_ts = 338.032959 current_received_ts = 338.032257 current_seq = 392 count = 243 seq_step = 1 [336.540772] (kms_flip:6506) DEBUG: Vblank took 49us [336.557406] (kms_flip:6506) DEBUG: name = flip last_ts = 338.032959 last_received_ts = 338.032257 last_seq = 392 current_ts = 338.049622 current_received_ts = 338.048950 current_seq = 393 count = 244 seq_step = 1 [336.557486] (kms_flip:6506) DEBUG: Vblank took 76us [336.574070] (kms_flip:6506) DEBUG: name = flip last_ts = 338.049622 last_received_ts = 338.048950 last_seq = 393 current_ts = 338.066284 current_received_ts = 338.065613 current_seq = 394 count = 245 seq_step = 1 [336.574123] (kms_flip:6506) DEBUG: Vblank took 50us [336.590726] (kms_flip:6506) DEBUG: name = flip last_ts = 338.066284 last_received_ts = 338.065613 last_seq = 394 current_ts = 338.082947 current_received_ts = 338.082275 current_seq = 395 count = 246 seq_step = 1 [336.590781] (kms_flip:6506) DEBUG: Vblank took 52us [336.607390] (kms_flip:6506) DEBUG: name = flip last_ts = 338.082947 last_received_ts = 338.082275 last_seq = 395 current_ts = 338.099609 current_received_ts = 338.098938 current_seq = 396 count = 247 seq_step = 1 [336.607448] (kms_flip:6506) DEBUG: Vblank took 55us [336.624071] (kms_flip:6506) DEBUG: name = flip last_ts = 338.099609 last_received_ts = 338.098938 last_seq = 396 current_ts = 338.116272 current_received_ts = 338.115601 current_seq = 397 count = 248 seq_step = 1 [336.624134] (kms_flip:6506) DEBUG: Vblank took 59us [336.640693] (kms_flip:6506) DEBUG: name = flip last_ts = 338.116272 last_received_ts = 338.115601 last_seq = 397 current_ts = 338.132935 current_received_ts = 338.132233 current_seq = 398 count = 249 seq_step = 1 [336.640743] (kms_flip:6506) DEBUG: Vblank took 47us [336.657327] (kms_flip:6506) DEBUG: name = flip last_ts = 338.132935 last_received_ts = 338.132233 last_seq = 398 current_ts = 338.149597 current_received_ts = 338.148865 current_seq = 399 count = 250 seq_step = 1 [336.657369] (kms_flip:6506) DEBUG: Vblank took 40us [336.674018] (kms_flip:6506) DEBUG: name = flip last_ts = 338.149597 last_received_ts = 338.148865 last_seq = 399 current_ts = 338.166260 current_received_ts = 338.165558 current_seq = 400 count = 251 seq_step = 1 [336.674063] (kms_flip:6506) DEBUG: Vblank took 43us [336.690701] (kms_flip:6506) DEBUG: name = flip last_ts = 338.166260 last_received_ts = 338.165558 last_seq = 400 current_ts = 338.182922 current_received_ts = 338.182220 current_seq = 401 count = 252 seq_step = 1 [336.690759] (kms_flip:6506) DEBUG: Vblank took 56us [336.707373] (kms_flip:6506) DEBUG: name = flip last_ts = 338.182922 last_received_ts = 338.182220 last_seq = 401 current_ts = 338.199585 current_received_ts = 338.198883 current_seq = 402 count = 253 seq_step = 1 [336.708810] (kms_flip:6506) DEBUG: Vblank took 1434us [336.708815] (kms_flip:6506) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [336.708914] (kms_flip:6506) CRITICAL: Failed assertion: end - start < 500 [336.708974] (kms_flip:6506) CRITICAL: Last errno: 4, Interrupted system call [336.723654] (kms_flip:6506) igt_core-INFO: Stack trace: [336.737727] (kms_flip:6506) igt_core-INFO: #0 ../lib/igt_core.c:2074 __igt_fail_assert() [336.739075] (kms_flip:6506) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [336.739146] (kms_flip:6506) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [336.739184] (kms_flip:6506) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() [336.739234] (kms_flip:6506) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [336.743772] (kms_flip:6506) igt_core-INFO: #5 [__libc_init_first+0x8a] [336.744632] (kms_flip:6506) igt_core-INFO: #6 [__libc_start_main+0x8b] [336.744858] (kms_flip:6506) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (5.481s)
Dmesg	<6> [424.477183] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [424.479959] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430] <7> [424.482017] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [424.490604] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [424.491059] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [424.491423] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [424.541927] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [424.542008] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [424.542138] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [424.542240] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [424.542346] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [424.542451] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [424.542566] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [424.542690] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [424.542811] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [424.542927] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [424.543033] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [424.543126] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [424.543215] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [424.543307] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [424.543402] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [424.543497] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [424.543614] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [424.543725] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [424.543835] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [424.543939] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [424.544028] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [424.544109] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [424.544195] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [424.544283] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [424.544371] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [424.544453] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [424.544533] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [424.544651] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [424.544752] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [424.544850] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [424.544938] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [424.545023] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [424.545108] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [424.545186] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [424.545261] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [424.545351] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [424.545439] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [424.545528] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [424.545643] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [424.545749] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [424.545853] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [424.545969] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [424.546045] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [424.546141] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [424.546217] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [424.546322] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [424.546429] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [424.546537] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [424.546695] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [424.546821] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [424.546921] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [424.547016] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [424.547101] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [424.547184] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [424.547266] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [424.547385] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [424.547484] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [424.547799] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [424.547946] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [424.750887] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [424.751497] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [424.757024] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [424.757426] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [424.757554] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [424.758133] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [424.758080] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [424.810039] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [424.810567] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [424.817637] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [424.818177] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [424.818229] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [424.818766] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [424.819841] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [424.820488] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [424.821201] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [424.821723] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [424.822159] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [424.822601] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [424.823068] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [424.823485] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [424.823933] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [424.824351] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [424.824785] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [424.825224] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [424.825679] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [424.826095] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [424.826476] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [424.826895] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [424.827384] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [424.827770] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [424.828122] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [424.828741] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [424.829216] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [424.829766] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [424.830129] 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> [424.830597] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [424.830895] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [424.831783] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [424.832124] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [424.832381] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [424.832446] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [424.832630] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [424.832962] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [424.833246] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [424.833541] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [424.833853] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [424.834189] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [424.834437] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [424.834694] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [424.834959] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [424.835206] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [424.835429] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [424.835656] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [424.835869] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [424.836056] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [424.836245] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [424.836424] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [424.836636] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [424.836817] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [424.836984] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [424.837152] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [424.837303] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [424.837450] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [424.837607] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [424.837758] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [424.837909] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [424.838056] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [424.838202] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [424.838329] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [424.838452] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [424.838574] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [424.838727] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [424.838857] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [424.839003] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [424.839142] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [424.839259] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [424.839372] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [424.839481] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [424.839594] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [424.839701] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [424.839818] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [424.839927] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [424.840030] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [424.840130] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [424.840226] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [424.840360] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [424.840449] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [424.840557] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [424.840707] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:264:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [424.840801] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [424.840890] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [424.840967] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [424.841038] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [424.841123] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [424.841220] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [424.841311] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [424.841397] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [424.841482] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [424.841563] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [424.841668] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [424.841802] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [424.841926] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [424.842039] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [424.842138] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [424.842230] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [424.842324] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [424.842424] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [424.842511] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [424.842600] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [424.842704] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [424.842812] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [424.842913] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [424.842995] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [424.843077] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [424.843167] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [424.843258] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [424.843346] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [424.843427] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [424.843510] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [424.843595] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [424.843698] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [424.843800] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [424.843898] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [424.843977] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [424.844055] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [424.844131] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [424.844209] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [424.844300] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [424.844388] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [424.844466] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [424.844547] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [424.844651] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [424.844757] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [424.844861] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [424.844959] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [424.845040] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0 <7> [424.845118] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [424.845197] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [424.845283] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [424.845367] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [424.845445] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [424.845522] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [424.845605] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [424.845704] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [424.845804] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [424.845903] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [424.845991] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [424.846065] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [424.846140] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [424.846223] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [424.846303] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [424.846379] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [424.846455] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [424.846531] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [424.846547] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [424.846632] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [424.846663] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [424.846730] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [424.846778] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [424.846829] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [424.846916] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [424.846912] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [424.847006] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [424.847117] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [424.847225] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [424.847307] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [424.847387] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [424.847465] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [424.847541] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:430] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [424.847643] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [424.847754] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [424.847856] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [424.847954] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [424.848035] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [424.848112] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [424.848202] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [424.848542] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [424.848716] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [424.848903] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [424.849006] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [424.849101] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [424.849212] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [424.849317] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [424.849391] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [424.849462] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [424.849531] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [424.849605] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [424.849695] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [424.849782] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [424.849879] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [424.849983] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [424.850062] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [424.850135] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [424.850201] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [424.850265] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [424.850348] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [424.850505] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [424.850567] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [424.850697] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [424.851660] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [424.851793] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [424.853803] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [424.853925] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (465 ms remaining) <7> [425.326972] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [425.367060] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [425.367777] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [425.368336] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [425.404055] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [425.404541] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [425.404977] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [425.405407] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [425.582399] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [425.583172] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [425.583753] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [425.586233] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [425.587941] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [425.588965] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [425.590366] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [425.591949] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [425.593199] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [425.593635] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [425.595301] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [425.595739] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [425.596636] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [425.597295] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [425.597763] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [425.598306] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [425.631057] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [425.632850] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [425.633307] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <7> [428.151100] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off <7> [428.151672] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [429.899366] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [429.900051] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [429.900697] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [429.959069] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

5.48 seconds

Hostname

shard-lnl-4

Igt-Version

IGT-Version: 2.4-g5f68f2d83 (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5062-dee34cfbffbfe2196-debug+ x86_64)

Out

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

Err

Starting dynamic subtest: B-eDP1
[336.708815] (kms_flip:6506) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[336.708914] (kms_flip:6506) CRITICAL: Failed assertion: end - start < 500
[336.708974] (kms_flip:6506) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
[334.691096] (kms_flip:6506) DEBUG: Vblank took 58us
[334.707708] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.183502
last_received_ts = 336.182831
last_seq = 281
current_ts = 336.200165
current_received_ts = 336.199493
current_seq = 282
count = 133
seq_step = 1
[334.707769] (kms_flip:6506) DEBUG: Vblank took 57us
[334.724335] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.200165
last_received_ts = 336.199493
last_seq = 282
current_ts = 336.216827
current_received_ts = 336.216125
current_seq = 283
count = 134
seq_step = 1
[334.724392] (kms_flip:6506) DEBUG: Vblank took 54us
[334.741026] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.216827
last_received_ts = 336.216125
last_seq = 283
current_ts = 336.233490
current_received_ts = 336.232819
current_seq = 284
count = 135
seq_step = 1
[334.741083] (kms_flip:6506) DEBUG: Vblank took 55us
[334.757699] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.233490
last_received_ts = 336.232819
last_seq = 284
current_ts = 336.250153
current_received_ts = 336.249481
current_seq = 285
count = 136
seq_step = 1
[334.757787] (kms_flip:6506) DEBUG: Vblank took 84us
[334.774341] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.250153
last_received_ts = 336.249481
last_seq = 285
current_ts = 336.266815
current_received_ts = 336.266113
current_seq = 286
count = 137
seq_step = 1
[334.774407] (kms_flip:6506) DEBUG: Vblank took 62us
[334.790925] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.266815
last_received_ts = 336.266113
last_seq = 286
current_ts = 336.283478
current_received_ts = 336.282715
current_seq = 287
count = 138
seq_step = 1
[334.790976] (kms_flip:6506) DEBUG: Vblank took 46us
[334.807570] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.283478
last_received_ts = 336.282715
last_seq = 287
current_ts = 336.300140
current_received_ts = 336.299347
current_seq = 288
count = 139
seq_step = 1
[334.807628] (kms_flip:6506) DEBUG: Vblank took 56us
[334.824335] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.300140
last_received_ts = 336.299347
last_seq = 288
current_ts = 336.316803
current_received_ts = 336.316101
current_seq = 289
count = 140
seq_step = 1
[334.824393] (kms_flip:6506) DEBUG: Vblank took 55us
[334.841025] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.316803
last_received_ts = 336.316101
last_seq = 289
current_ts = 336.333466
current_received_ts = 336.332794
current_seq = 290
count = 141
seq_step = 1
[334.841089] (kms_flip:6506) DEBUG: Vblank took 60us
[334.857669] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.333466
last_received_ts = 336.332794
last_seq = 290
current_ts = 336.350128
current_received_ts = 336.349457
current_seq = 291
count = 142
seq_step = 1
[334.857734] (kms_flip:6506) DEBUG: Vblank took 60us
[334.874336] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.350128
last_received_ts = 336.349457
last_seq = 291
current_ts = 336.366791
current_received_ts = 336.366119
current_seq = 292
count = 143
seq_step = 1
[334.874400] (kms_flip:6506) DEBUG: Vblank took 61us
[334.891005] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.366791
last_received_ts = 336.366119
last_seq = 292
current_ts = 336.383453
current_received_ts = 336.382782
current_seq = 293
count = 144
seq_step = 1
[334.891068] (kms_flip:6506) DEBUG: Vblank took 59us
[334.907676] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.383453
last_received_ts = 336.382782
last_seq = 293
current_ts = 336.400116
current_received_ts = 336.399445
current_seq = 294
count = 145
seq_step = 1
[334.907737] (kms_flip:6506) DEBUG: Vblank took 57us
[334.924337] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.400116
last_received_ts = 336.399445
last_seq = 294
current_ts = 336.416779
current_received_ts = 336.416107
current_seq = 295
count = 146
seq_step = 1
[334.924409] (kms_flip:6506) DEBUG: Vblank took 67us
[334.940996] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.416779
last_received_ts = 336.416107
last_seq = 295
current_ts = 336.433441
current_received_ts = 336.432770
current_seq = 296
count = 147
seq_step = 1
[334.941050] (kms_flip:6506) DEBUG: Vblank took 51us
[334.957674] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.433441
last_received_ts = 336.432770
last_seq = 296
current_ts = 336.450104
current_received_ts = 336.449432
current_seq = 297
count = 148
seq_step = 1
[334.957734] (kms_flip:6506) DEBUG: Vblank took 56us
[334.974233] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.450104
last_received_ts = 336.449432
last_seq = 297
current_ts = 336.466766
current_received_ts = 336.465973
current_seq = 298
count = 149
seq_step = 1
[334.974364] (kms_flip:6506) DEBUG: Vblank took 84us
[334.990888] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.466766
last_received_ts = 336.465973
last_seq = 298
current_ts = 336.483429
current_received_ts = 336.482635
current_seq = 299
count = 150
seq_step = 1
[334.990950] (kms_flip:6506) DEBUG: Vblank took 56us
[335.007534] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.483429
last_received_ts = 336.482635
last_seq = 299
current_ts = 336.500092
current_received_ts = 336.499298
current_seq = 300
count = 151
seq_step = 1
[335.007601] (kms_flip:6506) DEBUG: Vblank took 62us
[335.024333] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.500092
last_received_ts = 336.499298
last_seq = 300
current_ts = 336.516754
current_received_ts = 336.516083
current_seq = 301
count = 152
seq_step = 1
[335.024403] (kms_flip:6506) DEBUG: Vblank took 65us
[335.040996] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.516754
last_received_ts = 336.516083
last_seq = 301
current_ts = 336.533417
current_received_ts = 336.532745
current_seq = 302
count = 153
seq_step = 1
[335.041064] (kms_flip:6506) DEBUG: Vblank took 65us
[335.057679] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.533417
last_received_ts = 336.532745
last_seq = 302
current_ts = 336.550079
current_received_ts = 336.549438
current_seq = 303
count = 154
seq_step = 1
[335.057739] (kms_flip:6506) DEBUG: Vblank took 55us
[335.074328] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.550079
last_received_ts = 336.549438
last_seq = 303
current_ts = 336.566742
current_received_ts = 336.566071
current_seq = 304
count = 155
seq_step = 1
[335.074392] (kms_flip:6506) DEBUG: Vblank took 59us
[335.090970] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.566742
last_received_ts = 336.566071
last_seq = 304
current_ts = 336.583405
current_received_ts = 336.582703
current_seq = 305
count = 156
seq_step = 1
[335.091034] (kms_flip:6506) DEBUG: Vblank took 59us
[335.107563] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.583405
last_received_ts = 336.582703
last_seq = 305
current_ts = 336.600067
current_received_ts = 336.599304
current_seq = 306
count = 157
seq_step = 1
[335.107617] (kms_flip:6506) DEBUG: Vblank took 51us
[335.124316] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.600067
last_received_ts = 336.599304
last_seq = 306
current_ts = 336.616730
current_received_ts = 336.616058
current_seq = 307
count = 158
seq_step = 1
[335.124379] (kms_flip:6506) DEBUG: Vblank took 60us
[335.140996] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.616730
last_received_ts = 336.616058
last_seq = 307
current_ts = 336.633392
current_received_ts = 336.632721
current_seq = 308
count = 159
seq_step = 1
[335.141057] (kms_flip:6506) DEBUG: Vblank took 57us
[335.157628] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.633392
last_received_ts = 336.632721
last_seq = 308
current_ts = 336.650055
current_received_ts = 336.649353
current_seq = 309
count = 160
seq_step = 1
[335.157685] (kms_flip:6506) DEBUG: Vblank took 54us
[335.174316] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.650055
last_received_ts = 336.649353
last_seq = 309
current_ts = 336.666687
current_received_ts = 336.666046
current_seq = 310
count = 161
seq_step = 1
[335.174381] (kms_flip:6506) DEBUG: Vblank took 61us
[335.190867] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.666687
last_received_ts = 336.666046
last_seq = 310
current_ts = 336.683350
current_received_ts = 336.682587
current_seq = 311
count = 162
seq_step = 1
[335.190923] (kms_flip:6506) DEBUG: Vblank took 52us
[335.207620] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.683350
last_received_ts = 336.682587
last_seq = 311
current_ts = 336.700043
current_received_ts = 336.699341
current_seq = 312
count = 163
seq_step = 1
[335.207677] (kms_flip:6506) DEBUG: Vblank took 53us
[335.224296] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.700043
last_received_ts = 336.699341
last_seq = 312
current_ts = 336.716675
current_received_ts = 336.716003
current_seq = 313
count = 164
seq_step = 1
[335.224342] (kms_flip:6506) DEBUG: Vblank took 41us
[335.240985] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.716675
last_received_ts = 336.716003
last_seq = 313
current_ts = 336.733337
current_received_ts = 336.732697
current_seq = 314
count = 165
seq_step = 1
[335.241067] (kms_flip:6506) DEBUG: Vblank took 77us
[335.257623] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.733337
last_received_ts = 336.732697
last_seq = 314
current_ts = 336.750000
current_received_ts = 336.749329
current_seq = 315
count = 166
seq_step = 1
[335.257688] (kms_flip:6506) DEBUG: Vblank took 60us
[335.274323] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.750000
last_received_ts = 336.749329
last_seq = 315
current_ts = 336.766663
current_received_ts = 336.766052
current_seq = 316
count = 167
seq_step = 1
[335.274390] (kms_flip:6506) DEBUG: Vblank took 62us
[335.290955] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.766663
last_received_ts = 336.766052
last_seq = 316
current_ts = 336.783325
current_received_ts = 336.782684
current_seq = 317
count = 168
seq_step = 1
[335.291016] (kms_flip:6506) DEBUG: Vblank took 58us
[335.307619] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.783325
last_received_ts = 336.782684
last_seq = 317
current_ts = 336.799988
current_received_ts = 336.799347
current_seq = 318
count = 169
seq_step = 1
[335.307675] (kms_flip:6506) DEBUG: Vblank took 51us
[335.324268] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.799988
last_received_ts = 336.799347
last_seq = 318
current_ts = 336.816650
current_received_ts = 336.815979
current_seq = 319
count = 170
seq_step = 1
[335.324358] (kms_flip:6506) DEBUG: Vblank took 86us
[335.340952] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.816650
last_received_ts = 336.815979
last_seq = 319
current_ts = 336.833313
current_received_ts = 336.832672
current_seq = 320
count = 171
seq_step = 1
[335.341038] (kms_flip:6506) DEBUG: Vblank took 83us
[335.357605] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.833313
last_received_ts = 336.832672
last_seq = 320
current_ts = 336.849976
current_received_ts = 336.849304
current_seq = 321
count = 172
seq_step = 1
[335.357668] (kms_flip:6506) DEBUG: Vblank took 60us
[335.374155] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.849976
last_received_ts = 336.849304
last_seq = 321
current_ts = 336.866638
current_received_ts = 336.865845
current_seq = 322
count = 173
seq_step = 1
[335.374225] (kms_flip:6506) DEBUG: Vblank took 65us
[335.390958] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.866638
last_received_ts = 336.865845
last_seq = 322
current_ts = 336.883301
current_received_ts = 336.882660
current_seq = 323
count = 174
seq_step = 1
[335.391031] (kms_flip:6506) DEBUG: Vblank took 68us
[335.407595] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.883301
last_received_ts = 336.882660
last_seq = 323
current_ts = 336.899963
current_received_ts = 336.899292
current_seq = 324
count = 175
seq_step = 1
[335.407667] (kms_flip:6506) DEBUG: Vblank took 68us
[335.424245] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.899963
last_received_ts = 336.899292
last_seq = 324
current_ts = 336.916626
current_received_ts = 336.915955
current_seq = 325
count = 176
seq_step = 1
[335.424328] (kms_flip:6506) DEBUG: Vblank took 79us
[335.440898] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.916626
last_received_ts = 336.915955
last_seq = 325
current_ts = 336.933289
current_received_ts = 336.932587
current_seq = 326
count = 177
seq_step = 1
[335.440958] (kms_flip:6506) DEBUG: Vblank took 56us
[335.457527] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.933289
last_received_ts = 336.932587
last_seq = 326
current_ts = 336.949951
current_received_ts = 336.949188
current_seq = 327
count = 178
seq_step = 1
[335.457713] (kms_flip:6506) DEBUG: Vblank took 169us
[335.474160] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.949951
last_received_ts = 336.949188
last_seq = 327
current_ts = 336.966614
current_received_ts = 336.965851
current_seq = 328
count = 179
seq_step = 1
[335.474251] (kms_flip:6506) DEBUG: Vblank took 81us
[335.490915] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.966614
last_received_ts = 336.965851
last_seq = 328
current_ts = 336.983276
current_received_ts = 336.982574
current_seq = 329
count = 180
seq_step = 1
[335.491043] (kms_flip:6506) DEBUG: Vblank took 100us
[335.507550] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.983276
last_received_ts = 336.982574
last_seq = 329
current_ts = 336.999939
current_received_ts = 336.999207
current_seq = 330
count = 181
seq_step = 1
[335.507685] (kms_flip:6506) DEBUG: Vblank took 108us
[335.524216] (kms_flip:6506) DEBUG: name = flip
last_ts = 336.999939
last_received_ts = 336.999207
last_seq = 330
current_ts = 337.016602
current_received_ts = 337.015900
current_seq = 331
count = 182
seq_step = 1
[335.524290] (kms_flip:6506) DEBUG: Vblank took 65us
[335.540763] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.016602
last_received_ts = 337.015900
last_seq = 331
current_ts = 337.033264
current_received_ts = 337.032440
current_seq = 332
count = 183
seq_step = 1
[335.540821] (kms_flip:6506) DEBUG: Vblank took 54us
[335.557412] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.033264
last_received_ts = 337.032440
last_seq = 332
current_ts = 337.049927
current_received_ts = 337.049103
current_seq = 333
count = 184
seq_step = 1
[335.557469] (kms_flip:6506) DEBUG: Vblank took 48us
[335.574109] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.049927
last_received_ts = 337.049103
last_seq = 333
current_ts = 337.066589
current_received_ts = 337.065796
current_seq = 334
count = 185
seq_step = 1
[335.574177] (kms_flip:6506) DEBUG: Vblank took 61us
[335.590764] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.066589
last_received_ts = 337.065796
last_seq = 334
current_ts = 337.083252
current_received_ts = 337.082428
current_seq = 335
count = 186
seq_step = 1
[335.590828] (kms_flip:6506) DEBUG: Vblank took 58us
[335.607436] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.083252
last_received_ts = 337.082428
last_seq = 335
current_ts = 337.099915
current_received_ts = 337.099121
current_seq = 336
count = 187
seq_step = 1
[335.607475] (kms_flip:6506) DEBUG: Vblank took 34us
[335.624246] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.099915
last_received_ts = 337.099121
last_seq = 336
current_ts = 337.116577
current_received_ts = 337.115906
current_seq = 337
count = 188
seq_step = 1
[335.624350] (kms_flip:6506) DEBUG: Vblank took 93us
[335.640976] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.116577
last_received_ts = 337.115906
last_seq = 337
current_ts = 337.133240
current_received_ts = 337.132629
current_seq = 338
count = 189
seq_step = 1
[335.641056] (kms_flip:6506) DEBUG: Vblank took 73us
[335.657575] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.133240
last_received_ts = 337.132629
last_seq = 338
current_ts = 337.149902
current_received_ts = 337.149231
current_seq = 339
count = 190
seq_step = 1
[335.657646] (kms_flip:6506) DEBUG: Vblank took 65us
[335.674248] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.149902
last_received_ts = 337.149231
last_seq = 339
current_ts = 337.166534
current_received_ts = 337.165924
current_seq = 340
count = 191
seq_step = 1
[335.674318] (kms_flip:6506) DEBUG: Vblank took 65us
[335.690984] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.166534
last_received_ts = 337.165924
last_seq = 340
current_ts = 337.183197
current_received_ts = 337.182648
current_seq = 341
count = 192
seq_step = 1
[335.691052] (kms_flip:6506) DEBUG: Vblank took 63us
[335.707696] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.183197
last_received_ts = 337.182648
last_seq = 341
current_ts = 337.199860
current_received_ts = 337.199341
current_seq = 342
count = 193
seq_step = 1
[335.707757] (kms_flip:6506) DEBUG: Vblank took 56us
[335.724245] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.199860
last_received_ts = 337.199341
last_seq = 342
current_ts = 337.216522
current_received_ts = 337.215912
current_seq = 343
count = 194
seq_step = 1
[335.724317] (kms_flip:6506) DEBUG: Vblank took 67us
[335.740855] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.216522
last_received_ts = 337.215912
last_seq = 343
current_ts = 337.233215
current_received_ts = 337.232513
current_seq = 344
count = 195
seq_step = 1
[335.740914] (kms_flip:6506) DEBUG: Vblank took 54us
[335.757506] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.233215
last_received_ts = 337.232513
last_seq = 344
current_ts = 337.249878
current_received_ts = 337.249146
current_seq = 345
count = 196
seq_step = 1
[335.757553] (kms_flip:6506) DEBUG: Vblank took 42us
[335.774235] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.249878
last_received_ts = 337.249146
last_seq = 345
current_ts = 337.266510
current_received_ts = 337.265869
current_seq = 346
count = 197
seq_step = 1
[335.774301] (kms_flip:6506) DEBUG: Vblank took 61us
[335.790759] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.266510
last_received_ts = 337.265869
last_seq = 346
current_ts = 337.283203
current_received_ts = 337.282410
current_seq = 347
count = 198
seq_step = 1
[335.790820] (kms_flip:6506) DEBUG: Vblank took 56us
[335.807414] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.283203
last_received_ts = 337.282410
last_seq = 347
current_ts = 337.299835
current_received_ts = 337.299072
current_seq = 348
count = 199
seq_step = 1
[335.807475] (kms_flip:6506) DEBUG: Vblank took 56us
[335.824156] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.299835
last_received_ts = 337.299072
last_seq = 348
current_ts = 337.316498
current_received_ts = 337.315765
current_seq = 349
count = 200
seq_step = 1
[335.824220] (kms_flip:6506) DEBUG: Vblank took 59us
[335.840800] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.316498
last_received_ts = 337.315765
last_seq = 349
current_ts = 337.333160
current_received_ts = 337.332428
current_seq = 350
count = 201
seq_step = 1
[335.840864] (kms_flip:6506) DEBUG: Vblank took 58us
[335.857629] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.333160
last_received_ts = 337.332428
last_seq = 350
current_ts = 337.349823
current_received_ts = 337.349274
current_seq = 351
count = 202
seq_step = 1
[335.857685] (kms_flip:6506) DEBUG: Vblank took 52us
[335.874130] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.349823
last_received_ts = 337.349274
last_seq = 351
current_ts = 337.366486
current_received_ts = 337.365753
current_seq = 352
count = 203
seq_step = 1
[335.874195] (kms_flip:6506) DEBUG: Vblank took 59us
[335.890765] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.366486
last_received_ts = 337.365753
last_seq = 352
current_ts = 337.383148
current_received_ts = 337.382385
current_seq = 353
count = 204
seq_step = 1
[335.890856] (kms_flip:6506) DEBUG: Vblank took 78us
[335.907442] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.383148
last_received_ts = 337.382385
last_seq = 353
current_ts = 337.399811
current_received_ts = 337.399078
current_seq = 354
count = 205
seq_step = 1
[335.907516] (kms_flip:6506) DEBUG: Vblank took 66us
[335.924102] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.399811
last_received_ts = 337.399078
last_seq = 354
current_ts = 337.416473
current_received_ts = 337.415741
current_seq = 355
count = 206
seq_step = 1
[335.924170] (kms_flip:6506) DEBUG: Vblank took 63us
[335.940754] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.416473
last_received_ts = 337.415741
last_seq = 355
current_ts = 337.433136
current_received_ts = 337.432373
current_seq = 356
count = 207
seq_step = 1
[335.940831] (kms_flip:6506) DEBUG: Vblank took 68us
[335.957437] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.433136
last_received_ts = 337.432373
last_seq = 356
current_ts = 337.449799
current_received_ts = 337.449066
current_seq = 357
count = 208
seq_step = 1
[335.957510] (kms_flip:6506) DEBUG: Vblank took 67us
[335.974042] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.449799
last_received_ts = 337.449066
last_seq = 357
current_ts = 337.466461
current_received_ts = 337.465668
current_seq = 358
count = 209
seq_step = 1
[335.974123] (kms_flip:6506) DEBUG: Vblank took 73us
[335.990699] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.466461
last_received_ts = 337.465668
last_seq = 358
current_ts = 337.483124
current_received_ts = 337.482330
current_seq = 359
count = 210
seq_step = 1
[335.990766] (kms_flip:6506) DEBUG: Vblank took 62us
[336.007430] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.483124
last_received_ts = 337.482330
last_seq = 359
current_ts = 337.499786
current_received_ts = 337.499054
current_seq = 360
count = 211
seq_step = 1
[336.007499] (kms_flip:6506) DEBUG: Vblank took 63us
[336.024051] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.499786
last_received_ts = 337.499054
last_seq = 360
current_ts = 337.516449
current_received_ts = 337.515656
current_seq = 361
count = 212
seq_step = 1
[336.024117] (kms_flip:6506) DEBUG: Vblank took 61us
[336.040803] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.516449
last_received_ts = 337.515656
last_seq = 361
current_ts = 337.533112
current_received_ts = 337.532410
current_seq = 362
count = 213
seq_step = 1
[336.040869] (kms_flip:6506) DEBUG: Vblank took 60us
[336.057415] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.533112
last_received_ts = 337.532410
last_seq = 362
current_ts = 337.549774
current_received_ts = 337.549011
current_seq = 363
count = 214
seq_step = 1
[336.057482] (kms_flip:6506) DEBUG: Vblank took 60us
[336.074082] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.549774
last_received_ts = 337.549011
last_seq = 363
current_ts = 337.566437
current_received_ts = 337.565674
current_seq = 364
count = 215
seq_step = 1
[336.074150] (kms_flip:6506) DEBUG: Vblank took 61us
[336.090725] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.566437
last_received_ts = 337.565674
last_seq = 364
current_ts = 337.583099
current_received_ts = 337.582336
current_seq = 365
count = 216
seq_step = 1
[336.090792] (kms_flip:6506) DEBUG: Vblank took 62us
[336.107408] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.583099
last_received_ts = 337.582336
last_seq = 365
current_ts = 337.599762
current_received_ts = 337.598999
current_seq = 366
count = 217
seq_step = 1
[336.107481] (kms_flip:6506) DEBUG: Vblank took 68us
[336.124070] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.599762
last_received_ts = 337.598999
last_seq = 366
current_ts = 337.616425
current_received_ts = 337.615662
current_seq = 367
count = 218
seq_step = 1
[336.124142] (kms_flip:6506) DEBUG: Vblank took 66us
[336.140703] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.616425
last_received_ts = 337.615662
last_seq = 367
current_ts = 337.633087
current_received_ts = 337.632294
current_seq = 368
count = 219
seq_step = 1
[336.140778] (kms_flip:6506) DEBUG: Vblank took 67us
[336.157392] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.633087
last_received_ts = 337.632294
last_seq = 368
current_ts = 337.649750
current_received_ts = 337.648987
current_seq = 369
count = 220
seq_step = 1
[336.157474] (kms_flip:6506) DEBUG: Vblank took 76us
[336.174134] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.649750
last_received_ts = 337.648987
last_seq = 369
current_ts = 337.666412
current_received_ts = 337.665710
current_seq = 370
count = 221
seq_step = 1
[336.174207] (kms_flip:6506) DEBUG: Vblank took 65us
[336.190678] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.666412
last_received_ts = 337.665710
last_seq = 370
current_ts = 337.683075
current_received_ts = 337.682251
current_seq = 371
count = 222
seq_step = 1
[336.190750] (kms_flip:6506) DEBUG: Vblank took 65us
[336.207378] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.683075
last_received_ts = 337.682251
last_seq = 371
current_ts = 337.699738
current_received_ts = 337.698975
current_seq = 372
count = 223
seq_step = 1
[336.207474] (kms_flip:6506) DEBUG: Vblank took 92us
[336.224030] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.699738
last_received_ts = 337.698975
last_seq = 372
current_ts = 337.716400
current_received_ts = 337.715607
current_seq = 373
count = 224
seq_step = 1
[336.224102] (kms_flip:6506) DEBUG: Vblank took 66us
[336.240810] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.716400
last_received_ts = 337.715607
last_seq = 373
current_ts = 337.733063
current_received_ts = 337.732391
current_seq = 374
count = 225
seq_step = 1
[336.240881] (kms_flip:6506) DEBUG: Vblank took 66us
[336.257352] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.733063
last_received_ts = 337.732391
last_seq = 374
current_ts = 337.749695
current_received_ts = 337.748932
current_seq = 375
count = 226
seq_step = 1
[336.257439] (kms_flip:6506) DEBUG: Vblank took 80us
[336.274032] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.749695
last_received_ts = 337.748932
last_seq = 375
current_ts = 337.766388
current_received_ts = 337.765594
current_seq = 376
count = 227
seq_step = 1
[336.274104] (kms_flip:6506) DEBUG: Vblank took 67us
[336.290695] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.766388
last_received_ts = 337.765594
last_seq = 376
current_ts = 337.783020
current_received_ts = 337.782257
current_seq = 377
count = 228
seq_step = 1
[336.290767] (kms_flip:6506) DEBUG: Vblank took 66us
[336.307366] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.783020
last_received_ts = 337.782257
last_seq = 377
current_ts = 337.799713
current_received_ts = 337.798950
current_seq = 378
count = 229
seq_step = 1
[336.307494] (kms_flip:6506) DEBUG: Vblank took 121us
[336.324032] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.799713
last_received_ts = 337.798950
last_seq = 378
current_ts = 337.816345
current_received_ts = 337.815613
current_seq = 379
count = 230
seq_step = 1
[336.324105] (kms_flip:6506) DEBUG: Vblank took 66us
[336.340675] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.816345
last_received_ts = 337.815613
last_seq = 379
current_ts = 337.833008
current_received_ts = 337.832245
current_seq = 380
count = 231
seq_step = 1
[336.340748] (kms_flip:6506) DEBUG: Vblank took 66us
[336.357362] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.833008
last_received_ts = 337.832245
last_seq = 380
current_ts = 337.849670
current_received_ts = 337.848938
current_seq = 381
count = 232
seq_step = 1
[336.357452] (kms_flip:6506) DEBUG: Vblank took 84us
[336.374020] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.849670
last_received_ts = 337.848938
last_seq = 381
current_ts = 337.866333
current_received_ts = 337.865570
current_seq = 382
count = 233
seq_step = 1
[336.374094] (kms_flip:6506) DEBUG: Vblank took 68us
[336.390758] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.866333
last_received_ts = 337.865570
last_seq = 382
current_ts = 337.882996
current_received_ts = 337.882294
current_seq = 383
count = 234
seq_step = 1
[336.390907] (kms_flip:6506) DEBUG: Vblank took 123us
[336.407338] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.882996
last_received_ts = 337.882294
last_seq = 383
current_ts = 337.899658
current_received_ts = 337.898895
current_seq = 384
count = 235
seq_step = 1
[336.407411] (kms_flip:6506) DEBUG: Vblank took 67us
[336.424116] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.899658
last_received_ts = 337.898895
last_seq = 384
current_ts = 337.916321
current_received_ts = 337.915680
current_seq = 385
count = 236
seq_step = 1
[336.424181] (kms_flip:6506) DEBUG: Vblank took 61us
[336.440628] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.916321
last_received_ts = 337.915680
last_seq = 385
current_ts = 337.932983
current_received_ts = 337.932190
current_seq = 386
count = 237
seq_step = 1
[336.440683] (kms_flip:6506) DEBUG: Vblank took 51us
[336.457473] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.932983
last_received_ts = 337.932190
last_seq = 386
current_ts = 337.949646
current_received_ts = 337.949036
current_seq = 387
count = 238
seq_step = 1
[336.457519] (kms_flip:6506) DEBUG: Vblank took 43us
[336.474089] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.949646
last_received_ts = 337.949036
last_seq = 387
current_ts = 337.966309
current_received_ts = 337.965637
current_seq = 388
count = 239
seq_step = 1
[336.474143] (kms_flip:6506) DEBUG: Vblank took 52us
[336.490667] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.966309
last_received_ts = 337.965637
last_seq = 388
current_ts = 337.982971
current_received_ts = 337.982208
current_seq = 389
count = 240
seq_step = 1
[336.490718] (kms_flip:6506) DEBUG: Vblank took 48us
[336.507408] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.982971
last_received_ts = 337.982208
last_seq = 389
current_ts = 337.999634
current_received_ts = 337.998962
current_seq = 390
count = 241
seq_step = 1
[336.507469] (kms_flip:6506) DEBUG: Vblank took 57us
[336.524056] (kms_flip:6506) DEBUG: name = flip
last_ts = 337.999634
last_received_ts = 337.998962
last_seq = 390
current_ts = 338.016296
current_received_ts = 338.015594
current_seq = 391
count = 242
seq_step = 1
[336.524109] (kms_flip:6506) DEBUG: Vblank took 49us
[336.540720] (kms_flip:6506) DEBUG: name = flip
last_ts = 338.016296
last_received_ts = 338.015594
last_seq = 391
current_ts = 338.032959
current_received_ts = 338.032257
current_seq = 392
count = 243
seq_step = 1
[336.540772] (kms_flip:6506) DEBUG: Vblank took 49us
[336.557406] (kms_flip:6506) DEBUG: name = flip
last_ts = 338.032959
last_received_ts = 338.032257
last_seq = 392
current_ts = 338.049622
current_received_ts = 338.048950
current_seq = 393
count = 244
seq_step = 1
[336.557486] (kms_flip:6506) DEBUG: Vblank took 76us
[336.574070] (kms_flip:6506) DEBUG: name = flip
last_ts = 338.049622
last_received_ts = 338.048950
last_seq = 393
current_ts = 338.066284
current_received_ts = 338.065613
current_seq = 394
count = 245
seq_step = 1
[336.574123] (kms_flip:6506) DEBUG: Vblank took 50us
[336.590726] (kms_flip:6506) DEBUG: name = flip
last_ts = 338.066284
last_received_ts = 338.065613
last_seq = 394
current_ts = 338.082947
current_received_ts = 338.082275
current_seq = 395
count = 246
seq_step = 1
[336.590781] (kms_flip:6506) DEBUG: Vblank took 52us
[336.607390] (kms_flip:6506) DEBUG: name = flip
last_ts = 338.082947
last_received_ts = 338.082275
last_seq = 395
current_ts = 338.099609
current_received_ts = 338.098938
current_seq = 396
count = 247
seq_step = 1
[336.607448] (kms_flip:6506) DEBUG: Vblank took 55us
[336.624071] (kms_flip:6506) DEBUG: name = flip
last_ts = 338.099609
last_received_ts = 338.098938
last_seq = 396
current_ts = 338.116272
current_received_ts = 338.115601
current_seq = 397
count = 248
seq_step = 1
[336.624134] (kms_flip:6506) DEBUG: Vblank took 59us
[336.640693] (kms_flip:6506) DEBUG: name = flip
last_ts = 338.116272
last_received_ts = 338.115601
last_seq = 397
current_ts = 338.132935
current_received_ts = 338.132233
current_seq = 398
count = 249
seq_step = 1
[336.640743] (kms_flip:6506) DEBUG: Vblank took 47us
[336.657327] (kms_flip:6506) DEBUG: name = flip
last_ts = 338.132935
last_received_ts = 338.132233
last_seq = 398
current_ts = 338.149597
current_received_ts = 338.148865
current_seq = 399
count = 250
seq_step = 1
[336.657369] (kms_flip:6506) DEBUG: Vblank took 40us
[336.674018] (kms_flip:6506) DEBUG: name = flip
last_ts = 338.149597
last_received_ts = 338.148865
last_seq = 399
current_ts = 338.166260
current_received_ts = 338.165558
current_seq = 400
count = 251
seq_step = 1
[336.674063] (kms_flip:6506) DEBUG: Vblank took 43us
[336.690701] (kms_flip:6506) DEBUG: name = flip
last_ts = 338.166260
last_received_ts = 338.165558
last_seq = 400
current_ts = 338.182922
current_received_ts = 338.182220
current_seq = 401
count = 252
seq_step = 1
[336.690759] (kms_flip:6506) DEBUG: Vblank took 56us
[336.707373] (kms_flip:6506) DEBUG: name = flip
last_ts = 338.182922
last_received_ts = 338.182220
last_seq = 401
current_ts = 338.199585
current_received_ts = 338.198883
current_seq = 402
count = 253
seq_step = 1
[336.708810] (kms_flip:6506) DEBUG: Vblank took 1434us
[336.708815] (kms_flip:6506) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[336.708914] (kms_flip:6506) CRITICAL: Failed assertion: end - start < 500
[336.708974] (kms_flip:6506) CRITICAL: Last errno: 4, Interrupted system call
[336.723654] (kms_flip:6506) igt_core-INFO: Stack trace:
[336.737727] (kms_flip:6506) igt_core-INFO:   #0 ../lib/igt_core.c:2074 __igt_fail_assert()
[336.739075] (kms_flip:6506) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[336.739146] (kms_flip:6506) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[336.739184] (kms_flip:6506) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
[336.739234] (kms_flip:6506) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[336.743772] (kms_flip:6506) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[336.744632] (kms_flip:6506) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[336.744858] (kms_flip:6506) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (5.481s)

Dmesg

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [424.842995] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [424.844300] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97

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

<7> [424.844466] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

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

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

<7> [424.844757] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [424.844861] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa

<7> [424.844959] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [424.845040] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0

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

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

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

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

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

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

<7> [424.845605] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no

<7> [424.845704] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [425.586233] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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