igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a3 on shard-dg2@CI_DRM

Detail	Value
Duration	6.30 seconds
Hostname	shard-dg2-5
Igt-Version	IGT-Version: 2.3-gf38f4d8e9 (x86_64) (Linux: 6.19.0-rc1-CI_DRM_17720-g7fae53958ca7+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A3 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1889 run_test() #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045() #4 ../tests/kms_flip.c:2045 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-HDMI-A3: FAIL (6.296s)
Err	Starting dynamic subtest: B-HDMI-A3 (kms_flip:2135) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2135) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-HDMI-A3 failed. ** DEBUG (kms_flip:2135) DEBUG: name = flip last_ts = 127.054169 last_received_ts = 127.053940 last_seq = 257 current_ts = 127.070839 current_received_ts = 127.070419 current_seq = 258 count = 230 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.070839 last_received_ts = 127.070419 last_seq = 258 current_ts = 127.087494 current_received_ts = 127.087181 current_seq = 259 count = 231 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.087494 last_received_ts = 127.087181 last_seq = 259 current_ts = 127.104172 current_received_ts = 127.103928 current_seq = 260 count = 232 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 103us (kms_flip:2135) DEBUG: name = flip last_ts = 127.104172 last_received_ts = 127.103928 last_seq = 260 current_ts = 127.120842 current_received_ts = 127.120468 current_seq = 261 count = 233 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.120842 last_received_ts = 127.120468 last_seq = 261 current_ts = 127.137505 current_received_ts = 127.137314 current_seq = 262 count = 234 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.137505 last_received_ts = 127.137314 last_seq = 262 current_ts = 127.154167 current_received_ts = 127.153854 current_seq = 263 count = 235 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.154167 last_received_ts = 127.153854 last_seq = 263 current_ts = 127.170837 current_received_ts = 127.170479 current_seq = 264 count = 236 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 61us (kms_flip:2135) DEBUG: name = flip last_ts = 127.170837 last_received_ts = 127.170479 last_seq = 264 current_ts = 127.187508 current_received_ts = 127.187302 current_seq = 265 count = 237 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.187508 last_received_ts = 127.187302 last_seq = 265 current_ts = 127.204170 current_received_ts = 127.203926 current_seq = 266 count = 238 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 91us (kms_flip:2135) DEBUG: name = flip last_ts = 127.204170 last_received_ts = 127.203926 last_seq = 266 current_ts = 127.220848 current_received_ts = 127.220467 current_seq = 267 count = 239 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.220848 last_received_ts = 127.220467 last_seq = 267 current_ts = 127.237511 current_received_ts = 127.237206 current_seq = 268 count = 240 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.237511 last_received_ts = 127.237206 last_seq = 268 current_ts = 127.254173 current_received_ts = 127.253868 current_seq = 269 count = 241 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.254173 last_received_ts = 127.253868 last_seq = 269 current_ts = 127.270851 current_received_ts = 127.270485 current_seq = 270 count = 242 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.270851 last_received_ts = 127.270485 last_seq = 270 current_ts = 127.287514 current_received_ts = 127.287155 current_seq = 271 count = 243 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 53us (kms_flip:2135) DEBUG: name = flip last_ts = 127.287514 last_received_ts = 127.287155 last_seq = 271 current_ts = 127.304176 current_received_ts = 127.303864 current_seq = 272 count = 244 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.304176 last_received_ts = 127.303864 last_seq = 272 current_ts = 127.320839 current_received_ts = 127.320480 current_seq = 273 count = 245 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 127.320839 last_received_ts = 127.320480 last_seq = 273 current_ts = 127.337517 current_received_ts = 127.337181 current_seq = 274 count = 246 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.337517 last_received_ts = 127.337181 last_seq = 274 current_ts = 127.354179 current_received_ts = 127.353859 current_seq = 275 count = 247 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 58us (kms_flip:2135) DEBUG: name = flip last_ts = 127.354179 last_received_ts = 127.353859 last_seq = 275 current_ts = 127.370842 current_received_ts = 127.370590 current_seq = 276 count = 248 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.370842 last_received_ts = 127.370590 last_seq = 276 current_ts = 127.387520 current_received_ts = 127.387306 current_seq = 277 count = 249 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 58us (kms_flip:2135) DEBUG: name = flip last_ts = 127.387520 last_received_ts = 127.387306 last_seq = 277 current_ts = 127.404190 current_received_ts = 127.403839 current_seq = 278 count = 250 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 58us (kms_flip:2135) DEBUG: name = flip last_ts = 127.404190 last_received_ts = 127.403839 last_seq = 278 current_ts = 127.420853 current_received_ts = 127.420486 current_seq = 279 count = 251 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 58us (kms_flip:2135) DEBUG: name = flip last_ts = 127.420853 last_received_ts = 127.420486 last_seq = 279 current_ts = 127.437531 current_received_ts = 127.437164 current_seq = 280 count = 252 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 127.437531 last_received_ts = 127.437164 last_seq = 280 current_ts = 127.454193 current_received_ts = 127.453842 current_seq = 281 count = 253 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 127.454193 last_received_ts = 127.453842 last_seq = 281 current_ts = 127.470863 current_received_ts = 127.470474 current_seq = 282 count = 254 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.470863 last_received_ts = 127.470474 last_seq = 282 current_ts = 127.487534 current_received_ts = 127.487175 current_seq = 283 count = 255 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 127.487534 last_received_ts = 127.487175 last_seq = 283 current_ts = 127.504181 current_received_ts = 127.503960 current_seq = 284 count = 256 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 98us (kms_flip:2135) DEBUG: name = flip last_ts = 127.504181 last_received_ts = 127.503960 last_seq = 284 current_ts = 127.520851 current_received_ts = 127.520454 current_seq = 285 count = 257 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 54us (kms_flip:2135) DEBUG: name = flip last_ts = 127.520851 last_received_ts = 127.520454 last_seq = 285 current_ts = 127.537537 current_received_ts = 127.537155 current_seq = 286 count = 258 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 127.537537 last_received_ts = 127.537155 last_seq = 286 current_ts = 127.554192 current_received_ts = 127.553864 current_seq = 287 count = 259 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.554192 last_received_ts = 127.553864 last_seq = 287 current_ts = 127.570862 current_received_ts = 127.570480 current_seq = 288 count = 260 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 54us (kms_flip:2135) DEBUG: name = flip last_ts = 127.570862 last_received_ts = 127.570480 last_seq = 288 current_ts = 127.587524 current_received_ts = 127.587189 current_seq = 289 count = 261 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 127.587524 last_received_ts = 127.587189 last_seq = 289 current_ts = 127.604195 current_received_ts = 127.603882 current_seq = 290 count = 262 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.604195 last_received_ts = 127.603882 last_seq = 290 current_ts = 127.620865 current_received_ts = 127.620483 current_seq = 291 count = 263 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.620865 last_received_ts = 127.620483 last_seq = 291 current_ts = 127.637527 current_received_ts = 127.637207 current_seq = 292 count = 264 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.637527 last_received_ts = 127.637207 last_seq = 292 current_ts = 127.654205 current_received_ts = 127.653961 current_seq = 293 count = 265 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.654205 last_received_ts = 127.653961 last_seq = 293 current_ts = 127.670876 current_received_ts = 127.670464 current_seq = 294 count = 266 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 53us (kms_flip:2135) DEBUG: name = flip last_ts = 127.670876 last_received_ts = 127.670464 last_seq = 294 current_ts = 127.687538 current_received_ts = 127.687317 current_seq = 295 count = 267 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.687538 last_received_ts = 127.687317 last_seq = 295 current_ts = 127.704208 current_received_ts = 127.703957 current_seq = 296 count = 268 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 91us (kms_flip:2135) DEBUG: name = flip last_ts = 127.704208 last_received_ts = 127.703957 last_seq = 296 current_ts = 127.720879 current_received_ts = 127.720612 current_seq = 297 count = 269 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.720879 last_received_ts = 127.720612 last_seq = 297 current_ts = 127.737534 current_received_ts = 127.737190 current_seq = 298 count = 270 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.737534 last_received_ts = 127.737190 last_seq = 298 current_ts = 127.754211 current_received_ts = 127.753952 current_seq = 299 count = 271 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 96us (kms_flip:2135) DEBUG: name = flip last_ts = 127.754211 last_received_ts = 127.753952 last_seq = 299 current_ts = 127.770882 current_received_ts = 127.770485 current_seq = 300 count = 272 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.770882 last_received_ts = 127.770485 last_seq = 300 current_ts = 127.787537 current_received_ts = 127.787201 current_seq = 301 count = 273 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.787537 last_received_ts = 127.787201 last_seq = 301 current_ts = 127.804199 current_received_ts = 127.803879 current_seq = 302 count = 274 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.804199 last_received_ts = 127.803879 last_seq = 302 current_ts = 127.820885 current_received_ts = 127.820480 current_seq = 303 count = 275 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 61us (kms_flip:2135) DEBUG: name = flip last_ts = 127.820885 last_received_ts = 127.820480 last_seq = 303 current_ts = 127.837547 current_received_ts = 127.837166 current_seq = 304 count = 276 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 127.837547 last_received_ts = 127.837166 last_seq = 304 current_ts = 127.854210 current_received_ts = 127.853951 current_seq = 305 count = 277 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 97us (kms_flip:2135) DEBUG: name = flip last_ts = 127.854210 last_received_ts = 127.853951 last_seq = 305 current_ts = 127.870880 current_received_ts = 127.870468 current_seq = 306 count = 278 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.870880 last_received_ts = 127.870468 last_seq = 306 current_ts = 127.887535 current_received_ts = 127.887169 current_seq = 307 count = 279 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 127.887535 last_received_ts = 127.887169 last_seq = 307 current_ts = 127.904213 current_received_ts = 127.903954 current_seq = 308 count = 280 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 96us (kms_flip:2135) DEBUG: name = flip last_ts = 127.904213 last_received_ts = 127.903954 last_seq = 308 current_ts = 127.920883 current_received_ts = 127.920448 current_seq = 309 count = 281 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 127.920883 last_received_ts = 127.920448 last_seq = 309 current_ts = 127.937538 current_received_ts = 127.937218 current_seq = 310 count = 282 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 127.937538 last_received_ts = 127.937218 last_seq = 310 current_ts = 127.954208 current_received_ts = 127.953949 current_seq = 311 count = 283 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 101us (kms_flip:2135) DEBUG: name = flip last_ts = 127.954208 last_received_ts = 127.953949 last_seq = 311 current_ts = 127.970886 current_received_ts = 127.970459 current_seq = 312 count = 284 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 127.970886 last_received_ts = 127.970459 last_seq = 312 current_ts = 127.987556 current_received_ts = 127.987343 current_seq = 313 count = 285 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 127.987556 last_received_ts = 127.987343 last_seq = 313 current_ts = 128.004227 current_received_ts = 128.003891 current_seq = 314 count = 286 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.004227 last_received_ts = 128.003891 last_seq = 314 current_ts = 128.020889 current_received_ts = 128.020493 current_seq = 315 count = 287 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.020889 last_received_ts = 128.020493 last_seq = 315 current_ts = 128.037552 current_received_ts = 128.037201 current_seq = 316 count = 288 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.037552 last_received_ts = 128.037201 last_seq = 316 current_ts = 128.054214 current_received_ts = 128.053864 current_seq = 317 count = 289 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.054214 last_received_ts = 128.053864 last_seq = 317 current_ts = 128.070877 current_received_ts = 128.070587 current_seq = 318 count = 290 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.070877 last_received_ts = 128.070587 last_seq = 318 current_ts = 128.087555 current_received_ts = 128.087158 current_seq = 319 count = 291 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.087555 last_received_ts = 128.087158 last_seq = 319 current_ts = 128.104218 current_received_ts = 128.103897 current_seq = 320 count = 292 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.104218 last_received_ts = 128.103897 last_seq = 320 current_ts = 128.120880 current_received_ts = 128.120514 current_seq = 321 count = 293 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.120880 last_received_ts = 128.120514 last_seq = 321 current_ts = 128.137558 current_received_ts = 128.137360 current_seq = 322 count = 294 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.137558 last_received_ts = 128.137360 last_seq = 322 current_ts = 128.154236 current_received_ts = 128.153900 current_seq = 323 count = 295 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.154236 last_received_ts = 128.153900 last_seq = 323 current_ts = 128.170883 current_received_ts = 128.170624 current_seq = 324 count = 296 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 128.170883 last_received_ts = 128.170624 last_seq = 324 current_ts = 128.187561 current_received_ts = 128.187210 current_seq = 325 count = 297 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.187561 last_received_ts = 128.187210 last_seq = 325 current_ts = 128.204224 current_received_ts = 128.203888 current_seq = 326 count = 298 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.204224 last_received_ts = 128.203888 last_seq = 326 current_ts = 128.220886 current_received_ts = 128.220596 current_seq = 327 count = 299 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.220886 last_received_ts = 128.220596 last_seq = 327 current_ts = 128.237564 current_received_ts = 128.237381 current_seq = 328 count = 300 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.237564 last_received_ts = 128.237381 last_seq = 328 current_ts = 128.254227 current_received_ts = 128.253891 current_seq = 329 count = 301 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.254227 last_received_ts = 128.253891 last_seq = 329 current_ts = 128.270889 current_received_ts = 128.270493 current_seq = 330 count = 302 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.270889 last_received_ts = 128.270493 last_seq = 330 current_ts = 128.287567 current_received_ts = 128.287231 current_seq = 331 count = 303 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.287567 last_received_ts = 128.287231 last_seq = 331 current_ts = 128.304230 current_received_ts = 128.303894 current_seq = 332 count = 304 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.304230 last_received_ts = 128.303894 last_seq = 332 current_ts = 128.320892 current_received_ts = 128.320511 current_seq = 333 count = 305 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.320892 last_received_ts = 128.320511 last_seq = 333 current_ts = 128.337570 current_received_ts = 128.337189 current_seq = 334 count = 306 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.337570 last_received_ts = 128.337189 last_seq = 334 current_ts = 128.354233 current_received_ts = 128.353897 current_seq = 335 count = 307 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.354233 last_received_ts = 128.353897 last_seq = 335 current_ts = 128.370911 current_received_ts = 128.370499 current_seq = 336 count = 308 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.370911 last_received_ts = 128.370499 last_seq = 336 current_ts = 128.387573 current_received_ts = 128.387192 current_seq = 337 count = 309 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 53us (kms_flip:2135) DEBUG: name = flip last_ts = 128.387573 last_received_ts = 128.387192 last_seq = 337 current_ts = 128.404236 current_received_ts = 128.403900 current_seq = 338 count = 310 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.404236 last_received_ts = 128.403900 last_seq = 338 current_ts = 128.420898 current_received_ts = 128.420563 current_seq = 339 count = 311 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.420898 last_received_ts = 128.420563 last_seq = 339 current_ts = 128.437576 current_received_ts = 128.437195 current_seq = 340 count = 312 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.437576 last_received_ts = 128.437195 last_seq = 340 current_ts = 128.454239 current_received_ts = 128.453903 current_seq = 341 count = 313 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 87us (kms_flip:2135) DEBUG: name = flip last_ts = 128.454239 last_received_ts = 128.453903 last_seq = 341 current_ts = 128.470901 current_received_ts = 128.470535 current_seq = 342 count = 314 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.470901 last_received_ts = 128.470535 last_seq = 342 current_ts = 128.487564 current_received_ts = 128.487381 current_seq = 343 count = 315 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.487564 last_received_ts = 128.487381 last_seq = 343 current_ts = 128.504242 current_received_ts = 128.503998 current_seq = 344 count = 316 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.504242 last_received_ts = 128.503998 last_seq = 344 current_ts = 128.520905 current_received_ts = 128.520477 current_seq = 345 count = 317 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.520905 last_received_ts = 128.520477 last_seq = 345 current_ts = 128.537582 current_received_ts = 128.537384 current_seq = 346 count = 318 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 60us (kms_flip:2135) DEBUG: name = flip last_ts = 128.537582 last_received_ts = 128.537384 last_seq = 346 current_ts = 128.554245 current_received_ts = 128.553909 current_seq = 347 count = 319 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 81us (kms_flip:2135) DEBUG: name = flip last_ts = 128.554245 last_received_ts = 128.553909 last_seq = 347 current_ts = 128.570908 current_received_ts = 128.570526 current_seq = 348 count = 320 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.570908 last_received_ts = 128.570526 last_seq = 348 current_ts = 128.587585 current_received_ts = 128.587387 current_seq = 349 count = 321 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.587585 last_received_ts = 128.587387 last_seq = 349 current_ts = 128.604248 current_received_ts = 128.603989 current_seq = 350 count = 322 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.604248 last_received_ts = 128.603989 last_seq = 350 current_ts = 128.620926 current_received_ts = 128.620560 current_seq = 351 count = 323 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 54us (kms_flip:2135) DEBUG: name = flip last_ts = 128.620926 last_received_ts = 128.620560 last_seq = 351 current_ts = 128.637589 current_received_ts = 128.637253 current_seq = 352 count = 324 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 82us (kms_flip:2135) DEBUG: name = flip last_ts = 128.637589 last_received_ts = 128.637253 last_seq = 352 current_ts = 128.654251 current_received_ts = 128.653915 current_seq = 353 count = 325 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 91us (kms_flip:2135) DEBUG: name = flip last_ts = 128.654251 last_received_ts = 128.653915 last_seq = 353 current_ts = 128.670914 current_received_ts = 128.670624 current_seq = 354 count = 326 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.670914 last_received_ts = 128.670624 last_seq = 354 current_ts = 128.687592 current_received_ts = 128.687241 current_seq = 355 count = 327 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 74us (kms_flip:2135) DEBUG: name = flip last_ts = 128.687592 last_received_ts = 128.687241 last_seq = 355 current_ts = 128.704254 current_received_ts = 128.704041 current_seq = 356 count = 328 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.704254 last_received_ts = 128.704041 last_seq = 356 current_ts = 128.720917 current_received_ts = 128.720642 current_seq = 357 count = 329 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.720917 last_received_ts = 128.720642 last_seq = 357 current_ts = 128.737595 current_received_ts = 128.737259 current_seq = 358 count = 330 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 77us (kms_flip:2135) DEBUG: name = flip last_ts = 128.737595 last_received_ts = 128.737259 last_seq = 358 current_ts = 128.754257 current_received_ts = 128.753922 current_seq = 359 count = 331 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 88us (kms_flip:2135) DEBUG: name = flip last_ts = 128.754257 last_received_ts = 128.753922 last_seq = 359 current_ts = 128.770920 current_received_ts = 128.770660 current_seq = 360 count = 332 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.770920 last_received_ts = 128.770660 last_seq = 360 current_ts = 128.787598 current_received_ts = 128.787399 current_seq = 361 count = 333 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 58us (kms_flip:2135) DEBUG: name = flip last_ts = 128.787598 last_received_ts = 128.787399 last_seq = 361 current_ts = 128.804260 current_received_ts = 128.804047 current_seq = 362 count = 334 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.804260 last_received_ts = 128.804047 last_seq = 362 current_ts = 128.820923 current_received_ts = 128.820557 current_seq = 363 count = 335 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.820923 last_received_ts = 128.820557 last_seq = 363 current_ts = 128.837585 current_received_ts = 128.837280 current_seq = 364 count = 336 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 128.837585 last_received_ts = 128.837280 last_seq = 364 current_ts = 128.854263 current_received_ts = 128.853928 current_seq = 365 count = 337 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 169us (kms_flip:2135) DEBUG: name = flip last_ts = 128.854263 last_received_ts = 128.853928 last_seq = 365 current_ts = 128.870926 current_received_ts = 128.870499 current_seq = 366 count = 338 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 61us (kms_flip:2135) DEBUG: name = flip last_ts = 128.870926 last_received_ts = 128.870499 last_seq = 366 current_ts = 128.887604 current_received_ts = 128.887421 current_seq = 367 count = 339 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 58us (kms_flip:2135) DEBUG: name = flip last_ts = 128.887604 last_received_ts = 128.887421 last_seq = 367 current_ts = 128.904266 current_received_ts = 128.903915 current_seq = 368 count = 340 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 87us (kms_flip:2135) DEBUG: name = flip last_ts = 128.904266 last_received_ts = 128.903915 last_seq = 368 current_ts = 128.920929 current_received_ts = 128.920578 current_seq = 369 count = 341 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.920929 last_received_ts = 128.920578 last_seq = 369 current_ts = 128.937592 current_received_ts = 128.937256 current_seq = 370 count = 342 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 59us (kms_flip:2135) DEBUG: name = flip last_ts = 128.937592 last_received_ts = 128.937256 last_seq = 370 current_ts = 128.954269 current_received_ts = 128.953934 current_seq = 371 count = 343 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 83us (kms_flip:2135) DEBUG: name = flip last_ts = 128.954269 last_received_ts = 128.953934 last_seq = 371 current_ts = 128.970932 current_received_ts = 128.970673 current_seq = 372 count = 344 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 56us (kms_flip:2135) DEBUG: name = flip last_ts = 128.970932 last_received_ts = 128.970673 last_seq = 372 current_ts = 128.987610 current_received_ts = 128.987259 current_seq = 373 count = 345 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 53us (kms_flip:2135) DEBUG: name = flip last_ts = 128.987610 last_received_ts = 128.987259 last_seq = 373 current_ts = 129.004288 current_received_ts = 129.003952 current_seq = 374 count = 346 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 105us (kms_flip:2135) DEBUG: name = flip last_ts = 129.004288 last_received_ts = 129.003952 last_seq = 374 current_ts = 129.020935 current_received_ts = 129.020569 current_seq = 375 count = 347 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 129.020935 last_received_ts = 129.020569 last_seq = 375 current_ts = 129.037598 current_received_ts = 129.037292 current_seq = 376 count = 348 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 129.037598 last_received_ts = 129.037292 last_seq = 376 current_ts = 129.054260 current_received_ts = 129.053848 current_seq = 377 count = 349 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 57us (kms_flip:2135) DEBUG: name = flip last_ts = 129.054260 last_received_ts = 129.053848 last_seq = 377 current_ts = 129.070938 current_received_ts = 129.070480 current_seq = 378 count = 350 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 54us (kms_flip:2135) DEBUG: name = flip last_ts = 129.070938 last_received_ts = 129.070480 last_seq = 378 current_ts = 129.087601 current_received_ts = 129.087143 current_seq = 379 count = 351 seq_step = 1 (kms_flip:2135) DEBUG: Vblank took 993us (kms_flip:2135) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2135) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2135) igt_core-INFO: Stack trace: (kms_flip:2135) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2135) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:2135) igt_core-INFO: #2 ../tests/kms_flip.c:1889 run_test() (kms_flip:2135) igt_core-INFO: #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045() (kms_flip:2135) igt_core-INFO: #4 ../tests/kms_flip.c:2045 main() (kms_flip:2135) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2135) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2135) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A3: FAIL (6.296s)
Dmesg	<6> [122.978910] [IGT] kms_flip: starting dynamic subtest B-HDMI-A3 <7> [122.980427] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:560] <7> [122.981039] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:561] <7> [122.981615] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [122.982018] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [123.004001] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [123.004341] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [123.009891] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [123.010220] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [123.029270] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [123.029593] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [123.054783] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:149:pipe A] <7> [123.054879] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [123.055091] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [123.055273] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [123.055452] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [123.055630] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [123.055807] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [123.055985] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [123.056178] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [123.056357] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [123.056536] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [123.056714] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [123.056892] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [123.057078] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [123.057257] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [123.057434] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [123.057612] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [123.057790] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [123.057967] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [123.058152] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [123.058329] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [123.058507] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [123.058685] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [123.058864] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [123.059049] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [123.059227] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [123.059405] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [123.059583] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [123.059762] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [123.059940] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [123.060125] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [123.060302] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [123.060479] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [123.060656] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [123.060834] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [123.061016] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [123.061194] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [123.061372] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in port_clock (expected 148500, found 0) <7> [123.061551] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:149:pipe A] fastset requirement not met, forcing full modeset <7> [123.061750] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0xf), mbus joined? no->no <7> [123.061922] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:149:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [123.062124] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:143:cursor A] ddb (1963 - 2048) -> ( 0 - 0), size 85 -> 0 <7> [123.062325] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:149:pipe A] min cdclk: 74250 kHz -> 0 kHz <7> [123.062504] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz <7> [123.062680] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [123.062859] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:149:pipe A] enable: no [modeset] <7> [123.063045] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:33:plane 1A] fb: [NOFB], visible: no <7> [123.063222] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 2A] fb: [NOFB], visible: no <7> [123.063399] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:93:plane 3A] fb: [NOFB], visible: no <7> [123.063576] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:123:plane 4A] fb: [NOFB], visible: no <7> [123.063753] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:133:plane 5A] fb: [NOFB], visible: no <7> [123.063930] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:143:cursor A] fb: [NOFB], visible: no <7> [123.064326] i915 0000:03:00.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [123.077193] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_D <7> [123.077433] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:505:DDI A/PHY A] <7> [123.077609] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DP-MST A] <7> [123.077783] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:508:DP-MST B] <7> [123.077958] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST C] <7> [123.078141] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST D] <7> [123.078317] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DDI B/PHY B] <7> [123.078491] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST A] <7> [123.078665] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST B] <7> [123.078840] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST C] <7> [123.079020] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST D] <7> [123.079195] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:533:DDI C/PHY C] <7> [123.079369] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DP-MST A] <7> [123.079543] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST B] <7> [123.079718] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST C] <7> [123.079892] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST D] <7> [123.080076] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:545:DDI D/PHY D] <7> [123.080271] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DP-MST A] <7> [123.080447] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST B] <7> [123.080622] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST C] <7> [123.080797] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST D] <7> [123.080972] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:554:HDMI-A-3] <7> [123.081192] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [123.081473] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_A <7> [123.081714] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [123.081931] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:149:pipe A] <7> [123.082303] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:267:pipe B] <7> [123.082454] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:385:pipe C] <7> [123.082594] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:503:pipe D] <7> [123.082735] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:267:pipe B] <7> [123.082765] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:554:HDMI-A-3] <7> [123.082826] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CONNECTOR:554:HDMI-A-3] Limiting display bpp to 24 (EDID bpp 0, max requested bpp 36, max platform bpp 36) <7> [123.083019] i915 0000:03:00.0: [drm:intel_hdmi_compute_clock [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [123.083185] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:267:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [123.083364] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:545:DDI D/PHY D] [CRTC:267:pipe B] <7> [123.083533] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [123.083712] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [123.083889] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [123.084078] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [123.084257] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [123.084435] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [123.084613] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [123.084791] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [123.084969] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [123.085153] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [123.085332] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [123.085509] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [123.085687] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [123.085866] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [123.086052] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [123.086230] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [123.086408] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [123.086586] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [123.086763] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [123.086942] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [123.087126] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [123.087303] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [123.087480] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [123.087657] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [123.087834] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [123.088017] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [123.088194] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [123.088372] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [123.088549] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [123.088728] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [123.088906] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [123.089091] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [123.089269] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [123.089447] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [123.089624] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [123.089802] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [123.089980] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in port_clock (expected 0, found 148500) <7> [123.090166] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:267:pipe B] fastset requirement not met, forcing full modeset <7> [123.090364] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0xf), mbus joined? no->no <7> [123.090536] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:267:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2 <7> [123.090731] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:151:plane 1B] ddb ( 0 - 0) -> ( 0 - 1963), size 0 -> 1963 <7> [123.090902] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:261:cursor B] ddb ( 0 - 0) -> (1963 - 2048), size 0 -> 85 <7> [123.091081] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151: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> [123.091252] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 4, 5, 9, 11, 17, 25, 0, 0, 0 <7> [123.091424] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 62, 78, 139, 169, 261, 383, 137, 0, 0 <7> [123.091595] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 123, 184, 245, 245, 367, 489, 138, 0, 0 <7> [123.091782] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:267:pipe B] data rate 594000 num active planes 1 <7> [123.091959] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 50000 required 624 <7> [123.092142] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [123.092333] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:267:pipe B] min cdclk: 0 kHz -> 74250 kHz <7> [123.092524] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz <7> [123.092701] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [123.092879] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:267:pipe B] enable: yes [modeset] <7> [123.093061] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [123.093239] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [123.093416] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [123.093593] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [123.093769] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [123.093946] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [123.094175] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0 <7> [123.094353] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [123.094529] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [123.094707] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 45 vsync start: 41, vsync end: 36 <7> [123.094885] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1080, vmax vblank: 1080, vmin vtotal: 1125, vmax vtotal: 1125 <7> [123.095068] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [123.095247] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [123.095425] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [123.095603] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5 <7> [123.095781] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [123.095959] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port clock: 148500, pipe src: 1920x1080+0+0, pixel rate 148500, min cdclk 74250 <7> [123.096141] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] linetime: 119, ips linetime: 0 <7> [123.096318] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [123.096495] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [123.096672] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [123.096850] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x24414, dpll_md: 0x18000000, fp0: 0x8801ef8, fp1: 0x2b000440 <7> [123.097033] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [123.097222] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [123.097395] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [123.097567] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [123.097741] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [123.097913] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [123.098124] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [123.098297] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [123.098470] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [123.098642] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [123.098815] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [123.098992] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [123.099194] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [123.099367] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:151:plane 1B] fb: [FB:560] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [123.099542] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [123.099715] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [123.099889] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:181:plane 2B] fb: [NOFB], visible: no <7> [123.100104] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:211:plane 3B] fb: [NOFB], visible: no <7> [123.100172] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DC_off <7> [123.100311] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:241:plane 4B] fb: [NOFB], visible: no <7> [123.100405] i915 0000:03:00.0: [drm:gen9_enable_dc5 [i915]] Enabling DC5 <7> [123.100483] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:251:plane 5B] fb: [NOFB], visible: no <7> [123.100584] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 01 <7> [123.100656] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:261:cursor B] fb: [NOFB], visible: no <7> [123.101264] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DC_off <7> [123.101563] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 01 to 00 <7> [123.101923] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [123.102160] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_B <7> [123.102381] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:505:DDI A/PHY A] <7> [123.102553] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DP-MST A] <7> [123.102723] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:508:DP-MST B] <7> [123.102894] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST C] <7> [123.103136] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST D] <7> [123.103339] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DDI B/PHY B] <7> [123.103509] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST A] <7> [123.103679] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST B] <7> [123.103866] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST C] <7> [123.104059] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST D] <7> [123.104230] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:533:DDI C/PHY C] <7> [123.104399] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DP-MST A] <7> [123.104570] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST B] <7> [123.104741] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST C] <7> [123.104911] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST D] <7> [123.105116] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:545:DDI D/PHY D] <7> [123.105286] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DP-MST A] <7> [123.105457] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST B] <7> [123.105628] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST C] <7> [123.105798] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST D] <7> [123.105969] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [123.106401] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_D <7> [123.106696] i915 0000:03:00.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [123.125778] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:554:HDMI-A-3] <7> [123.126166] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:267:pipe B] <6> [129.275467] [IGT] kms_flip: finished subtest B-HDMI-A3, FAIL

