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

Detail	Value
Duration	2.96 seconds
Hostname	shard-dg2-1
Igt-Version	IGT-Version: 2.3-g07ca77c0e (x86_64) (Linux: 6.19.0-CI_DRM_17988-g0558a31efefc+ 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:921 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1887 run_test() #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043() #4 ../tests/kms_flip.c:2043 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-HDMI-A3: FAIL (2.956s)
Err	Starting dynamic subtest: B-HDMI-A3 (kms_flip:2267) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2267) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-HDMI-A3 failed. ** DEBUG (kms_flip:2267) DEBUG: name = flip last_ts = 311.877472 last_received_ts = 311.877258 last_seq = 269 current_ts = 311.894165 current_received_ts = 311.893799 current_seq = 270 count = 32 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 53us (kms_flip:2267) DEBUG: name = flip last_ts = 311.894165 last_received_ts = 311.893799 last_seq = 270 current_ts = 311.910828 current_received_ts = 311.910431 current_seq = 271 count = 33 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 311.910828 last_received_ts = 311.910431 last_seq = 271 current_ts = 311.927490 current_received_ts = 311.927155 current_seq = 272 count = 34 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 311.927490 last_received_ts = 311.927155 last_seq = 272 current_ts = 311.944153 current_received_ts = 311.943817 current_seq = 273 count = 35 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 311.944153 last_received_ts = 311.943817 last_seq = 273 current_ts = 311.960846 current_received_ts = 311.960419 current_seq = 274 count = 36 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 51us (kms_flip:2267) DEBUG: name = flip last_ts = 311.960846 last_received_ts = 311.960419 last_seq = 274 current_ts = 311.977478 current_received_ts = 311.977142 current_seq = 275 count = 37 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 311.977478 last_received_ts = 311.977142 last_seq = 275 current_ts = 311.994171 current_received_ts = 311.993896 current_seq = 276 count = 38 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 85us (kms_flip:2267) DEBUG: name = flip last_ts = 311.994171 last_received_ts = 311.993896 last_seq = 276 current_ts = 312.010834 current_received_ts = 312.010437 current_seq = 277 count = 39 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 53us (kms_flip:2267) DEBUG: name = flip last_ts = 312.010834 last_received_ts = 312.010437 last_seq = 277 current_ts = 312.027496 current_received_ts = 312.027130 current_seq = 278 count = 40 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.027496 last_received_ts = 312.027130 last_seq = 278 current_ts = 312.044159 current_received_ts = 312.043793 current_seq = 279 count = 41 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 312.044159 last_received_ts = 312.043793 last_seq = 279 current_ts = 312.060822 current_received_ts = 312.060455 current_seq = 280 count = 42 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.060822 last_received_ts = 312.060455 last_seq = 280 current_ts = 312.077515 current_received_ts = 312.077271 current_seq = 281 count = 43 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.077515 last_received_ts = 312.077271 last_seq = 281 current_ts = 312.094177 current_received_ts = 312.093903 current_seq = 282 count = 44 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 84us (kms_flip:2267) DEBUG: name = flip last_ts = 312.094177 last_received_ts = 312.093903 last_seq = 282 current_ts = 312.110840 current_received_ts = 312.110443 current_seq = 283 count = 45 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.110840 last_received_ts = 312.110443 last_seq = 283 current_ts = 312.127502 current_received_ts = 312.127167 current_seq = 284 count = 46 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.127502 last_received_ts = 312.127167 last_seq = 284 current_ts = 312.144165 current_received_ts = 312.143829 current_seq = 285 count = 47 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.144165 last_received_ts = 312.143829 last_seq = 285 current_ts = 312.160828 current_received_ts = 312.160400 current_seq = 286 count = 48 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 53us (kms_flip:2267) DEBUG: name = flip last_ts = 312.160828 last_received_ts = 312.160400 last_seq = 286 current_ts = 312.177521 current_received_ts = 312.177277 current_seq = 287 count = 49 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 312.177521 last_received_ts = 312.177277 last_seq = 287 current_ts = 312.194153 current_received_ts = 312.193817 current_seq = 288 count = 50 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 53us (kms_flip:2267) DEBUG: name = flip last_ts = 312.194153 last_received_ts = 312.193817 last_seq = 288 current_ts = 312.210846 current_received_ts = 312.210449 current_seq = 289 count = 51 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.210846 last_received_ts = 312.210449 last_seq = 289 current_ts = 312.227509 current_received_ts = 312.227295 current_seq = 290 count = 52 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.227509 last_received_ts = 312.227295 last_seq = 290 current_ts = 312.244171 current_received_ts = 312.243927 current_seq = 291 count = 53 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 79us (kms_flip:2267) DEBUG: name = flip last_ts = 312.244171 last_received_ts = 312.243927 last_seq = 291 current_ts = 312.260834 current_received_ts = 312.260468 current_seq = 292 count = 54 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.260834 last_received_ts = 312.260468 last_seq = 292 current_ts = 312.277496 current_received_ts = 312.277161 current_seq = 293 count = 55 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.277496 last_received_ts = 312.277161 last_seq = 293 current_ts = 312.294159 current_received_ts = 312.293945 current_seq = 294 count = 56 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 77us (kms_flip:2267) DEBUG: name = flip last_ts = 312.294159 last_received_ts = 312.293945 last_seq = 294 current_ts = 312.310852 current_received_ts = 312.310364 current_seq = 295 count = 57 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 51us (kms_flip:2267) DEBUG: name = flip last_ts = 312.310852 last_received_ts = 312.310364 last_seq = 295 current_ts = 312.327515 current_received_ts = 312.327148 current_seq = 296 count = 58 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 53us (kms_flip:2267) DEBUG: name = flip last_ts = 312.327515 last_received_ts = 312.327148 last_seq = 296 current_ts = 312.344177 current_received_ts = 312.343933 current_seq = 297 count = 59 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 81us (kms_flip:2267) DEBUG: name = flip last_ts = 312.344177 last_received_ts = 312.343933 last_seq = 297 current_ts = 312.360840 current_received_ts = 312.360382 current_seq = 298 count = 60 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 51us (kms_flip:2267) DEBUG: name = flip last_ts = 312.360840 last_received_ts = 312.360382 last_seq = 298 current_ts = 312.377502 current_received_ts = 312.377167 current_seq = 299 count = 61 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.377502 last_received_ts = 312.377167 last_seq = 299 current_ts = 312.394165 current_received_ts = 312.393829 current_seq = 300 count = 62 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.394165 last_received_ts = 312.393829 last_seq = 300 current_ts = 312.410828 current_received_ts = 312.410492 current_seq = 301 count = 63 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.410828 last_received_ts = 312.410492 last_seq = 301 current_ts = 312.427521 current_received_ts = 312.427155 current_seq = 302 count = 64 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 312.427521 last_received_ts = 312.427155 last_seq = 302 current_ts = 312.444183 current_received_ts = 312.443939 current_seq = 303 count = 65 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 88us (kms_flip:2267) DEBUG: name = flip last_ts = 312.444183 last_received_ts = 312.443939 last_seq = 303 current_ts = 312.460846 current_received_ts = 312.460449 current_seq = 304 count = 66 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.460846 last_received_ts = 312.460449 last_seq = 304 current_ts = 312.477509 current_received_ts = 312.477142 current_seq = 305 count = 67 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.477509 last_received_ts = 312.477142 last_seq = 305 current_ts = 312.494171 current_received_ts = 312.493958 current_seq = 306 count = 68 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 84us (kms_flip:2267) DEBUG: name = flip last_ts = 312.494171 last_received_ts = 312.493958 last_seq = 306 current_ts = 312.510864 current_received_ts = 312.510590 current_seq = 307 count = 69 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.510864 last_received_ts = 312.510590 last_seq = 307 current_ts = 312.527496 current_received_ts = 312.527161 current_seq = 308 count = 70 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 53us (kms_flip:2267) DEBUG: name = flip last_ts = 312.527496 last_received_ts = 312.527161 last_seq = 308 current_ts = 312.544189 current_received_ts = 312.543854 current_seq = 309 count = 71 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.544189 last_received_ts = 312.543854 last_seq = 309 current_ts = 312.560852 current_received_ts = 312.560455 current_seq = 310 count = 72 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.560852 last_received_ts = 312.560455 last_seq = 310 current_ts = 312.577515 current_received_ts = 312.577179 current_seq = 311 count = 73 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.577515 last_received_ts = 312.577179 last_seq = 311 current_ts = 312.594208 current_received_ts = 312.593933 current_seq = 312 count = 74 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 81us (kms_flip:2267) DEBUG: name = flip last_ts = 312.594208 last_received_ts = 312.593933 last_seq = 312 current_ts = 312.610870 current_received_ts = 312.610474 current_seq = 313 count = 75 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 53us (kms_flip:2267) DEBUG: name = flip last_ts = 312.610870 last_received_ts = 312.610474 last_seq = 313 current_ts = 312.627533 current_received_ts = 312.627167 current_seq = 314 count = 76 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.627533 last_received_ts = 312.627167 last_seq = 314 current_ts = 312.644196 current_received_ts = 312.643829 current_seq = 315 count = 77 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.644196 last_received_ts = 312.643829 last_seq = 315 current_ts = 312.660858 current_received_ts = 312.660583 current_seq = 316 count = 78 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.660858 last_received_ts = 312.660583 last_seq = 316 current_ts = 312.677521 current_received_ts = 312.677155 current_seq = 317 count = 79 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 312.677521 last_received_ts = 312.677155 last_seq = 317 current_ts = 312.694183 current_received_ts = 312.693939 current_seq = 318 count = 80 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 82us (kms_flip:2267) DEBUG: name = flip last_ts = 312.694183 last_received_ts = 312.693939 last_seq = 318 current_ts = 312.710876 current_received_ts = 312.710480 current_seq = 319 count = 81 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 53us (kms_flip:2267) DEBUG: name = flip last_ts = 312.710876 last_received_ts = 312.710480 last_seq = 319 current_ts = 312.727509 current_received_ts = 312.727325 current_seq = 320 count = 82 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.727509 last_received_ts = 312.727325 last_seq = 320 current_ts = 312.744202 current_received_ts = 312.743835 current_seq = 321 count = 83 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.744202 last_received_ts = 312.743835 last_seq = 321 current_ts = 312.760864 current_received_ts = 312.760468 current_seq = 322 count = 84 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.760864 last_received_ts = 312.760468 last_seq = 322 current_ts = 312.777527 current_received_ts = 312.777191 current_seq = 323 count = 85 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.777527 last_received_ts = 312.777191 last_seq = 323 current_ts = 312.794189 current_received_ts = 312.793976 current_seq = 324 count = 86 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 92us (kms_flip:2267) DEBUG: name = flip last_ts = 312.794189 last_received_ts = 312.793976 last_seq = 324 current_ts = 312.810852 current_received_ts = 312.810425 current_seq = 325 count = 87 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 53us (kms_flip:2267) DEBUG: name = flip last_ts = 312.810852 last_received_ts = 312.810425 last_seq = 325 current_ts = 312.827545 current_received_ts = 312.827179 current_seq = 326 count = 88 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 56us (kms_flip:2267) DEBUG: name = flip last_ts = 312.827545 last_received_ts = 312.827179 last_seq = 326 current_ts = 312.844208 current_received_ts = 312.843872 current_seq = 327 count = 89 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 312.844208 last_received_ts = 312.843872 last_seq = 327 current_ts = 312.860870 current_received_ts = 312.860474 current_seq = 328 count = 90 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.860870 last_received_ts = 312.860474 last_seq = 328 current_ts = 312.877533 current_received_ts = 312.877350 current_seq = 329 count = 91 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 312.877533 last_received_ts = 312.877350 last_seq = 329 current_ts = 312.894196 current_received_ts = 312.893982 current_seq = 330 count = 92 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 56us (kms_flip:2267) DEBUG: name = flip last_ts = 312.894196 last_received_ts = 312.893982 last_seq = 330 current_ts = 312.910889 current_received_ts = 312.910583 current_seq = 331 count = 93 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 312.910889 last_received_ts = 312.910583 last_seq = 331 current_ts = 312.927551 current_received_ts = 312.927124 current_seq = 332 count = 94 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 52us (kms_flip:2267) DEBUG: name = flip last_ts = 312.927551 last_received_ts = 312.927124 last_seq = 332 current_ts = 312.944214 current_received_ts = 312.943848 current_seq = 333 count = 95 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 312.944214 last_received_ts = 312.943848 last_seq = 333 current_ts = 312.960876 current_received_ts = 312.960571 current_seq = 334 count = 96 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 312.960876 last_received_ts = 312.960571 last_seq = 334 current_ts = 312.977539 current_received_ts = 312.977356 current_seq = 335 count = 97 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 56us (kms_flip:2267) DEBUG: name = flip last_ts = 312.977539 last_received_ts = 312.977356 last_seq = 335 current_ts = 312.994202 current_received_ts = 312.993988 current_seq = 336 count = 98 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 56us (kms_flip:2267) DEBUG: name = flip last_ts = 312.994202 last_received_ts = 312.993988 last_seq = 336 current_ts = 313.010895 current_received_ts = 313.010498 current_seq = 337 count = 99 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.010895 last_received_ts = 313.010498 last_seq = 337 current_ts = 313.027527 current_received_ts = 313.027191 current_seq = 338 count = 100 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.027527 last_received_ts = 313.027191 last_seq = 338 current_ts = 313.044220 current_received_ts = 313.043854 current_seq = 339 count = 101 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.044220 last_received_ts = 313.043854 last_seq = 339 current_ts = 313.060883 current_received_ts = 313.060608 current_seq = 340 count = 102 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.060883 last_received_ts = 313.060608 last_seq = 340 current_ts = 313.077545 current_received_ts = 313.077362 current_seq = 341 count = 103 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.077545 last_received_ts = 313.077362 last_seq = 341 current_ts = 313.094208 current_received_ts = 313.093872 current_seq = 342 count = 104 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.094208 last_received_ts = 313.093872 last_seq = 342 current_ts = 313.110870 current_received_ts = 313.110474 current_seq = 343 count = 105 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.110870 last_received_ts = 313.110474 last_seq = 343 current_ts = 313.127533 current_received_ts = 313.127228 current_seq = 344 count = 106 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.127533 last_received_ts = 313.127228 last_seq = 344 current_ts = 313.144226 current_received_ts = 313.143890 current_seq = 345 count = 107 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.144226 last_received_ts = 313.143890 last_seq = 345 current_ts = 313.160889 current_received_ts = 313.160461 current_seq = 346 count = 108 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.160889 last_received_ts = 313.160461 last_seq = 346 current_ts = 313.177551 current_received_ts = 313.177338 current_seq = 347 count = 109 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.177551 last_received_ts = 313.177338 last_seq = 347 current_ts = 313.194214 current_received_ts = 313.194000 current_seq = 348 count = 110 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 57us (kms_flip:2267) DEBUG: name = flip last_ts = 313.194214 last_received_ts = 313.194000 last_seq = 348 current_ts = 313.210876 current_received_ts = 313.210480 current_seq = 349 count = 111 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.210876 last_received_ts = 313.210480 last_seq = 349 current_ts = 313.227539 current_received_ts = 313.227234 current_seq = 350 count = 112 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.227539 last_received_ts = 313.227234 last_seq = 350 current_ts = 313.244232 current_received_ts = 313.243988 current_seq = 351 count = 113 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 57us (kms_flip:2267) DEBUG: name = flip last_ts = 313.244232 last_received_ts = 313.243988 last_seq = 351 current_ts = 313.260895 current_received_ts = 313.260529 current_seq = 352 count = 114 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.260895 last_received_ts = 313.260529 last_seq = 352 current_ts = 313.277557 current_received_ts = 313.277374 current_seq = 353 count = 115 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.277557 last_received_ts = 313.277374 last_seq = 353 current_ts = 313.294220 current_received_ts = 313.293854 current_seq = 354 count = 116 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 52us (kms_flip:2267) DEBUG: name = flip last_ts = 313.294220 last_received_ts = 313.293854 last_seq = 354 current_ts = 313.310883 current_received_ts = 313.310486 current_seq = 355 count = 117 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.310883 last_received_ts = 313.310486 last_seq = 355 current_ts = 313.327545 current_received_ts = 313.327209 current_seq = 356 count = 118 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.327545 last_received_ts = 313.327209 last_seq = 356 current_ts = 313.344208 current_received_ts = 313.343994 current_seq = 357 count = 119 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.344208 last_received_ts = 313.343994 last_seq = 357 current_ts = 313.360901 current_received_ts = 313.360535 current_seq = 358 count = 120 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.360901 last_received_ts = 313.360535 last_seq = 358 current_ts = 313.377563 current_received_ts = 313.377350 current_seq = 359 count = 121 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.377563 last_received_ts = 313.377350 last_seq = 359 current_ts = 313.394226 current_received_ts = 313.393890 current_seq = 360 count = 122 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.394226 last_received_ts = 313.393890 last_seq = 360 current_ts = 313.410889 current_received_ts = 313.410553 current_seq = 361 count = 123 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.410889 last_received_ts = 313.410553 last_seq = 361 current_ts = 313.427551 current_received_ts = 313.427368 current_seq = 362 count = 124 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.427551 last_received_ts = 313.427368 last_seq = 362 current_ts = 313.444214 current_received_ts = 313.444031 current_seq = 363 count = 125 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 57us (kms_flip:2267) DEBUG: name = flip last_ts = 313.444214 last_received_ts = 313.444031 last_seq = 363 current_ts = 313.460907 current_received_ts = 313.460602 current_seq = 364 count = 126 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.460907 last_received_ts = 313.460602 last_seq = 364 current_ts = 313.477570 current_received_ts = 313.477142 current_seq = 365 count = 127 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 51us (kms_flip:2267) DEBUG: name = flip last_ts = 313.477570 last_received_ts = 313.477142 last_seq = 365 current_ts = 313.494232 current_received_ts = 313.493683 current_seq = 366 count = 128 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 47us (kms_flip:2267) DEBUG: name = flip last_ts = 313.494232 last_received_ts = 313.493683 last_seq = 366 current_ts = 313.510895 current_received_ts = 313.510376 current_seq = 367 count = 129 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 32us (kms_flip:2267) DEBUG: name = flip last_ts = 313.510895 last_received_ts = 313.510376 last_seq = 367 current_ts = 313.527557 current_received_ts = 313.527069 current_seq = 368 count = 130 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 45us (kms_flip:2267) DEBUG: name = flip last_ts = 313.527557 last_received_ts = 313.527069 last_seq = 368 current_ts = 313.544220 current_received_ts = 313.543732 current_seq = 369 count = 131 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 45us (kms_flip:2267) DEBUG: name = flip last_ts = 313.544220 last_received_ts = 313.543732 last_seq = 369 current_ts = 313.560913 current_received_ts = 313.560364 current_seq = 370 count = 132 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 49us (kms_flip:2267) DEBUG: name = flip last_ts = 313.560913 last_received_ts = 313.560364 last_seq = 370 current_ts = 313.577576 current_received_ts = 313.577057 current_seq = 371 count = 133 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 46us (kms_flip:2267) DEBUG: name = flip last_ts = 313.577576 last_received_ts = 313.577057 last_seq = 371 current_ts = 313.594238 current_received_ts = 313.593719 current_seq = 372 count = 134 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 33us (kms_flip:2267) DEBUG: name = flip last_ts = 313.594238 last_received_ts = 313.593719 last_seq = 372 current_ts = 313.610901 current_received_ts = 313.610352 current_seq = 373 count = 135 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 33us (kms_flip:2267) DEBUG: name = flip last_ts = 313.610901 last_received_ts = 313.610352 last_seq = 373 current_ts = 313.627563 current_received_ts = 313.627136 current_seq = 374 count = 136 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 32us (kms_flip:2267) DEBUG: name = flip last_ts = 313.627563 last_received_ts = 313.627136 last_seq = 374 current_ts = 313.644226 current_received_ts = 313.643799 current_seq = 375 count = 137 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 31us (kms_flip:2267) DEBUG: name = flip last_ts = 313.644226 last_received_ts = 313.643799 last_seq = 375 current_ts = 313.660919 current_received_ts = 313.660461 current_seq = 376 count = 138 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 34us (kms_flip:2267) DEBUG: name = flip last_ts = 313.660919 last_received_ts = 313.660461 last_seq = 376 current_ts = 313.677582 current_received_ts = 313.677155 current_seq = 377 count = 139 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 38us (kms_flip:2267) DEBUG: name = flip last_ts = 313.677582 last_received_ts = 313.677155 last_seq = 377 current_ts = 313.694244 current_received_ts = 313.693878 current_seq = 378 count = 140 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 48us (kms_flip:2267) DEBUG: name = flip last_ts = 313.694244 last_received_ts = 313.693878 last_seq = 378 current_ts = 313.710907 current_received_ts = 313.710602 current_seq = 379 count = 141 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.710907 last_received_ts = 313.710602 last_seq = 379 current_ts = 313.727570 current_received_ts = 313.727234 current_seq = 380 count = 142 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 53us (kms_flip:2267) DEBUG: name = flip last_ts = 313.727570 last_received_ts = 313.727234 last_seq = 380 current_ts = 313.744232 current_received_ts = 313.743896 current_seq = 381 count = 143 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 53us (kms_flip:2267) DEBUG: name = flip last_ts = 313.744232 last_received_ts = 313.743896 last_seq = 381 current_ts = 313.760895 current_received_ts = 313.760437 current_seq = 382 count = 144 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.760895 last_received_ts = 313.760437 last_seq = 382 current_ts = 313.777588 current_received_ts = 313.777374 current_seq = 383 count = 145 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.777588 last_received_ts = 313.777374 last_seq = 383 current_ts = 313.794250 current_received_ts = 313.794037 current_seq = 384 count = 146 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.794250 last_received_ts = 313.794037 last_seq = 384 current_ts = 313.810913 current_received_ts = 313.810486 current_seq = 385 count = 147 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.810913 last_received_ts = 313.810486 last_seq = 385 current_ts = 313.827576 current_received_ts = 313.827240 current_seq = 386 count = 148 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.827576 last_received_ts = 313.827240 last_seq = 386 current_ts = 313.844238 current_received_ts = 313.844025 current_seq = 387 count = 149 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.844238 last_received_ts = 313.844025 last_seq = 387 current_ts = 313.860901 current_received_ts = 313.860474 current_seq = 388 count = 150 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 56us (kms_flip:2267) DEBUG: name = flip last_ts = 313.860901 last_received_ts = 313.860474 last_seq = 388 current_ts = 313.877594 current_received_ts = 313.877380 current_seq = 389 count = 151 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 54us (kms_flip:2267) DEBUG: name = flip last_ts = 313.877594 last_received_ts = 313.877380 last_seq = 389 current_ts = 313.894257 current_received_ts = 313.894043 current_seq = 390 count = 152 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 55us (kms_flip:2267) DEBUG: name = flip last_ts = 313.894257 last_received_ts = 313.894043 last_seq = 390 current_ts = 313.910919 current_received_ts = 313.910492 current_seq = 391 count = 153 seq_step = 1 (kms_flip:2267) DEBUG: Vblank took 567us (kms_flip:2267) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2267) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2267) igt_core-INFO: Stack trace: (kms_flip:2267) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2267) igt_core-INFO: #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0() (kms_flip:2267) igt_core-INFO: #2 ../tests/kms_flip.c:1887 run_test() (kms_flip:2267) igt_core-INFO: #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043() (kms_flip:2267) igt_core-INFO: #4 ../tests/kms_flip.c:2043 main() (kms_flip:2267) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2267) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2267) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A3: FAIL (2.956s)
Dmesg	<6> [310.939971] [IGT] kms_flip: starting dynamic subtest B-HDMI-A3 <7> [310.940485] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:560] <7> [310.940680] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:562] <7> [310.941137] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [310.941708] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [310.963238] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [310.963598] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [310.970283] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [310.970621] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [310.991389] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [310.991732] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [311.018823] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:150:pipe A] <7> [311.018940] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [311.019170] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [311.019374] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [311.019576] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [311.019794] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [311.020008] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [311.020208] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [311.020407] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [311.020607] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [311.020849] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [311.021048] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [311.021247] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [311.021445] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [311.021644] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [311.021891] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [311.022090] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [311.022290] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [311.022489] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [311.022688] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [311.022926] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [311.023125] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [311.023324] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [311.023522] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [311.023721] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [311.023960] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [311.024160] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [311.024358] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [311.024557] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [311.024780] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [311.025026] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [311.025225] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [311.025424] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [311.025623] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [311.025866] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [311.026065] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [311.026263] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [311.026462] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:150:pipe A] fastset requirement not met in port_clock (expected 148500, found 0) <7> [311.026661] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:150:pipe A] fastset requirement not met, forcing full modeset <7> [311.026923] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0xf), mbus joined? no->no <7> [311.027113] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:150:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [311.027326] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:144:cursor A] ddb (1963 - 2048) -> ( 0 - 0), size 85 -> 0 <7> [311.027546] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:150:pipe A] min cdclk: 74250 kHz -> 0 kHz <7> [311.027777] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz <7> [311.027990] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [311.028189] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:150:pipe A] enable: no [modeset] <7> [311.028388] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:34:plane 1A] fb: [NOFB], visible: no <7> [311.028586] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:64:plane 2A] fb: [NOFB], visible: no <7> [311.028826] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:94:plane 3A] fb: [NOFB], visible: no <7> [311.029023] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:124:plane 4A] fb: [NOFB], visible: no <7> [311.029222] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:134:plane 5A] fb: [NOFB], visible: no <7> [311.029419] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:144:cursor A] fb: [NOFB], visible: no <7> [311.029731] i915 0000:03:00.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [311.038945] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_D <7> [311.039207] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:506:DDI A/PHY A] <7> [311.039403] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:508:DP-MST A] <7> [311.039597] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST B] <7> [311.039809] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST C] <7> [311.040002] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:511:DP-MST D] <7> [311.040195] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:519:DDI B/PHY B] <7> [311.040387] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST A] <7> [311.040579] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST B] <7> [311.040778] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST C] <7> [311.040973] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:524:DP-MST D] <7> [311.041165] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:534:DDI C/PHY C] <7> [311.041358] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST A] <7> [311.041550] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST B] <7> [311.041748] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST C] <7> [311.041975] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST D] <7> [311.042168] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:546:DDI D/PHY D] <7> [311.042379] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST A] <7> [311.042572] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST B] <7> [311.042804] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST C] <7> [311.042997] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST D] <7> [311.043189] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:555:HDMI-A-3] <7> [311.043419] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [311.043721] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_A <7> [311.044026] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [311.044268] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:150:pipe A] <7> [311.044655] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B] <7> [311.044850] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:386:pipe C] <7> [311.044989] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:504:pipe D] <7> [311.045130] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B] <7> [311.045160] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:555:HDMI-A-3] <7> [311.045224] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CONNECTOR:555:HDMI-A-3] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 36, max platform bpp 36) <7> [311.045437] i915 0000:03:00.0: [drm:intel_hdmi_compute_clock [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [311.045621] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:268:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [311.045869] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:546:DDI D/PHY D] [CRTC:268:pipe B] <7> [311.046057] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [311.046257] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [311.046456] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [311.046656] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [311.046898] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [311.047098] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [311.047297] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [311.047496] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [311.047696] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [311.047983] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [311.048215] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [311.048414] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [311.048613] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [311.048852] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [311.049052] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [311.049251] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [311.049450] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [311.049649] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [311.049907] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [311.050106] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [311.050305] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [311.050504] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [311.050703] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [311.050943] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [311.051143] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [311.051341] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [311.051540] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [311.051745] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [311.051979] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [311.052178] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [311.052376] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [311.052575] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [311.052812] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [311.053012] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [311.053211] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [311.053411] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [311.053609] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:268:pipe B] fastset requirement not met in port_clock (expected 0, found 148500) <7> [311.053849] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:268:pipe B] fastset requirement not met, forcing full modeset <7> [311.054071] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0xf), mbus joined? no->no <7> [311.054261] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:268:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2 <7> [311.054474] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:152:plane 1B] ddb ( 0 - 0) -> ( 0 - 1963), size 0 -> 1963 <7> [311.054662] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [PLANE:262:cursor B] ddb ( 0 - 0) -> (1963 - 2048), size 0 -> 85 <7> [311.054857] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:152: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> [311.055046] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:152: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> [311.055235] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:152: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> [311.055425] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:152: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> [311.055630] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:268:pipe B] data rate 594000 num active planes 1 <7> [311.055901] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 50000 required 624 <7> [311.056099] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [311.056310] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:268:pipe B] min cdclk: 0 kHz -> 74250 kHz <7> [311.056523] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz <7> [311.056721] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [311.056960] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:268:pipe B] enable: yes [modeset] <7> [311.057160] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [311.057358] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [311.057557] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [311.057780] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [311.057992] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [311.058189] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [311.058386] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0 <7> [311.058584] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [311.058821] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [311.059018] 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> [311.059217] 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> [311.059415] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [311.059612] 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> [311.059850] 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> [311.060049] 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> [311.060249] 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> [311.060448] 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> [311.060647] 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> [311.060887] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] linetime: 119, ips linetime: 0 <7> [311.061085] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [311.061283] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [311.061481] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [311.061679] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x24414, dpll_md: 0x18000000, fp0: 0x8801ef8, fp1: 0x2b000440 <7> [311.061917] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [311.062115] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [311.062314] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [311.062511] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [311.062708] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [311.062947] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [311.063007] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DC_off <7> [311.063145] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [311.063249] i915 0000:03:00.0: [drm:gen9_enable_dc5 [i915]] Enabling DC5 <7> [311.063344] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [311.063453] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 01 <7> [311.063541] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [311.063892] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [311.064123] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [311.064321] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [311.064519] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [311.064717] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:152:plane 1B] fb: [FB:560] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [311.064959] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [311.065157] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [311.065356] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:182:plane 2B] fb: [NOFB], visible: no <7> [311.065555] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:212:plane 3B] fb: [NOFB], visible: no <7> [311.065760] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:242:plane 4B] fb: [NOFB], visible: no <7> [311.065997] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:252:plane 5B] fb: [NOFB], visible: no <7> [311.066196] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:262:cursor B] fb: [NOFB], visible: no <7> [311.066846] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DC_off <7> [311.067171] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 01 to 00 <7> [311.067557] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [311.067813] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_B <7> [311.068059] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:506:DDI A/PHY A] <7> [311.068252] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:508:DP-MST A] <7> [311.068445] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST B] <7> [311.068637] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST C] <7> [311.068869] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:511:DP-MST D] <7> [311.069064] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:519:DDI B/PHY B] <7> [311.069257] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST A] <7> [311.069450] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST B] <7> [311.069642] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST C] <7> [311.069874] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:524:DP-MST D] <7> [311.070067] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:534:DDI C/PHY C] <7> [311.070259] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST A] <7> [311.070451] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST B] <7> [311.070643] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST C] <7> [311.070874] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST D] <7> [311.071067] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:546:DDI D/PHY D] <7> [311.071260] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:548:DP-MST A] <7> [311.071452] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST B] <7> [311.071644] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST C] <7> [311.071879] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST D] <7> [311.072072] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [311.072488] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_D <7> [311.072913] i915 0000:03:00.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [311.092004] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:555:HDMI-A-3] <7> [311.092314] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:268:pipe B] <6> [313.896495] [IGT] kms_flip: finished subtest B-HDMI-A3, FAIL