Detail

Value

Duration

6.30 seconds

Hostname

shard-dg2-5

Igt-Version

IGT-Version: 2.3-gf38f4d8e9 (x86_64) (Linux: 6.19.0-rc1-CI_DRM_17720-g7fae53958ca7+ x86_64)

Out

Starting dynamic subtest: B-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1889 run_test()
  #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045()
  #4 ../tests/kms_flip.c:2045 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A3: FAIL (6.296s)

Err

Starting dynamic subtest: B-HDMI-A3
(kms_flip:2135) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2135) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.054169
last_received_ts = 127.053940
last_seq = 257
current_ts = 127.070839
current_received_ts = 127.070419
current_seq = 258
count = 230
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.070839
last_received_ts = 127.070419
last_seq = 258
current_ts = 127.087494
current_received_ts = 127.087181
current_seq = 259
count = 231
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.087494
last_received_ts = 127.087181
last_seq = 259
current_ts = 127.104172
current_received_ts = 127.103928
current_seq = 260
count = 232
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 103us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.104172
last_received_ts = 127.103928
last_seq = 260
current_ts = 127.120842
current_received_ts = 127.120468
current_seq = 261
count = 233
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.120842
last_received_ts = 127.120468
last_seq = 261
current_ts = 127.137505
current_received_ts = 127.137314
current_seq = 262
count = 234
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.137505
last_received_ts = 127.137314
last_seq = 262
current_ts = 127.154167
current_received_ts = 127.153854
current_seq = 263
count = 235
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.154167
last_received_ts = 127.153854
last_seq = 263
current_ts = 127.170837
current_received_ts = 127.170479
current_seq = 264
count = 236
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 61us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.170837
last_received_ts = 127.170479
last_seq = 264
current_ts = 127.187508
current_received_ts = 127.187302
current_seq = 265
count = 237
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.187508
last_received_ts = 127.187302
last_seq = 265
current_ts = 127.204170
current_received_ts = 127.203926
current_seq = 266
count = 238
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 91us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.204170
last_received_ts = 127.203926
last_seq = 266
current_ts = 127.220848
current_received_ts = 127.220467
current_seq = 267
count = 239
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.220848
last_received_ts = 127.220467
last_seq = 267
current_ts = 127.237511
current_received_ts = 127.237206
current_seq = 268
count = 240
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.237511
last_received_ts = 127.237206
last_seq = 268
current_ts = 127.254173
current_received_ts = 127.253868
current_seq = 269
count = 241
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.254173
last_received_ts = 127.253868
last_seq = 269
current_ts = 127.270851
current_received_ts = 127.270485
current_seq = 270
count = 242
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.270851
last_received_ts = 127.270485
last_seq = 270
current_ts = 127.287514
current_received_ts = 127.287155
current_seq = 271
count = 243
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 53us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.287514
last_received_ts = 127.287155
last_seq = 271
current_ts = 127.304176
current_received_ts = 127.303864
current_seq = 272
count = 244
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.304176
last_received_ts = 127.303864
last_seq = 272
current_ts = 127.320839
current_received_ts = 127.320480
current_seq = 273
count = 245
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.320839
last_received_ts = 127.320480
last_seq = 273
current_ts = 127.337517
current_received_ts = 127.337181
current_seq = 274
count = 246
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.337517
last_received_ts = 127.337181
last_seq = 274
current_ts = 127.354179
current_received_ts = 127.353859
current_seq = 275
count = 247
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 58us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.354179
last_received_ts = 127.353859
last_seq = 275
current_ts = 127.370842
current_received_ts = 127.370590
current_seq = 276
count = 248
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.370842
last_received_ts = 127.370590
last_seq = 276
current_ts = 127.387520
current_received_ts = 127.387306
current_seq = 277
count = 249
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 58us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.387520
last_received_ts = 127.387306
last_seq = 277
current_ts = 127.404190
current_received_ts = 127.403839
current_seq = 278
count = 250
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 58us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.404190
last_received_ts = 127.403839
last_seq = 278
current_ts = 127.420853
current_received_ts = 127.420486
current_seq = 279
count = 251
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 58us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.420853
last_received_ts = 127.420486
last_seq = 279
current_ts = 127.437531
current_received_ts = 127.437164
current_seq = 280
count = 252
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.437531
last_received_ts = 127.437164
last_seq = 280
current_ts = 127.454193
current_received_ts = 127.453842
current_seq = 281
count = 253
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.454193
last_received_ts = 127.453842
last_seq = 281
current_ts = 127.470863
current_received_ts = 127.470474
current_seq = 282
count = 254
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.470863
last_received_ts = 127.470474
last_seq = 282
current_ts = 127.487534
current_received_ts = 127.487175
current_seq = 283
count = 255
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.487534
last_received_ts = 127.487175
last_seq = 283
current_ts = 127.504181
current_received_ts = 127.503960
current_seq = 284
count = 256
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 98us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.504181
last_received_ts = 127.503960
last_seq = 284
current_ts = 127.520851
current_received_ts = 127.520454
current_seq = 285
count = 257
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 54us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.520851
last_received_ts = 127.520454
last_seq = 285
current_ts = 127.537537
current_received_ts = 127.537155
current_seq = 286
count = 258
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.537537
last_received_ts = 127.537155
last_seq = 286
current_ts = 127.554192
current_received_ts = 127.553864
current_seq = 287
count = 259
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.554192
last_received_ts = 127.553864
last_seq = 287
current_ts = 127.570862
current_received_ts = 127.570480
current_seq = 288
count = 260
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 54us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.570862
last_received_ts = 127.570480
last_seq = 288
current_ts = 127.587524
current_received_ts = 127.587189
current_seq = 289
count = 261
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.587524
last_received_ts = 127.587189
last_seq = 289
current_ts = 127.604195
current_received_ts = 127.603882
current_seq = 290
count = 262
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.604195
last_received_ts = 127.603882
last_seq = 290
current_ts = 127.620865
current_received_ts = 127.620483
current_seq = 291
count = 263
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.620865
last_received_ts = 127.620483
last_seq = 291
current_ts = 127.637527
current_received_ts = 127.637207
current_seq = 292
count = 264
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.637527
last_received_ts = 127.637207
last_seq = 292
current_ts = 127.654205
current_received_ts = 127.653961
current_seq = 293
count = 265
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.654205
last_received_ts = 127.653961
last_seq = 293
current_ts = 127.670876
current_received_ts = 127.670464
current_seq = 294
count = 266
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 53us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.670876
last_received_ts = 127.670464
last_seq = 294
current_ts = 127.687538
current_received_ts = 127.687317
current_seq = 295
count = 267
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.687538
last_received_ts = 127.687317
last_seq = 295
current_ts = 127.704208
current_received_ts = 127.703957
current_seq = 296
count = 268
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 91us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.704208
last_received_ts = 127.703957
last_seq = 296
current_ts = 127.720879
current_received_ts = 127.720612
current_seq = 297
count = 269
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.720879
last_received_ts = 127.720612
last_seq = 297
current_ts = 127.737534
current_received_ts = 127.737190
current_seq = 298
count = 270
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.737534
last_received_ts = 127.737190
last_seq = 298
current_ts = 127.754211
current_received_ts = 127.753952
current_seq = 299
count = 271
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 96us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.754211
last_received_ts = 127.753952
last_seq = 299
current_ts = 127.770882
current_received_ts = 127.770485
current_seq = 300
count = 272
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.770882
last_received_ts = 127.770485
last_seq = 300
current_ts = 127.787537
current_received_ts = 127.787201
current_seq = 301
count = 273
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.787537
last_received_ts = 127.787201
last_seq = 301
current_ts = 127.804199
current_received_ts = 127.803879
current_seq = 302
count = 274
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.804199
last_received_ts = 127.803879
last_seq = 302
current_ts = 127.820885
current_received_ts = 127.820480
current_seq = 303
count = 275
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 61us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.820885
last_received_ts = 127.820480
last_seq = 303
current_ts = 127.837547
current_received_ts = 127.837166
current_seq = 304
count = 276
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.837547
last_received_ts = 127.837166
last_seq = 304
current_ts = 127.854210
current_received_ts = 127.853951
current_seq = 305
count = 277
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 97us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.854210
last_received_ts = 127.853951
last_seq = 305
current_ts = 127.870880
current_received_ts = 127.870468
current_seq = 306
count = 278
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.870880
last_received_ts = 127.870468
last_seq = 306
current_ts = 127.887535
current_received_ts = 127.887169
current_seq = 307
count = 279
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.887535
last_received_ts = 127.887169
last_seq = 307
current_ts = 127.904213
current_received_ts = 127.903954
current_seq = 308
count = 280
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 96us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.904213
last_received_ts = 127.903954
last_seq = 308
current_ts = 127.920883
current_received_ts = 127.920448
current_seq = 309
count = 281
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.920883
last_received_ts = 127.920448
last_seq = 309
current_ts = 127.937538
current_received_ts = 127.937218
current_seq = 310
count = 282
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.937538
last_received_ts = 127.937218
last_seq = 310
current_ts = 127.954208
current_received_ts = 127.953949
current_seq = 311
count = 283
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 101us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.954208
last_received_ts = 127.953949
last_seq = 311
current_ts = 127.970886
current_received_ts = 127.970459
current_seq = 312
count = 284
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.970886
last_received_ts = 127.970459
last_seq = 312
current_ts = 127.987556
current_received_ts = 127.987343
current_seq = 313
count = 285
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 127.987556
last_received_ts = 127.987343
last_seq = 313
current_ts = 128.004227
current_received_ts = 128.003891
current_seq = 314
count = 286
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.004227
last_received_ts = 128.003891
last_seq = 314
current_ts = 128.020889
current_received_ts = 128.020493
current_seq = 315
count = 287
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.020889
last_received_ts = 128.020493
last_seq = 315
current_ts = 128.037552
current_received_ts = 128.037201
current_seq = 316
count = 288
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.037552
last_received_ts = 128.037201
last_seq = 316
current_ts = 128.054214
current_received_ts = 128.053864
current_seq = 317
count = 289
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.054214
last_received_ts = 128.053864
last_seq = 317
current_ts = 128.070877
current_received_ts = 128.070587
current_seq = 318
count = 290
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.070877
last_received_ts = 128.070587
last_seq = 318
current_ts = 128.087555
current_received_ts = 128.087158
current_seq = 319
count = 291
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.087555
last_received_ts = 128.087158
last_seq = 319
current_ts = 128.104218
current_received_ts = 128.103897
current_seq = 320
count = 292
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.104218
last_received_ts = 128.103897
last_seq = 320
current_ts = 128.120880
current_received_ts = 128.120514
current_seq = 321
count = 293
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.120880
last_received_ts = 128.120514
last_seq = 321
current_ts = 128.137558
current_received_ts = 128.137360
current_seq = 322
count = 294
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.137558
last_received_ts = 128.137360
last_seq = 322
current_ts = 128.154236
current_received_ts = 128.153900
current_seq = 323
count = 295
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.154236
last_received_ts = 128.153900
last_seq = 323
current_ts = 128.170883
current_received_ts = 128.170624
current_seq = 324
count = 296
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.170883
last_received_ts = 128.170624
last_seq = 324
current_ts = 128.187561
current_received_ts = 128.187210
current_seq = 325
count = 297
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.187561
last_received_ts = 128.187210
last_seq = 325
current_ts = 128.204224
current_received_ts = 128.203888
current_seq = 326
count = 298
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.204224
last_received_ts = 128.203888
last_seq = 326
current_ts = 128.220886
current_received_ts = 128.220596
current_seq = 327
count = 299
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.220886
last_received_ts = 128.220596
last_seq = 327
current_ts = 128.237564
current_received_ts = 128.237381
current_seq = 328
count = 300
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.237564
last_received_ts = 128.237381
last_seq = 328
current_ts = 128.254227
current_received_ts = 128.253891
current_seq = 329
count = 301
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.254227
last_received_ts = 128.253891
last_seq = 329
current_ts = 128.270889
current_received_ts = 128.270493
current_seq = 330
count = 302
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.270889
last_received_ts = 128.270493
last_seq = 330
current_ts = 128.287567
current_received_ts = 128.287231
current_seq = 331
count = 303
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.287567
last_received_ts = 128.287231
last_seq = 331
current_ts = 128.304230
current_received_ts = 128.303894
current_seq = 332
count = 304
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.304230
last_received_ts = 128.303894
last_seq = 332
current_ts = 128.320892
current_received_ts = 128.320511
current_seq = 333
count = 305
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.320892
last_received_ts = 128.320511
last_seq = 333
current_ts = 128.337570
current_received_ts = 128.337189
current_seq = 334
count = 306
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.337570
last_received_ts = 128.337189
last_seq = 334
current_ts = 128.354233
current_received_ts = 128.353897
current_seq = 335
count = 307
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.354233
last_received_ts = 128.353897
last_seq = 335
current_ts = 128.370911
current_received_ts = 128.370499
current_seq = 336
count = 308
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.370911
last_received_ts = 128.370499
last_seq = 336
current_ts = 128.387573
current_received_ts = 128.387192
current_seq = 337
count = 309
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 53us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.387573
last_received_ts = 128.387192
last_seq = 337
current_ts = 128.404236
current_received_ts = 128.403900
current_seq = 338
count = 310
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.404236
last_received_ts = 128.403900
last_seq = 338
current_ts = 128.420898
current_received_ts = 128.420563
current_seq = 339
count = 311
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.420898
last_received_ts = 128.420563
last_seq = 339
current_ts = 128.437576
current_received_ts = 128.437195
current_seq = 340
count = 312
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.437576
last_received_ts = 128.437195
last_seq = 340
current_ts = 128.454239
current_received_ts = 128.453903
current_seq = 341
count = 313
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 87us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.454239
last_received_ts = 128.453903
last_seq = 341
current_ts = 128.470901
current_received_ts = 128.470535
current_seq = 342
count = 314
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.470901
last_received_ts = 128.470535
last_seq = 342
current_ts = 128.487564
current_received_ts = 128.487381
current_seq = 343
count = 315
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.487564
last_received_ts = 128.487381
last_seq = 343
current_ts = 128.504242
current_received_ts = 128.503998
current_seq = 344
count = 316
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.504242
last_received_ts = 128.503998
last_seq = 344
current_ts = 128.520905
current_received_ts = 128.520477
current_seq = 345
count = 317
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.520905
last_received_ts = 128.520477
last_seq = 345
current_ts = 128.537582
current_received_ts = 128.537384
current_seq = 346
count = 318
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 60us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.537582
last_received_ts = 128.537384
last_seq = 346
current_ts = 128.554245
current_received_ts = 128.553909
current_seq = 347
count = 319
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 81us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.554245
last_received_ts = 128.553909
last_seq = 347
current_ts = 128.570908
current_received_ts = 128.570526
current_seq = 348
count = 320
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.570908
last_received_ts = 128.570526
last_seq = 348
current_ts = 128.587585
current_received_ts = 128.587387
current_seq = 349
count = 321
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.587585
last_received_ts = 128.587387
last_seq = 349
current_ts = 128.604248
current_received_ts = 128.603989
current_seq = 350
count = 322
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.604248
last_received_ts = 128.603989
last_seq = 350
current_ts = 128.620926
current_received_ts = 128.620560
current_seq = 351
count = 323
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 54us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.620926
last_received_ts = 128.620560
last_seq = 351
current_ts = 128.637589
current_received_ts = 128.637253
current_seq = 352
count = 324
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 82us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.637589
last_received_ts = 128.637253
last_seq = 352
current_ts = 128.654251
current_received_ts = 128.653915
current_seq = 353
count = 325
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 91us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.654251
last_received_ts = 128.653915
last_seq = 353
current_ts = 128.670914
current_received_ts = 128.670624
current_seq = 354
count = 326
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.670914
last_received_ts = 128.670624
last_seq = 354
current_ts = 128.687592
current_received_ts = 128.687241
current_seq = 355
count = 327
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 74us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.687592
last_received_ts = 128.687241
last_seq = 355
current_ts = 128.704254
current_received_ts = 128.704041
current_seq = 356
count = 328
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.704254
last_received_ts = 128.704041
last_seq = 356
current_ts = 128.720917
current_received_ts = 128.720642
current_seq = 357
count = 329
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.720917
last_received_ts = 128.720642
last_seq = 357
current_ts = 128.737595
current_received_ts = 128.737259
current_seq = 358
count = 330
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 77us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.737595
last_received_ts = 128.737259
last_seq = 358
current_ts = 128.754257
current_received_ts = 128.753922
current_seq = 359
count = 331
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 88us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.754257
last_received_ts = 128.753922
last_seq = 359
current_ts = 128.770920
current_received_ts = 128.770660
current_seq = 360
count = 332
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.770920
last_received_ts = 128.770660
last_seq = 360
current_ts = 128.787598
current_received_ts = 128.787399
current_seq = 361
count = 333
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 58us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.787598
last_received_ts = 128.787399
last_seq = 361
current_ts = 128.804260
current_received_ts = 128.804047
current_seq = 362
count = 334
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.804260
last_received_ts = 128.804047
last_seq = 362
current_ts = 128.820923
current_received_ts = 128.820557
current_seq = 363
count = 335
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.820923
last_received_ts = 128.820557
last_seq = 363
current_ts = 128.837585
current_received_ts = 128.837280
current_seq = 364
count = 336
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.837585
last_received_ts = 128.837280
last_seq = 364
current_ts = 128.854263
current_received_ts = 128.853928
current_seq = 365
count = 337
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 169us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.854263
last_received_ts = 128.853928
last_seq = 365
current_ts = 128.870926
current_received_ts = 128.870499
current_seq = 366
count = 338
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 61us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.870926
last_received_ts = 128.870499
last_seq = 366
current_ts = 128.887604
current_received_ts = 128.887421
current_seq = 367
count = 339
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 58us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.887604
last_received_ts = 128.887421
last_seq = 367
current_ts = 128.904266
current_received_ts = 128.903915
current_seq = 368
count = 340
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 87us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.904266
last_received_ts = 128.903915
last_seq = 368
current_ts = 128.920929
current_received_ts = 128.920578
current_seq = 369
count = 341
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.920929
last_received_ts = 128.920578
last_seq = 369
current_ts = 128.937592
current_received_ts = 128.937256
current_seq = 370
count = 342
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 59us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.937592
last_received_ts = 128.937256
last_seq = 370
current_ts = 128.954269
current_received_ts = 128.953934
current_seq = 371
count = 343
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 83us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.954269
last_received_ts = 128.953934
last_seq = 371
current_ts = 128.970932
current_received_ts = 128.970673
current_seq = 372
count = 344
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 56us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.970932
last_received_ts = 128.970673
last_seq = 372
current_ts = 128.987610
current_received_ts = 128.987259
current_seq = 373
count = 345
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 53us
(kms_flip:2135) DEBUG: name = flip
last_ts = 128.987610
last_received_ts = 128.987259
last_seq = 373
current_ts = 129.004288
current_received_ts = 129.003952
current_seq = 374
count = 346
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 105us
(kms_flip:2135) DEBUG: name = flip
last_ts = 129.004288
last_received_ts = 129.003952
last_seq = 374
current_ts = 129.020935
current_received_ts = 129.020569
current_seq = 375
count = 347
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 129.020935
last_received_ts = 129.020569
last_seq = 375
current_ts = 129.037598
current_received_ts = 129.037292
current_seq = 376
count = 348
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 129.037598
last_received_ts = 129.037292
last_seq = 376
current_ts = 129.054260
current_received_ts = 129.053848
current_seq = 377
count = 349
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 57us
(kms_flip:2135) DEBUG: name = flip
last_ts = 129.054260
last_received_ts = 129.053848
last_seq = 377
current_ts = 129.070938
current_received_ts = 129.070480
current_seq = 378
count = 350
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 54us
(kms_flip:2135) DEBUG: name = flip
last_ts = 129.070938
last_received_ts = 129.070480
last_seq = 378
current_ts = 129.087601
current_received_ts = 129.087143
current_seq = 379
count = 351
seq_step = 1
(kms_flip:2135) DEBUG: Vblank took 993us
(kms_flip:2135) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2135) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2135) igt_core-INFO: Stack trace:
(kms_flip:2135) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2135) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:2135) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:2135) igt_core-INFO:   #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2045()
(kms_flip:2135) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:2135) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2135) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2135) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A3: FAIL (6.296s)

Dmesg

<6> [122.978910] [IGT] kms_flip: starting dynamic subtest B-HDMI-A3

<7> [122.980427] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:560]

<7> [122.981039] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:561]

<7> [122.981615] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [122.982018] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [123.004001] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [123.004341] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [123.009891] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [123.010220] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [123.029270] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [123.029593] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509

<7> [123.054783] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:149:pipe A]

<7> [123.054879] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.enable (expected yes, found no)

<7> [123.055091] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.active (expected yes, found no)

<7> [123.055273] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)

<7> [123.055452] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in lane_count (expected 4, found 0)

<7> [123.055630] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000)

<7> [123.055807] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)

<7> [123.055985] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0)

<7> [123.056178] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0)

<7> [123.056357] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0)

<7> [123.056536] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0)

<7> [123.056714] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0)

<7> [123.056892] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0)

<7> [123.057078] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0)

<7> [123.057257] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0)

<7> [123.057434] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0)

<7> [123.057612] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0)

<7> [123.057790] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0)

<7> [123.057967] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0)

<7> [123.058152] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0)

<7> [123.058329] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0)

<7> [123.058507] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0)

<7> [123.058685] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0)

<7> [123.058864] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0)

<7> [123.059049] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0)

<7> [123.059227] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0)

<7> [123.059405] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0)