Detail

Value

Duration

2.96 seconds

Hostname

shard-dg2-1

Igt-Version

IGT-Version: 2.3-g07ca77c0e (x86_64) (Linux: 6.19.0-CI_DRM_17988-g0558a31efefc+ 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:921 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1887 run_test()
  #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043()
  #4 ../tests/kms_flip.c:2043 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A3: FAIL (2.956s)

Err

Starting dynamic subtest: B-HDMI-A3
(kms_flip:2267) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2267) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2267) DEBUG: name = flip
last_ts = 311.877472
last_received_ts = 311.877258
last_seq = 269
current_ts = 311.894165
current_received_ts = 311.893799
current_seq = 270
count = 32
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 53us
(kms_flip:2267) DEBUG: name = flip
last_ts = 311.894165
last_received_ts = 311.893799
last_seq = 270
current_ts = 311.910828
current_received_ts = 311.910431
current_seq = 271
count = 33
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 311.910828
last_received_ts = 311.910431
last_seq = 271
current_ts = 311.927490
current_received_ts = 311.927155
current_seq = 272
count = 34
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 311.927490
last_received_ts = 311.927155
last_seq = 272
current_ts = 311.944153
current_received_ts = 311.943817
current_seq = 273
count = 35
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 311.944153
last_received_ts = 311.943817
last_seq = 273
current_ts = 311.960846
current_received_ts = 311.960419
current_seq = 274
count = 36
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 51us
(kms_flip:2267) DEBUG: name = flip
last_ts = 311.960846
last_received_ts = 311.960419
last_seq = 274
current_ts = 311.977478
current_received_ts = 311.977142
current_seq = 275
count = 37
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 311.977478
last_received_ts = 311.977142
last_seq = 275
current_ts = 311.994171
current_received_ts = 311.993896
current_seq = 276
count = 38
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 85us
(kms_flip:2267) DEBUG: name = flip
last_ts = 311.994171
last_received_ts = 311.993896
last_seq = 276
current_ts = 312.010834
current_received_ts = 312.010437
current_seq = 277
count = 39
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 53us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.010834
last_received_ts = 312.010437
last_seq = 277
current_ts = 312.027496
current_received_ts = 312.027130
current_seq = 278
count = 40
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.027496
last_received_ts = 312.027130
last_seq = 278
current_ts = 312.044159
current_received_ts = 312.043793
current_seq = 279
count = 41
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.044159
last_received_ts = 312.043793
last_seq = 279
current_ts = 312.060822
current_received_ts = 312.060455
current_seq = 280
count = 42
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.060822
last_received_ts = 312.060455
last_seq = 280
current_ts = 312.077515
current_received_ts = 312.077271
current_seq = 281
count = 43
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.077515
last_received_ts = 312.077271
last_seq = 281
current_ts = 312.094177
current_received_ts = 312.093903
current_seq = 282
count = 44
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 84us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.094177
last_received_ts = 312.093903
last_seq = 282
current_ts = 312.110840
current_received_ts = 312.110443
current_seq = 283
count = 45
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.110840
last_received_ts = 312.110443
last_seq = 283
current_ts = 312.127502
current_received_ts = 312.127167
current_seq = 284
count = 46
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.127502
last_received_ts = 312.127167
last_seq = 284
current_ts = 312.144165
current_received_ts = 312.143829
current_seq = 285
count = 47
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.144165
last_received_ts = 312.143829
last_seq = 285
current_ts = 312.160828
current_received_ts = 312.160400
current_seq = 286
count = 48
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 53us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.160828
last_received_ts = 312.160400
last_seq = 286
current_ts = 312.177521
current_received_ts = 312.177277
current_seq = 287
count = 49
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.177521
last_received_ts = 312.177277
last_seq = 287
current_ts = 312.194153
current_received_ts = 312.193817
current_seq = 288
count = 50
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 53us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.194153
last_received_ts = 312.193817
last_seq = 288
current_ts = 312.210846
current_received_ts = 312.210449
current_seq = 289
count = 51
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.210846
last_received_ts = 312.210449
last_seq = 289
current_ts = 312.227509
current_received_ts = 312.227295
current_seq = 290
count = 52
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.227509
last_received_ts = 312.227295
last_seq = 290
current_ts = 312.244171
current_received_ts = 312.243927
current_seq = 291
count = 53
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 79us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.244171
last_received_ts = 312.243927
last_seq = 291
current_ts = 312.260834
current_received_ts = 312.260468
current_seq = 292
count = 54
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.260834
last_received_ts = 312.260468
last_seq = 292
current_ts = 312.277496
current_received_ts = 312.277161
current_seq = 293
count = 55
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.277496
last_received_ts = 312.277161
last_seq = 293
current_ts = 312.294159
current_received_ts = 312.293945
current_seq = 294
count = 56
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 77us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.294159
last_received_ts = 312.293945
last_seq = 294
current_ts = 312.310852
current_received_ts = 312.310364
current_seq = 295
count = 57
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 51us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.310852
last_received_ts = 312.310364
last_seq = 295
current_ts = 312.327515
current_received_ts = 312.327148
current_seq = 296
count = 58
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 53us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.327515
last_received_ts = 312.327148
last_seq = 296
current_ts = 312.344177
current_received_ts = 312.343933
current_seq = 297
count = 59
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 81us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.344177
last_received_ts = 312.343933
last_seq = 297
current_ts = 312.360840
current_received_ts = 312.360382
current_seq = 298
count = 60
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 51us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.360840
last_received_ts = 312.360382
last_seq = 298
current_ts = 312.377502
current_received_ts = 312.377167
current_seq = 299
count = 61
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.377502
last_received_ts = 312.377167
last_seq = 299
current_ts = 312.394165
current_received_ts = 312.393829
current_seq = 300
count = 62
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.394165
last_received_ts = 312.393829
last_seq = 300
current_ts = 312.410828
current_received_ts = 312.410492
current_seq = 301
count = 63
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.410828
last_received_ts = 312.410492
last_seq = 301
current_ts = 312.427521
current_received_ts = 312.427155
current_seq = 302
count = 64
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.427521
last_received_ts = 312.427155
last_seq = 302
current_ts = 312.444183
current_received_ts = 312.443939
current_seq = 303
count = 65
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 88us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.444183
last_received_ts = 312.443939
last_seq = 303
current_ts = 312.460846
current_received_ts = 312.460449
current_seq = 304
count = 66
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.460846
last_received_ts = 312.460449
last_seq = 304
current_ts = 312.477509
current_received_ts = 312.477142
current_seq = 305
count = 67
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.477509
last_received_ts = 312.477142
last_seq = 305
current_ts = 312.494171
current_received_ts = 312.493958
current_seq = 306
count = 68
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 84us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.494171
last_received_ts = 312.493958
last_seq = 306
current_ts = 312.510864
current_received_ts = 312.510590
current_seq = 307
count = 69
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.510864
last_received_ts = 312.510590
last_seq = 307
current_ts = 312.527496
current_received_ts = 312.527161
current_seq = 308
count = 70
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 53us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.527496
last_received_ts = 312.527161
last_seq = 308
current_ts = 312.544189
current_received_ts = 312.543854
current_seq = 309
count = 71
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.544189
last_received_ts = 312.543854
last_seq = 309
current_ts = 312.560852
current_received_ts = 312.560455
current_seq = 310
count = 72
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.560852
last_received_ts = 312.560455
last_seq = 310
current_ts = 312.577515
current_received_ts = 312.577179
current_seq = 311
count = 73
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.577515
last_received_ts = 312.577179
last_seq = 311
current_ts = 312.594208
current_received_ts = 312.593933
current_seq = 312
count = 74
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 81us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.594208
last_received_ts = 312.593933
last_seq = 312
current_ts = 312.610870
current_received_ts = 312.610474
current_seq = 313
count = 75
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 53us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.610870
last_received_ts = 312.610474
last_seq = 313
current_ts = 312.627533
current_received_ts = 312.627167
current_seq = 314
count = 76
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.627533
last_received_ts = 312.627167
last_seq = 314
current_ts = 312.644196
current_received_ts = 312.643829
current_seq = 315
count = 77
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.644196
last_received_ts = 312.643829
last_seq = 315
current_ts = 312.660858
current_received_ts = 312.660583
current_seq = 316
count = 78
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.660858
last_received_ts = 312.660583
last_seq = 316
current_ts = 312.677521
current_received_ts = 312.677155
current_seq = 317
count = 79
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.677521
last_received_ts = 312.677155
last_seq = 317
current_ts = 312.694183
current_received_ts = 312.693939
current_seq = 318
count = 80
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 82us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.694183
last_received_ts = 312.693939
last_seq = 318
current_ts = 312.710876
current_received_ts = 312.710480
current_seq = 319
count = 81
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 53us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.710876
last_received_ts = 312.710480
last_seq = 319
current_ts = 312.727509
current_received_ts = 312.727325
current_seq = 320
count = 82
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.727509
last_received_ts = 312.727325
last_seq = 320
current_ts = 312.744202
current_received_ts = 312.743835
current_seq = 321
count = 83
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.744202
last_received_ts = 312.743835
last_seq = 321
current_ts = 312.760864
current_received_ts = 312.760468
current_seq = 322
count = 84
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.760864
last_received_ts = 312.760468
last_seq = 322
current_ts = 312.777527
current_received_ts = 312.777191
current_seq = 323
count = 85
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.777527
last_received_ts = 312.777191
last_seq = 323
current_ts = 312.794189
current_received_ts = 312.793976
current_seq = 324
count = 86
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 92us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.794189
last_received_ts = 312.793976
last_seq = 324
current_ts = 312.810852
current_received_ts = 312.810425
current_seq = 325
count = 87
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 53us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.810852
last_received_ts = 312.810425
last_seq = 325
current_ts = 312.827545
current_received_ts = 312.827179
current_seq = 326
count = 88
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 56us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.827545
last_received_ts = 312.827179
last_seq = 326
current_ts = 312.844208
current_received_ts = 312.843872
current_seq = 327
count = 89
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.844208
last_received_ts = 312.843872
last_seq = 327
current_ts = 312.860870
current_received_ts = 312.860474
current_seq = 328
count = 90
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.860870
last_received_ts = 312.860474
last_seq = 328
current_ts = 312.877533
current_received_ts = 312.877350
current_seq = 329
count = 91
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.877533
last_received_ts = 312.877350
last_seq = 329
current_ts = 312.894196
current_received_ts = 312.893982
current_seq = 330
count = 92
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 56us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.894196
last_received_ts = 312.893982
last_seq = 330
current_ts = 312.910889
current_received_ts = 312.910583
current_seq = 331
count = 93
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.910889
last_received_ts = 312.910583
last_seq = 331
current_ts = 312.927551
current_received_ts = 312.927124
current_seq = 332
count = 94
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 52us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.927551
last_received_ts = 312.927124
last_seq = 332
current_ts = 312.944214
current_received_ts = 312.943848
current_seq = 333
count = 95
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.944214
last_received_ts = 312.943848
last_seq = 333
current_ts = 312.960876
current_received_ts = 312.960571
current_seq = 334
count = 96
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.960876
last_received_ts = 312.960571
last_seq = 334
current_ts = 312.977539
current_received_ts = 312.977356
current_seq = 335
count = 97
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 56us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.977539
last_received_ts = 312.977356
last_seq = 335
current_ts = 312.994202
current_received_ts = 312.993988
current_seq = 336
count = 98
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 56us
(kms_flip:2267) DEBUG: name = flip
last_ts = 312.994202
last_received_ts = 312.993988
last_seq = 336
current_ts = 313.010895
current_received_ts = 313.010498
current_seq = 337
count = 99
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.010895
last_received_ts = 313.010498
last_seq = 337
current_ts = 313.027527
current_received_ts = 313.027191
current_seq = 338
count = 100
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.027527
last_received_ts = 313.027191
last_seq = 338
current_ts = 313.044220
current_received_ts = 313.043854
current_seq = 339
count = 101
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.044220
last_received_ts = 313.043854
last_seq = 339
current_ts = 313.060883
current_received_ts = 313.060608
current_seq = 340
count = 102
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.060883
last_received_ts = 313.060608
last_seq = 340
current_ts = 313.077545
current_received_ts = 313.077362
current_seq = 341
count = 103
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.077545
last_received_ts = 313.077362
last_seq = 341
current_ts = 313.094208
current_received_ts = 313.093872
current_seq = 342
count = 104
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.094208
last_received_ts = 313.093872
last_seq = 342
current_ts = 313.110870
current_received_ts = 313.110474
current_seq = 343
count = 105
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.110870
last_received_ts = 313.110474
last_seq = 343
current_ts = 313.127533
current_received_ts = 313.127228
current_seq = 344
count = 106
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.127533
last_received_ts = 313.127228
last_seq = 344
current_ts = 313.144226
current_received_ts = 313.143890
current_seq = 345
count = 107
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.144226
last_received_ts = 313.143890
last_seq = 345
current_ts = 313.160889
current_received_ts = 313.160461
current_seq = 346
count = 108
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.160889
last_received_ts = 313.160461
last_seq = 346
current_ts = 313.177551
current_received_ts = 313.177338
current_seq = 347
count = 109
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.177551
last_received_ts = 313.177338
last_seq = 347
current_ts = 313.194214
current_received_ts = 313.194000
current_seq = 348
count = 110
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 57us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.194214
last_received_ts = 313.194000
last_seq = 348
current_ts = 313.210876
current_received_ts = 313.210480
current_seq = 349
count = 111
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.210876
last_received_ts = 313.210480
last_seq = 349
current_ts = 313.227539
current_received_ts = 313.227234
current_seq = 350
count = 112
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.227539
last_received_ts = 313.227234
last_seq = 350
current_ts = 313.244232
current_received_ts = 313.243988
current_seq = 351
count = 113
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 57us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.244232
last_received_ts = 313.243988
last_seq = 351
current_ts = 313.260895
current_received_ts = 313.260529
current_seq = 352
count = 114
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.260895
last_received_ts = 313.260529
last_seq = 352
current_ts = 313.277557
current_received_ts = 313.277374
current_seq = 353
count = 115
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.277557
last_received_ts = 313.277374
last_seq = 353
current_ts = 313.294220
current_received_ts = 313.293854
current_seq = 354
count = 116
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 52us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.294220
last_received_ts = 313.293854
last_seq = 354
current_ts = 313.310883
current_received_ts = 313.310486
current_seq = 355
count = 117
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.310883
last_received_ts = 313.310486
last_seq = 355
current_ts = 313.327545
current_received_ts = 313.327209
current_seq = 356
count = 118
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.327545
last_received_ts = 313.327209
last_seq = 356
current_ts = 313.344208
current_received_ts = 313.343994
current_seq = 357
count = 119
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.344208
last_received_ts = 313.343994
last_seq = 357
current_ts = 313.360901
current_received_ts = 313.360535
current_seq = 358
count = 120
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.360901
last_received_ts = 313.360535
last_seq = 358
current_ts = 313.377563
current_received_ts = 313.377350
current_seq = 359
count = 121
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.377563
last_received_ts = 313.377350
last_seq = 359
current_ts = 313.394226
current_received_ts = 313.393890
current_seq = 360
count = 122
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.394226
last_received_ts = 313.393890
last_seq = 360
current_ts = 313.410889
current_received_ts = 313.410553
current_seq = 361
count = 123
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.410889
last_received_ts = 313.410553
last_seq = 361
current_ts = 313.427551
current_received_ts = 313.427368
current_seq = 362
count = 124
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.427551
last_received_ts = 313.427368
last_seq = 362
current_ts = 313.444214
current_received_ts = 313.444031
current_seq = 363
count = 125
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 57us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.444214
last_received_ts = 313.444031
last_seq = 363
current_ts = 313.460907
current_received_ts = 313.460602
current_seq = 364
count = 126
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.460907
last_received_ts = 313.460602
last_seq = 364
current_ts = 313.477570
current_received_ts = 313.477142
current_seq = 365
count = 127
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 51us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.477570
last_received_ts = 313.477142
last_seq = 365
current_ts = 313.494232
current_received_ts = 313.493683
current_seq = 366
count = 128
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 47us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.494232
last_received_ts = 313.493683
last_seq = 366
current_ts = 313.510895
current_received_ts = 313.510376
current_seq = 367
count = 129
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 32us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.510895
last_received_ts = 313.510376
last_seq = 367
current_ts = 313.527557
current_received_ts = 313.527069
current_seq = 368
count = 130
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 45us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.527557
last_received_ts = 313.527069
last_seq = 368
current_ts = 313.544220
current_received_ts = 313.543732
current_seq = 369
count = 131
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 45us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.544220
last_received_ts = 313.543732
last_seq = 369
current_ts = 313.560913
current_received_ts = 313.560364
current_seq = 370
count = 132
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 49us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.560913
last_received_ts = 313.560364
last_seq = 370
current_ts = 313.577576
current_received_ts = 313.577057
current_seq = 371
count = 133
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 46us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.577576
last_received_ts = 313.577057
last_seq = 371
current_ts = 313.594238
current_received_ts = 313.593719
current_seq = 372
count = 134
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 33us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.594238
last_received_ts = 313.593719
last_seq = 372
current_ts = 313.610901
current_received_ts = 313.610352
current_seq = 373
count = 135
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 33us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.610901
last_received_ts = 313.610352
last_seq = 373
current_ts = 313.627563
current_received_ts = 313.627136
current_seq = 374
count = 136
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 32us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.627563
last_received_ts = 313.627136
last_seq = 374
current_ts = 313.644226
current_received_ts = 313.643799
current_seq = 375
count = 137
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 31us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.644226
last_received_ts = 313.643799
last_seq = 375
current_ts = 313.660919
current_received_ts = 313.660461
current_seq = 376
count = 138
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 34us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.660919
last_received_ts = 313.660461
last_seq = 376
current_ts = 313.677582
current_received_ts = 313.677155
current_seq = 377
count = 139
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 38us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.677582
last_received_ts = 313.677155
last_seq = 377
current_ts = 313.694244
current_received_ts = 313.693878
current_seq = 378
count = 140
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 48us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.694244
last_received_ts = 313.693878
last_seq = 378
current_ts = 313.710907
current_received_ts = 313.710602
current_seq = 379
count = 141
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.710907
last_received_ts = 313.710602
last_seq = 379
current_ts = 313.727570
current_received_ts = 313.727234
current_seq = 380
count = 142
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 53us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.727570
last_received_ts = 313.727234
last_seq = 380
current_ts = 313.744232
current_received_ts = 313.743896
current_seq = 381
count = 143
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 53us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.744232
last_received_ts = 313.743896
last_seq = 381
current_ts = 313.760895
current_received_ts = 313.760437
current_seq = 382
count = 144
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.760895
last_received_ts = 313.760437
last_seq = 382
current_ts = 313.777588
current_received_ts = 313.777374
current_seq = 383
count = 145
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.777588
last_received_ts = 313.777374
last_seq = 383
current_ts = 313.794250
current_received_ts = 313.794037
current_seq = 384
count = 146
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.794250
last_received_ts = 313.794037
last_seq = 384
current_ts = 313.810913
current_received_ts = 313.810486
current_seq = 385
count = 147
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.810913
last_received_ts = 313.810486
last_seq = 385
current_ts = 313.827576
current_received_ts = 313.827240
current_seq = 386
count = 148
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.827576
last_received_ts = 313.827240
last_seq = 386
current_ts = 313.844238
current_received_ts = 313.844025
current_seq = 387
count = 149
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.844238
last_received_ts = 313.844025
last_seq = 387
current_ts = 313.860901
current_received_ts = 313.860474
current_seq = 388
count = 150
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 56us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.860901
last_received_ts = 313.860474
last_seq = 388
current_ts = 313.877594
current_received_ts = 313.877380
current_seq = 389
count = 151
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 54us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.877594
last_received_ts = 313.877380
last_seq = 389
current_ts = 313.894257
current_received_ts = 313.894043
current_seq = 390
count = 152
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 55us
(kms_flip:2267) DEBUG: name = flip
last_ts = 313.894257
last_received_ts = 313.894043
last_seq = 390
current_ts = 313.910919
current_received_ts = 313.910492
current_seq = 391
count = 153
seq_step = 1
(kms_flip:2267) DEBUG: Vblank took 567us
(kms_flip:2267) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2267) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2267) igt_core-INFO: Stack trace:
(kms_flip:2267) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2267) igt_core-INFO:   #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0()
(kms_flip:2267) igt_core-INFO:   #2 ../tests/kms_flip.c:1887 run_test()
(kms_flip:2267) igt_core-INFO:   #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043()
(kms_flip:2267) igt_core-INFO:   #4 ../tests/kms_flip.c:2043 main()
(kms_flip:2267) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2267) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2267) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A3: FAIL (2.956s)

Dmesg

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

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

<7> [310.940680] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:562]

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

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

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

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

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

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

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

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

<7> [311.018823] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:150:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [311.044268] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:150:pipe A]

<7> [311.044655] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B]

<7> [311.044850] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:386:pipe C]

<7> [311.044989] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:504:pipe D]

<7> [311.045130] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:268:pipe B]

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

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

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

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

<7> [311.045869] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:546:DDI D/PHY D] [CRTC:268:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [311.054857] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:152: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> [311.055046] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:152: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> [311.055235] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:152: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> [311.055425] i915 0000:03:00.0: [drm:skl_print_plane_changes [i915]] [PLANE:152: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> [311.055630] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:268:pipe B] data rate 594000 num active planes 1

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [311.059018] 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> [311.059217] 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> [311.059415] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

<7> [311.059612] 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> [311.059850] 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> [311.060049] 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> [311.060249] 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> [311.060448] 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> [311.060647] 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> [311.060887] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] linetime: 119, ips linetime: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [311.092314] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:268:pipe B]

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

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