<7> [123.059583] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0)

<7> [123.059762] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0)

<7> [123.059940] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0)

<7> [123.060125] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0)

<7> [123.060302] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)

<7> [123.060479] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0)

<7> [123.060656] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0)

<7> [123.060834] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)

<7> [123.061016] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0)

<7> [123.061194] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0)

<7> [123.061372] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:149:pipe A] fastset requirement not met in port_clock (expected 148500, found 0)

<7> [123.061551] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:149:pipe A] fastset requirement not met, forcing full modeset

<7> [123.061750] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0xf), mbus joined? no->no

<7> [123.061922] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:149:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0

<7> [123.062124] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:143:cursor A] ddb (1963 - 2048) -> ( 0 - 0), size 85 -> 0

<7> [123.062325] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:149:pipe A] min cdclk: 74250 kHz -> 0 kHz

<7> [123.062504] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz

<7> [123.062680] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0

<7> [123.062859] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:149:pipe A] enable: no [modeset]

<7> [123.063045] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:33:plane 1A] fb: [NOFB], visible: no

<7> [123.063222] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 2A] fb: [NOFB], visible: no

<7> [123.063399] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:93:plane 3A] fb: [NOFB], visible: no

<7> [123.063576] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:123:plane 4A] fb: [NOFB], visible: no

<7> [123.063753] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:133:plane 5A] fb: [NOFB], visible: no

<7> [123.063930] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:143:cursor A] fb: [NOFB], visible: no

<7> [123.064326] i915 0000:03:00.0: [drm:intel_disable_transcoder [i915]] disabling pipe A

<7> [123.077193] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_D

<7> [123.077433] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:505:DDI A/PHY A]

<7> [123.077609] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DP-MST A]

<7> [123.077783] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:508:DP-MST B]

<7> [123.077958] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST C]

<7> [123.078141] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST D]

<7> [123.078317] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DDI B/PHY B]

<7> [123.078491] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST A]

<7> [123.078665] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST B]

<7> [123.078840] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST C]

<7> [123.079020] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST D]

<7> [123.079195] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:533:DDI C/PHY C]

<7> [123.079369] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DP-MST A]

<7> [123.079543] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST B]

<7> [123.079718] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST C]

<7> [123.079892] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST D]

<7> [123.080076] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:545:DDI D/PHY D]

<7> [123.080271] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DP-MST A]

<7> [123.080447] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST B]

<7> [123.080622] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST C]

<7> [123.080797] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST D]

<7> [123.080972] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:554:HDMI-A-3]

<7> [123.081192] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1

<7> [123.081473] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_A

<7> [123.081714] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_2

<7> [123.081931] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:149:pipe A]

<7> [123.082303] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:267:pipe B]

<7> [123.082454] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:385:pipe C]

<7> [123.082594] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:503:pipe D]

<7> [123.082735] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:267:pipe B]

<7> [123.082765] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:554:HDMI-A-3]

<7> [123.082826] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CONNECTOR:554:HDMI-A-3] Limiting display bpp to 24 (EDID bpp 0, max requested bpp 36, max platform bpp 36)

<7> [123.083019] i915 0000:03:00.0: [drm:intel_hdmi_compute_clock [i915]] picking 8 bpc for HDMI output (pipe bpp: 24)

<7> [123.083185] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:267:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0

<7> [123.083364] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:545:DDI D/PHY D] [CRTC:267:pipe B]

<7> [123.083533] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.enable (expected no, found yes)

<7> [123.083712] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.active (expected no, found yes)

<7> [123.083889] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)

<7> [123.084078] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in lane_count (expected 0, found 4)

<7> [123.084257] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040)

<7> [123.084435] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)

<7> [123.084613] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920)

<7> [123.084791] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200)

<7> [123.084969] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920)

<7> [123.085153] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200)

<7> [123.085332] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008)

<7> [123.085509] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052)

<7> [123.085687] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080)

<7> [123.085866] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080)

<7> [123.086052] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084)

<7> [123.086230] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089)

<7> [123.086408] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125)

<7> [123.086586] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125)

<7> [123.086763] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920)

<7> [123.086942] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200)

<7> [123.087126] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920)

<7> [123.087303] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200)

<7> [123.087480] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008)

<7> [123.087657] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052)

<7> [123.087834] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080)

<7> [123.088017] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080)

<7> [123.088194] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084)

<7> [123.088372] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089)

<7> [123.088549] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125)

<7> [123.088728] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125)

<7> [123.088906] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)

<7> [123.089091] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1)

<7> [123.089269] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4)

<7> [123.089447] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)

<7> [123.089624] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500)

<7> [123.089802] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500)

<7> [123.089980] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:267:pipe B] fastset requirement not met in port_clock (expected 0, found 148500)

<7> [123.090166] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:267:pipe B] fastset requirement not met, forcing full modeset

<7> [123.090364] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0xf), mbus joined? no->no

<7> [123.090536] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:267:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2

<7> [123.090731] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:151:plane 1B] ddb ( 0 - 0) -> ( 0 - 1963), size 0 -> 1963

<7> [123.090902] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:261:cursor B] ddb ( 0 - 0) -> (1963 - 2048), size 0 -> 85

<7> [123.091081] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151: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> [123.091252] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 4, 5, 9, 11, 17, 25, 0, 0, 0

<7> [123.091424] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 62, 78, 139, 169, 261, 383, 137, 0, 0

<7> [123.091595] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:151:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 123, 184, 245, 245, 367, 489, 138, 0, 0

<7> [123.091782] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:267:pipe B] data rate 594000 num active planes 1

<7> [123.091959] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 50000 required 624

<7> [123.092142] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1

<7> [123.092333] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:267:pipe B] min cdclk: 0 kHz -> 74250 kHz

<7> [123.092524] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz

<7> [123.092701] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0

<7> [123.092879] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:267:pipe B] enable: yes [modeset]

<7> [123.093061] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB

<7> [123.093239] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0

<7> [123.093416] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>

<7> [123.093593] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0

<7> [123.093769] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0

<7> [123.093946] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0

<7> [123.094175] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0

<7> [123.094353] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

<7> [123.094529] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0

<7> [123.094707] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 45 vsync start: 41, vsync end: 36

<7> [123.094885] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1080, vmax vblank: 1080, vmin vtotal: 1125, vmax vtotal: 1125

<7> [123.095068] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5

<7> [123.095247] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5

<7> [123.095425] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [123.095603] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5

<7> [123.095781] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [123.095959] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port clock: 148500, pipe src: 1920x1080+0+0, pixel rate 148500, min cdclk 74250

<7> [123.096141] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] linetime: 119, ips linetime: 0

<7> [123.096318] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0

<7> [123.096495] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no

<7> [123.096672] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0

<7> [123.096850] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x24414, dpll_md: 0x18000000, fp0: 0x8801ef8, fp1: 0x2b000440

<7> [123.097033] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

<7> [123.097222] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries

<7> [123.097395] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000

<7> [123.097567] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [123.097741] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [123.097913] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [123.098124] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000

<7> [123.098297] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000

<7> [123.098470] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [123.098642] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [123.098815] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [123.098992] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000

<7> [123.099194] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0

<7> [123.099367] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:151:plane 1B] fb: [FB:560] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes

<7> [123.099542] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0

<7> [123.099715] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0

<7> [123.099889] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:181:plane 2B] fb: [NOFB], visible: no

<7> [123.100104] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:211:plane 3B] fb: [NOFB], visible: no

<7> [123.100172] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DC_off

<7> [123.100311] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:241:plane 4B] fb: [NOFB], visible: no

<7> [123.100405] i915 0000:03:00.0: [drm:gen9_enable_dc5 [i915]] Enabling DC5

<7> [123.100483] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:251:plane 5B] fb: [NOFB], visible: no

<7> [123.100584] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 01

<7> [123.100656] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:261:cursor B] fb: [NOFB], visible: no

<7> [123.101264] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DC_off

<7> [123.101563] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 01 to 00

<7> [123.101923] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_2

<7> [123.102160] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_B

<7> [123.102381] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:505:DDI A/PHY A]

<7> [123.102553] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DP-MST A]

<7> [123.102723] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:508:DP-MST B]

<7> [123.102894] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST C]

<7> [123.103136] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST D]

<7> [123.103339] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DDI B/PHY B]

<7> [123.103509] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST A]

<7> [123.103679] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST B]

<7> [123.103866] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST C]

<7> [123.104059] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST D]

<7> [123.104230] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:533:DDI C/PHY C]

<7> [123.104399] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DP-MST A]

<7> [123.104570] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST B]

<7> [123.104741] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST C]

<7> [123.104911] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST D]

<7> [123.105116] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:545:DDI D/PHY D]

<7> [123.105286] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DP-MST A]

<7> [123.105457] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST B]

<7> [123.105628] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST C]

<7> [123.105798] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST D]

<7> [123.105969] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3

<7> [123.106401] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_D

<7> [123.106696] i915 0000:03:00.0: [drm:intel_enable_transcoder [i915]] enabling pipe B

<7> [123.125778] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:554:HDMI-A-3]

<7> [123.126166] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:267:pipe B]

<6> [129.275467] [IGT] kms_flip: finished subtest B-HDMI-A3, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a3