igt@kms_flip@flip-vs-expired-vblank@b-vga1 on shard-snb@CI_DRM

Detail	Value
Duration	6.83 seconds
Hostname	shard-snb1
Igt-Version	IGT-Version: 2.3-g33f5420a2 (x86_64) (Linux: 7.0.0-rc4-CI_DRM_18159-g973a56bafac0+ x86_64)
Out	Starting dynamic subtest: B-VGA1 1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 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:2122 __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-VGA1: FAIL (6.828s)
Err	Starting dynamic subtest: B-VGA1 (kms_flip:2685) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2685) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-VGA1 failed. ** DEBUG (kms_flip:2685) DEBUG: name = flip last_ts = 285.913513 last_received_ts = 285.912903 last_seq = 10314 current_ts = 285.930237 current_received_ts = 285.929626 current_seq = 10315 count = 262 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 7us (kms_flip:2685) DEBUG: name = flip last_ts = 285.930237 last_received_ts = 285.929626 last_seq = 10315 current_ts = 285.946930 current_received_ts = 285.946320 current_seq = 10316 count = 263 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 285.946930 last_received_ts = 285.946320 last_seq = 10316 current_ts = 285.963623 current_received_ts = 285.963043 current_seq = 10317 count = 264 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 285.963623 last_received_ts = 285.963043 last_seq = 10317 current_ts = 285.980347 current_received_ts = 285.979736 current_seq = 10318 count = 265 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 285.980347 last_received_ts = 285.979736 last_seq = 10318 current_ts = 285.997040 current_received_ts = 285.996460 current_seq = 10319 count = 266 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 285.997040 last_received_ts = 285.996460 last_seq = 10319 current_ts = 286.013763 current_received_ts = 286.013123 current_seq = 10320 count = 267 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.013763 last_received_ts = 286.013123 last_seq = 10320 current_ts = 286.030457 current_received_ts = 286.029877 current_seq = 10321 count = 268 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.030457 last_received_ts = 286.029877 last_seq = 10321 current_ts = 286.047180 current_received_ts = 286.046539 current_seq = 10322 count = 269 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.047180 last_received_ts = 286.046539 last_seq = 10322 current_ts = 286.063873 current_received_ts = 286.063202 current_seq = 10323 count = 270 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.063873 last_received_ts = 286.063202 last_seq = 10323 current_ts = 286.080566 current_received_ts = 286.079987 current_seq = 10324 count = 271 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 34us (kms_flip:2685) DEBUG: name = flip last_ts = 286.080566 last_received_ts = 286.079987 last_seq = 10324 current_ts = 286.097290 current_received_ts = 286.096680 current_seq = 10325 count = 272 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 286.097290 last_received_ts = 286.096680 last_seq = 10325 current_ts = 286.113983 current_received_ts = 286.113373 current_seq = 10326 count = 273 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.113983 last_received_ts = 286.113373 last_seq = 10326 current_ts = 286.130707 current_received_ts = 286.130096 current_seq = 10327 count = 274 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.130707 last_received_ts = 286.130096 last_seq = 10327 current_ts = 286.147400 current_received_ts = 286.146790 current_seq = 10328 count = 275 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.147400 last_received_ts = 286.146790 last_seq = 10328 current_ts = 286.164093 current_received_ts = 286.163513 current_seq = 10329 count = 276 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.164093 last_received_ts = 286.163513 last_seq = 10329 current_ts = 286.180817 current_received_ts = 286.180176 current_seq = 10330 count = 277 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.180817 last_received_ts = 286.180176 last_seq = 10330 current_ts = 286.197510 current_received_ts = 286.196899 current_seq = 10331 count = 278 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.197510 last_received_ts = 286.196899 last_seq = 10331 current_ts = 286.214233 current_received_ts = 286.213623 current_seq = 10332 count = 279 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 7us (kms_flip:2685) DEBUG: name = flip last_ts = 286.214233 last_received_ts = 286.213623 last_seq = 10332 current_ts = 286.230927 current_received_ts = 286.230316 current_seq = 10333 count = 280 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.230927 last_received_ts = 286.230316 last_seq = 10333 current_ts = 286.247650 current_received_ts = 286.246948 current_seq = 10334 count = 281 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 12us (kms_flip:2685) DEBUG: name = flip last_ts = 286.247650 last_received_ts = 286.246948 last_seq = 10334 current_ts = 286.264343 current_received_ts = 286.263672 current_seq = 10335 count = 282 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 15us (kms_flip:2685) DEBUG: name = flip last_ts = 286.264343 last_received_ts = 286.263672 last_seq = 10335 current_ts = 286.281067 current_received_ts = 286.280457 current_seq = 10336 count = 283 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 12us (kms_flip:2685) DEBUG: name = flip last_ts = 286.281067 last_received_ts = 286.280457 last_seq = 10336 current_ts = 286.297760 current_received_ts = 286.297150 current_seq = 10337 count = 284 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 12us (kms_flip:2685) DEBUG: name = flip last_ts = 286.297760 last_received_ts = 286.297150 last_seq = 10337 current_ts = 286.314453 current_received_ts = 286.313873 current_seq = 10338 count = 285 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 12us (kms_flip:2685) DEBUG: name = flip last_ts = 286.314453 last_received_ts = 286.313873 last_seq = 10338 current_ts = 286.331177 current_received_ts = 286.330566 current_seq = 10339 count = 286 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 10us (kms_flip:2685) DEBUG: name = flip last_ts = 286.331177 last_received_ts = 286.330566 last_seq = 10339 current_ts = 286.347870 current_received_ts = 286.347290 current_seq = 10340 count = 287 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 12us (kms_flip:2685) DEBUG: name = flip last_ts = 286.347870 last_received_ts = 286.347290 last_seq = 10340 current_ts = 286.364563 current_received_ts = 286.364044 current_seq = 10341 count = 288 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 13us (kms_flip:2685) DEBUG: name = flip last_ts = 286.364563 last_received_ts = 286.364044 last_seq = 10341 current_ts = 286.381287 current_received_ts = 286.380707 current_seq = 10342 count = 289 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 11us (kms_flip:2685) DEBUG: name = flip last_ts = 286.381287 last_received_ts = 286.380707 last_seq = 10342 current_ts = 286.397980 current_received_ts = 286.397400 current_seq = 10343 count = 290 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 10us (kms_flip:2685) DEBUG: name = flip last_ts = 286.397980 last_received_ts = 286.397400 last_seq = 10343 current_ts = 286.414673 current_received_ts = 286.414093 current_seq = 10344 count = 291 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 11us (kms_flip:2685) DEBUG: name = flip last_ts = 286.414673 last_received_ts = 286.414093 last_seq = 10344 current_ts = 286.431396 current_received_ts = 286.430817 current_seq = 10345 count = 292 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 12us (kms_flip:2685) DEBUG: name = flip last_ts = 286.431396 last_received_ts = 286.430817 last_seq = 10345 current_ts = 286.448120 current_received_ts = 286.447510 current_seq = 10346 count = 293 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 286.448120 last_received_ts = 286.447510 last_seq = 10346 current_ts = 286.464813 current_received_ts = 286.464203 current_seq = 10347 count = 294 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 12us (kms_flip:2685) DEBUG: name = flip last_ts = 286.464813 last_received_ts = 286.464203 last_seq = 10347 current_ts = 286.481506 current_received_ts = 286.480927 current_seq = 10348 count = 295 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 12us (kms_flip:2685) DEBUG: name = flip last_ts = 286.481506 last_received_ts = 286.480927 last_seq = 10348 current_ts = 286.498230 current_received_ts = 286.497650 current_seq = 10349 count = 296 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 12us (kms_flip:2685) DEBUG: name = flip last_ts = 286.498230 last_received_ts = 286.497650 last_seq = 10349 current_ts = 286.514923 current_received_ts = 286.514343 current_seq = 10350 count = 297 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 12us (kms_flip:2685) DEBUG: name = flip last_ts = 286.514923 last_received_ts = 286.514343 last_seq = 10350 current_ts = 286.531616 current_received_ts = 286.531067 current_seq = 10351 count = 298 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 11us (kms_flip:2685) DEBUG: name = flip last_ts = 286.531616 last_received_ts = 286.531067 last_seq = 10351 current_ts = 286.548340 current_received_ts = 286.547729 current_seq = 10352 count = 299 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.548340 last_received_ts = 286.547729 last_seq = 10352 current_ts = 286.565033 current_received_ts = 286.564453 current_seq = 10353 count = 300 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.565033 last_received_ts = 286.564453 last_seq = 10353 current_ts = 286.581757 current_received_ts = 286.581146 current_seq = 10354 count = 301 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.581757 last_received_ts = 286.581146 last_seq = 10354 current_ts = 286.598450 current_received_ts = 286.597870 current_seq = 10355 count = 302 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.598450 last_received_ts = 286.597870 last_seq = 10355 current_ts = 286.615173 current_received_ts = 286.614532 current_seq = 10356 count = 303 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 7us (kms_flip:2685) DEBUG: name = flip last_ts = 286.615173 last_received_ts = 286.614532 last_seq = 10356 current_ts = 286.631866 current_received_ts = 286.631256 current_seq = 10357 count = 304 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.631866 last_received_ts = 286.631256 last_seq = 10357 current_ts = 286.648590 current_received_ts = 286.647949 current_seq = 10358 count = 305 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.648590 last_received_ts = 286.647949 last_seq = 10358 current_ts = 286.665283 current_received_ts = 286.664673 current_seq = 10359 count = 306 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.665283 last_received_ts = 286.664673 last_seq = 10359 current_ts = 286.681976 current_received_ts = 286.681396 current_seq = 10360 count = 307 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.681976 last_received_ts = 286.681396 last_seq = 10360 current_ts = 286.698700 current_received_ts = 286.698090 current_seq = 10361 count = 308 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.698700 last_received_ts = 286.698090 last_seq = 10361 current_ts = 286.715393 current_received_ts = 286.714783 current_seq = 10362 count = 309 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.715393 last_received_ts = 286.714783 last_seq = 10362 current_ts = 286.732117 current_received_ts = 286.731506 current_seq = 10363 count = 310 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.732117 last_received_ts = 286.731506 last_seq = 10363 current_ts = 286.748810 current_received_ts = 286.748199 current_seq = 10364 count = 311 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.748810 last_received_ts = 286.748199 last_seq = 10364 current_ts = 286.765533 current_received_ts = 286.764923 current_seq = 10365 count = 312 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.765533 last_received_ts = 286.764923 last_seq = 10365 current_ts = 286.782227 current_received_ts = 286.781616 current_seq = 10366 count = 313 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 7us (kms_flip:2685) DEBUG: name = flip last_ts = 286.782227 last_received_ts = 286.781616 last_seq = 10366 current_ts = 286.798920 current_received_ts = 286.798309 current_seq = 10367 count = 314 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.798920 last_received_ts = 286.798309 last_seq = 10367 current_ts = 286.815643 current_received_ts = 286.815063 current_seq = 10368 count = 315 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.815643 last_received_ts = 286.815063 last_seq = 10368 current_ts = 286.832336 current_received_ts = 286.831726 current_seq = 10369 count = 316 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.832336 last_received_ts = 286.831726 last_seq = 10369 current_ts = 286.849060 current_received_ts = 286.848450 current_seq = 10370 count = 317 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 7us (kms_flip:2685) DEBUG: name = flip last_ts = 286.849060 last_received_ts = 286.848450 last_seq = 10370 current_ts = 286.865753 current_received_ts = 286.865112 current_seq = 10371 count = 318 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 286.865753 last_received_ts = 286.865112 last_seq = 10371 current_ts = 286.882446 current_received_ts = 286.881866 current_seq = 10372 count = 319 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.882446 last_received_ts = 286.881866 last_seq = 10372 current_ts = 286.899170 current_received_ts = 286.898560 current_seq = 10373 count = 320 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.899170 last_received_ts = 286.898560 last_seq = 10373 current_ts = 286.915863 current_received_ts = 286.915283 current_seq = 10374 count = 321 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.915863 last_received_ts = 286.915283 last_seq = 10374 current_ts = 286.932587 current_received_ts = 286.931976 current_seq = 10375 count = 322 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.932587 last_received_ts = 286.931976 last_seq = 10375 current_ts = 286.949280 current_received_ts = 286.948639 current_seq = 10376 count = 323 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.949280 last_received_ts = 286.948639 last_seq = 10376 current_ts = 286.966003 current_received_ts = 286.965393 current_seq = 10377 count = 324 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.966003 last_received_ts = 286.965393 last_seq = 10377 current_ts = 286.982697 current_received_ts = 286.982086 current_seq = 10378 count = 325 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 286.982697 last_received_ts = 286.982086 last_seq = 10378 current_ts = 286.999420 current_received_ts = 286.998810 current_seq = 10379 count = 326 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 286.999420 last_received_ts = 286.998810 last_seq = 10379 current_ts = 287.016113 current_received_ts = 287.015503 current_seq = 10380 count = 327 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 7us (kms_flip:2685) DEBUG: name = flip last_ts = 287.016113 last_received_ts = 287.015503 last_seq = 10380 current_ts = 287.032806 current_received_ts = 287.032227 current_seq = 10381 count = 328 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.032806 last_received_ts = 287.032227 last_seq = 10381 current_ts = 287.049530 current_received_ts = 287.048920 current_seq = 10382 count = 329 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.049530 last_received_ts = 287.048920 last_seq = 10382 current_ts = 287.066254 current_received_ts = 287.065582 current_seq = 10383 count = 330 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.066254 last_received_ts = 287.065582 last_seq = 10383 current_ts = 287.082947 current_received_ts = 287.082336 current_seq = 10384 count = 331 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.082947 last_received_ts = 287.082336 last_seq = 10384 current_ts = 287.099640 current_received_ts = 287.099060 current_seq = 10385 count = 332 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.099640 last_received_ts = 287.099060 last_seq = 10385 current_ts = 287.116333 current_received_ts = 287.115784 current_seq = 10386 count = 333 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.116333 last_received_ts = 287.115784 last_seq = 10386 current_ts = 287.133057 current_received_ts = 287.132507 current_seq = 10387 count = 334 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.133057 last_received_ts = 287.132507 last_seq = 10387 current_ts = 287.149750 current_received_ts = 287.149200 current_seq = 10388 count = 335 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.149750 last_received_ts = 287.149200 last_seq = 10388 current_ts = 287.166473 current_received_ts = 287.165924 current_seq = 10389 count = 336 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.166473 last_received_ts = 287.165924 last_seq = 10389 current_ts = 287.183167 current_received_ts = 287.182617 current_seq = 10390 count = 337 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.183167 last_received_ts = 287.182617 last_seq = 10390 current_ts = 287.199890 current_received_ts = 287.199310 current_seq = 10391 count = 338 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.199890 last_received_ts = 287.199310 last_seq = 10391 current_ts = 287.216583 current_received_ts = 287.216034 current_seq = 10392 count = 339 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.216583 last_received_ts = 287.216034 last_seq = 10392 current_ts = 287.233307 current_received_ts = 287.232727 current_seq = 10393 count = 340 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.233307 last_received_ts = 287.232727 last_seq = 10393 current_ts = 287.250000 current_received_ts = 287.249451 current_seq = 10394 count = 341 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 7us (kms_flip:2685) DEBUG: name = flip last_ts = 287.250000 last_received_ts = 287.249451 last_seq = 10394 current_ts = 287.266693 current_received_ts = 287.266113 current_seq = 10395 count = 342 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.266693 last_received_ts = 287.266113 last_seq = 10395 current_ts = 287.283417 current_received_ts = 287.282837 current_seq = 10396 count = 343 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 6us (kms_flip:2685) DEBUG: name = flip last_ts = 287.283417 last_received_ts = 287.282837 last_seq = 10396 current_ts = 287.300110 current_received_ts = 287.299530 current_seq = 10397 count = 344 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.300110 last_received_ts = 287.299530 last_seq = 10397 current_ts = 287.316833 current_received_ts = 287.316254 current_seq = 10398 count = 345 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.316833 last_received_ts = 287.316254 last_seq = 10398 current_ts = 287.333527 current_received_ts = 287.332977 current_seq = 10399 count = 346 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.333527 last_received_ts = 287.332977 last_seq = 10399 current_ts = 287.350250 current_received_ts = 287.349640 current_seq = 10400 count = 347 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.350250 last_received_ts = 287.349640 last_seq = 10400 current_ts = 287.366943 current_received_ts = 287.366333 current_seq = 10401 count = 348 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.366943 last_received_ts = 287.366333 last_seq = 10401 current_ts = 287.383667 current_received_ts = 287.383118 current_seq = 10402 count = 349 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.383667 last_received_ts = 287.383118 last_seq = 10402 current_ts = 287.400360 current_received_ts = 287.399780 current_seq = 10403 count = 350 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.400360 last_received_ts = 287.399780 last_seq = 10403 current_ts = 287.417053 current_received_ts = 287.416473 current_seq = 10404 count = 351 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.417053 last_received_ts = 287.416473 last_seq = 10404 current_ts = 287.433777 current_received_ts = 287.433197 current_seq = 10405 count = 352 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.433777 last_received_ts = 287.433197 last_seq = 10405 current_ts = 287.450470 current_received_ts = 287.449890 current_seq = 10406 count = 353 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.450470 last_received_ts = 287.449890 last_seq = 10406 current_ts = 287.467194 current_received_ts = 287.466614 current_seq = 10407 count = 354 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.467194 last_received_ts = 287.466614 last_seq = 10407 current_ts = 287.483887 current_received_ts = 287.483307 current_seq = 10408 count = 355 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 6us (kms_flip:2685) DEBUG: name = flip last_ts = 287.483887 last_received_ts = 287.483307 last_seq = 10408 current_ts = 287.500610 current_received_ts = 287.500031 current_seq = 10409 count = 356 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.500610 last_received_ts = 287.500031 last_seq = 10409 current_ts = 287.517303 current_received_ts = 287.516724 current_seq = 10410 count = 357 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.517303 last_received_ts = 287.516724 last_seq = 10410 current_ts = 287.533997 current_received_ts = 287.533447 current_seq = 10411 count = 358 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.533997 last_received_ts = 287.533447 last_seq = 10411 current_ts = 287.550720 current_received_ts = 287.550140 current_seq = 10412 count = 359 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.550720 last_received_ts = 287.550140 last_seq = 10412 current_ts = 287.567413 current_received_ts = 287.566864 current_seq = 10413 count = 360 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.567413 last_received_ts = 287.566864 last_seq = 10413 current_ts = 287.584137 current_received_ts = 287.583557 current_seq = 10414 count = 361 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.584137 last_received_ts = 287.583557 last_seq = 10414 current_ts = 287.600830 current_received_ts = 287.600281 current_seq = 10415 count = 362 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.600830 last_received_ts = 287.600281 last_seq = 10415 current_ts = 287.617554 current_received_ts = 287.616943 current_seq = 10416 count = 363 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.617554 last_received_ts = 287.616943 last_seq = 10416 current_ts = 287.634247 current_received_ts = 287.633698 current_seq = 10417 count = 364 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.634247 last_received_ts = 287.633698 last_seq = 10417 current_ts = 287.650940 current_received_ts = 287.650391 current_seq = 10418 count = 365 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.650940 last_received_ts = 287.650391 last_seq = 10418 current_ts = 287.667664 current_received_ts = 287.667084 current_seq = 10419 count = 366 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 7us (kms_flip:2685) DEBUG: name = flip last_ts = 287.667664 last_received_ts = 287.667084 last_seq = 10419 current_ts = 287.684357 current_received_ts = 287.683807 current_seq = 10420 count = 367 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.684357 last_received_ts = 287.683807 last_seq = 10420 current_ts = 287.701080 current_received_ts = 287.700500 current_seq = 10421 count = 368 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.701080 last_received_ts = 287.700500 last_seq = 10421 current_ts = 287.717773 current_received_ts = 287.717163 current_seq = 10422 count = 369 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.717773 last_received_ts = 287.717163 last_seq = 10422 current_ts = 287.734497 current_received_ts = 287.733917 current_seq = 10423 count = 370 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.734497 last_received_ts = 287.733917 last_seq = 10423 current_ts = 287.751190 current_received_ts = 287.750610 current_seq = 10424 count = 371 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.751190 last_received_ts = 287.750610 last_seq = 10424 current_ts = 287.767914 current_received_ts = 287.767303 current_seq = 10425 count = 372 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.767914 last_received_ts = 287.767303 last_seq = 10425 current_ts = 287.784607 current_received_ts = 287.784058 current_seq = 10426 count = 373 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.784607 last_received_ts = 287.784058 last_seq = 10426 current_ts = 287.801300 current_received_ts = 287.800720 current_seq = 10427 count = 374 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.801300 last_received_ts = 287.800720 last_seq = 10427 current_ts = 287.818024 current_received_ts = 287.817444 current_seq = 10428 count = 375 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.818024 last_received_ts = 287.817444 last_seq = 10428 current_ts = 287.834717 current_received_ts = 287.834167 current_seq = 10429 count = 376 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.834717 last_received_ts = 287.834167 last_seq = 10429 current_ts = 287.851440 current_received_ts = 287.850861 current_seq = 10430 count = 377 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.851440 last_received_ts = 287.850861 last_seq = 10430 current_ts = 287.868134 current_received_ts = 287.867554 current_seq = 10431 count = 378 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.868134 last_received_ts = 287.867554 last_seq = 10431 current_ts = 287.884857 current_received_ts = 287.884247 current_seq = 10432 count = 379 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.884857 last_received_ts = 287.884247 last_seq = 10432 current_ts = 287.901550 current_received_ts = 287.900970 current_seq = 10433 count = 380 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.901550 last_received_ts = 287.900970 last_seq = 10433 current_ts = 287.918274 current_received_ts = 287.917664 current_seq = 10434 count = 381 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 9us (kms_flip:2685) DEBUG: name = flip last_ts = 287.918274 last_received_ts = 287.917664 last_seq = 10434 current_ts = 287.934967 current_received_ts = 287.934387 current_seq = 10435 count = 382 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 8us (kms_flip:2685) DEBUG: name = flip last_ts = 287.934967 last_received_ts = 287.934387 last_seq = 10435 current_ts = 287.951691 current_received_ts = 287.951080 current_seq = 10436 count = 383 seq_step = 1 (kms_flip:2685) DEBUG: Vblank took 539us (kms_flip:2685) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2685) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2685) igt_core-INFO: Stack trace: (kms_flip:2685) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2685) igt_core-INFO: #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0() (kms_flip:2685) igt_core-INFO: #2 ../tests/kms_flip.c:1887 run_test() (kms_flip:2685) igt_core-INFO: #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2043() (kms_flip:2685) igt_core-INFO: #4 ../tests/kms_flip.c:2043 main() (kms_flip:2685) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2685) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2685) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-VGA1: FAIL (6.828s)
Dmesg	<6> [281.085780] [IGT] kms_flip: starting dynamic subtest B-VGA1 <7> [281.086775] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:89] <7> [281.086909] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:90] <7> [281.121596] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:52:pipe A] <7> [281.121808] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [281.122367] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [281.122931] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [281.123493] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in has_pch_encoder (expected yes, found no) <7> [281.124009] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in fdi_lanes (expected 1, found 0) <7> [281.124558] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in fdi_m_n (expected tu 64 data 6039797/8388608 link 125829/524288, found tu 0, data 0/0 link 0/0) <7> [281.125185] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000) <7> [281.125715] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [281.125951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0) <7> [281.126185] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0) <7> [281.126422] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0) <7> [281.126748] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0) <7> [281.126984] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0) <7> [281.127236] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0) <7> [281.127500] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0) <7> [281.127734] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0) <7> [281.127978] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0) <7> [281.128274] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0) <7> [281.128526] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0) <7> [281.128791] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0) <7> [281.129018] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0) <7> [281.129244] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0) <7> [281.129507] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0) <7> [281.129823] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0) <7> [281.130078] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0) <7> [281.130306] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0) <7> [281.130592] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0) <7> [281.130831] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0) <7> [281.131058] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0) <7> [281.131313] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0) <7> [281.131612] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0) <7> [281.131856] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0) <7> [281.132095] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [281.132322] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [281.132598] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [281.132877] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [281.133129] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0) <7> [281.133357] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0) <7> [281.133640] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in port_clock (expected 64800, found 0) <7> [281.133881] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:52:pipe A] fastset requirement not met, forcing full modeset <7> [281.134108] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:52:pipe A] releasing PCH DPLL A <7> [281.134358] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:52:pipe A] min cdclk: 72000 kHz -> 0 kHz <7> [281.134686] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:52:pipe A] enable: no [modeset] <7> [281.134960] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:34:primary A] fb: [NOFB], visible: no <7> [281.135313] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [281.151586] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found <7> [281.152064] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found <7> [281.152584] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found <7> [281.169242] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:52:pipe A] <7> [281.169789] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A <7> [281.170493] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT] <7> [281.170950] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D] <7> [281.171389] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D] <7> [281.171887] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1] <7> [281.172615] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:52:pipe A] <7> [281.172954] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B] <7> [281.173081] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B] <7> [281.173106] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:72:VGA-1] <7> [281.173190] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:72:VGA-1] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36) <7> [281.173465] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [281.173745] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1 <7> [281.174004] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [281.174239] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [281.174511] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [281.174746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes) <7> [281.174980] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1) <7> [281.175214] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in fdi_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6039797/8388608 link 125829/524288) <7> [281.175526] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002) <7> [281.175793] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [281.176027] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024) <7> [281.176276] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344) <7> [281.176531] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024) <7> [281.176773] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344) <7> [281.177027] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048) <7> [281.177298] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184) <7> [281.177569] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768) <7> [281.177835] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768) <7> [281.178077] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771) <7> [281.178304] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777) <7> [281.178610] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806) <7> [281.178881] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806) <7> [281.179108] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024) <7> [281.179351] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344) <7> [281.179627] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024) <7> [281.179865] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344) <7> [281.180096] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048) <7> [281.180405] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184) <7> [281.180663] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768) <7> [281.180921] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768) <7> [281.181148] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771) <7> [281.181375] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777) <7> [281.181678] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806) <7> [281.181964] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806) <7> [281.182191] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [281.182457] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [281.182703] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [281.182931] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in dpll_hw_state <7> [281.183182] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [281.183483] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06 <7> [281.183744] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [281.183989] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09 <7> [281.184216] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [281.184524] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800) <7> [281.184773] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800) <7> [281.185068] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in port_clock (expected 0, found 64800) <7> [281.185297] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] fastset requirement not met, forcing full modeset <7> [281.185619] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:71:pipe B] min cdclk: 0 kHz -> 72000 kHz <7> [281.185857] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:71:pipe B] allocated PCH DPLL A <7> [281.186081] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:71:pipe B] reserving PCH DPLL A <7> [281.186308] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:71:pipe B] enable: yes [modeset] <7> [281.186647] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB <7> [281.186891] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [281.187127] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [281.187352] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [281.187621] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [281.187857] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [281.188141] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fdi: lanes: 1; data_m: 6039797, data_n: 8388608, link_m: 125829, link_n: 524288, tu: 64 <7> [281.188377] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0 <7> [281.188666] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1 <7> [281.188902] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [281.189127] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0 <7> [281.189355] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0 <7> [281.189688] i915 0000:00:02.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> [281.189948] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa <7> [281.190187] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa <7> [281.190472] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa <7> [281.190473] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on <7> [281.190711] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1024x768": 60 64800 1024 1048 1184 1344 768 771 777 806 0x40 0xa <7> [281.190954] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa <7> [281.191237] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pipe src: 1024x768+0+0, pixel rate 64800, min cdclk 72000 <7> [281.191525] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0 <7> [281.191758] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [281.192004] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [281.192237] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09 <7> [281.192489] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [281.192768] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [281.193023] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [281.193260] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [281.193531] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [281.193765] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [281.193998] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [281.194274] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:53:primary B] fb: [FB:89] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [281.194553] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [281.194791] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0 <7> [281.196010] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on <7> [281.196261] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT] <7> [281.196521] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D] <7> [281.196748] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D] <7> [281.197540] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [281.198607] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100 <7> [281.198884] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done. <7> [281.199782] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200 <7> [281.200009] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done. <7> [281.200301] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done. <7> [281.200590] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:71:pipe B] <7> [281.200867] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A <7> [281.252875] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1] <7> [281.253428] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:71:pipe B] <6> [287.914872] [IGT] kms_flip: finished subtest B-VGA1, FAIL

Detail

Value

Duration

6.83 seconds

Hostname

shard-snb1

Igt-Version

IGT-Version: 2.3-g33f5420a2 (x86_64) (Linux: 7.0.0-rc4-CI_DRM_18159-g973a56bafac0+ x86_64)

Out

Starting dynamic subtest: B-VGA1
  1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 
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:2122 __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-VGA1: FAIL (6.828s)

Err

Starting dynamic subtest: B-VGA1
(kms_flip:2685) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2685) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:2685) DEBUG: name = flip
last_ts = 285.913513
last_received_ts = 285.912903
last_seq = 10314
current_ts = 285.930237
current_received_ts = 285.929626
current_seq = 10315
count = 262
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 7us
(kms_flip:2685) DEBUG: name = flip
last_ts = 285.930237
last_received_ts = 285.929626
last_seq = 10315
current_ts = 285.946930
current_received_ts = 285.946320
current_seq = 10316
count = 263
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 285.946930
last_received_ts = 285.946320
last_seq = 10316
current_ts = 285.963623
current_received_ts = 285.963043
current_seq = 10317
count = 264
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 285.963623
last_received_ts = 285.963043
last_seq = 10317
current_ts = 285.980347
current_received_ts = 285.979736
current_seq = 10318
count = 265
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 285.980347
last_received_ts = 285.979736
last_seq = 10318
current_ts = 285.997040
current_received_ts = 285.996460
current_seq = 10319
count = 266
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 285.997040
last_received_ts = 285.996460
last_seq = 10319
current_ts = 286.013763
current_received_ts = 286.013123
current_seq = 10320
count = 267
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.013763
last_received_ts = 286.013123
last_seq = 10320
current_ts = 286.030457
current_received_ts = 286.029877
current_seq = 10321
count = 268
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.030457
last_received_ts = 286.029877
last_seq = 10321
current_ts = 286.047180
current_received_ts = 286.046539
current_seq = 10322
count = 269
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.047180
last_received_ts = 286.046539
last_seq = 10322
current_ts = 286.063873
current_received_ts = 286.063202
current_seq = 10323
count = 270
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.063873
last_received_ts = 286.063202
last_seq = 10323
current_ts = 286.080566
current_received_ts = 286.079987
current_seq = 10324
count = 271
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 34us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.080566
last_received_ts = 286.079987
last_seq = 10324
current_ts = 286.097290
current_received_ts = 286.096680
current_seq = 10325
count = 272
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.097290
last_received_ts = 286.096680
last_seq = 10325
current_ts = 286.113983
current_received_ts = 286.113373
current_seq = 10326
count = 273
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.113983
last_received_ts = 286.113373
last_seq = 10326
current_ts = 286.130707
current_received_ts = 286.130096
current_seq = 10327
count = 274
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.130707
last_received_ts = 286.130096
last_seq = 10327
current_ts = 286.147400
current_received_ts = 286.146790
current_seq = 10328
count = 275
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.147400
last_received_ts = 286.146790
last_seq = 10328
current_ts = 286.164093
current_received_ts = 286.163513
current_seq = 10329
count = 276
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.164093
last_received_ts = 286.163513
last_seq = 10329
current_ts = 286.180817
current_received_ts = 286.180176
current_seq = 10330
count = 277
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.180817
last_received_ts = 286.180176
last_seq = 10330
current_ts = 286.197510
current_received_ts = 286.196899
current_seq = 10331
count = 278
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.197510
last_received_ts = 286.196899
last_seq = 10331
current_ts = 286.214233
current_received_ts = 286.213623
current_seq = 10332
count = 279
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 7us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.214233
last_received_ts = 286.213623
last_seq = 10332
current_ts = 286.230927
current_received_ts = 286.230316
current_seq = 10333
count = 280
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.230927
last_received_ts = 286.230316
last_seq = 10333
current_ts = 286.247650
current_received_ts = 286.246948
current_seq = 10334
count = 281
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 12us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.247650
last_received_ts = 286.246948
last_seq = 10334
current_ts = 286.264343
current_received_ts = 286.263672
current_seq = 10335
count = 282
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 15us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.264343
last_received_ts = 286.263672
last_seq = 10335
current_ts = 286.281067
current_received_ts = 286.280457
current_seq = 10336
count = 283
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 12us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.281067
last_received_ts = 286.280457
last_seq = 10336
current_ts = 286.297760
current_received_ts = 286.297150
current_seq = 10337
count = 284
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 12us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.297760
last_received_ts = 286.297150
last_seq = 10337
current_ts = 286.314453
current_received_ts = 286.313873
current_seq = 10338
count = 285
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 12us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.314453
last_received_ts = 286.313873
last_seq = 10338
current_ts = 286.331177
current_received_ts = 286.330566
current_seq = 10339
count = 286
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 10us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.331177
last_received_ts = 286.330566
last_seq = 10339
current_ts = 286.347870
current_received_ts = 286.347290
current_seq = 10340
count = 287
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 12us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.347870
last_received_ts = 286.347290
last_seq = 10340
current_ts = 286.364563
current_received_ts = 286.364044
current_seq = 10341
count = 288
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 13us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.364563
last_received_ts = 286.364044
last_seq = 10341
current_ts = 286.381287
current_received_ts = 286.380707
current_seq = 10342
count = 289
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 11us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.381287
last_received_ts = 286.380707
last_seq = 10342
current_ts = 286.397980
current_received_ts = 286.397400
current_seq = 10343
count = 290
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 10us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.397980
last_received_ts = 286.397400
last_seq = 10343
current_ts = 286.414673
current_received_ts = 286.414093
current_seq = 10344
count = 291
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 11us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.414673
last_received_ts = 286.414093
last_seq = 10344
current_ts = 286.431396
current_received_ts = 286.430817
current_seq = 10345
count = 292
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 12us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.431396
last_received_ts = 286.430817
last_seq = 10345
current_ts = 286.448120
current_received_ts = 286.447510
current_seq = 10346
count = 293
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.448120
last_received_ts = 286.447510
last_seq = 10346
current_ts = 286.464813
current_received_ts = 286.464203
current_seq = 10347
count = 294
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 12us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.464813
last_received_ts = 286.464203
last_seq = 10347
current_ts = 286.481506
current_received_ts = 286.480927
current_seq = 10348
count = 295
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 12us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.481506
last_received_ts = 286.480927
last_seq = 10348
current_ts = 286.498230
current_received_ts = 286.497650
current_seq = 10349
count = 296
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 12us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.498230
last_received_ts = 286.497650
last_seq = 10349
current_ts = 286.514923
current_received_ts = 286.514343
current_seq = 10350
count = 297
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 12us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.514923
last_received_ts = 286.514343
last_seq = 10350
current_ts = 286.531616
current_received_ts = 286.531067
current_seq = 10351
count = 298
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 11us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.531616
last_received_ts = 286.531067
last_seq = 10351
current_ts = 286.548340
current_received_ts = 286.547729
current_seq = 10352
count = 299
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.548340
last_received_ts = 286.547729
last_seq = 10352
current_ts = 286.565033
current_received_ts = 286.564453
current_seq = 10353
count = 300
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.565033
last_received_ts = 286.564453
last_seq = 10353
current_ts = 286.581757
current_received_ts = 286.581146
current_seq = 10354
count = 301
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.581757
last_received_ts = 286.581146
last_seq = 10354
current_ts = 286.598450
current_received_ts = 286.597870
current_seq = 10355
count = 302
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.598450
last_received_ts = 286.597870
last_seq = 10355
current_ts = 286.615173
current_received_ts = 286.614532
current_seq = 10356
count = 303
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 7us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.615173
last_received_ts = 286.614532
last_seq = 10356
current_ts = 286.631866
current_received_ts = 286.631256
current_seq = 10357
count = 304
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.631866
last_received_ts = 286.631256
last_seq = 10357
current_ts = 286.648590
current_received_ts = 286.647949
current_seq = 10358
count = 305
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.648590
last_received_ts = 286.647949
last_seq = 10358
current_ts = 286.665283
current_received_ts = 286.664673
current_seq = 10359
count = 306
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.665283
last_received_ts = 286.664673
last_seq = 10359
current_ts = 286.681976
current_received_ts = 286.681396
current_seq = 10360
count = 307
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.681976
last_received_ts = 286.681396
last_seq = 10360
current_ts = 286.698700
current_received_ts = 286.698090
current_seq = 10361
count = 308
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.698700
last_received_ts = 286.698090
last_seq = 10361
current_ts = 286.715393
current_received_ts = 286.714783
current_seq = 10362
count = 309
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.715393
last_received_ts = 286.714783
last_seq = 10362
current_ts = 286.732117
current_received_ts = 286.731506
current_seq = 10363
count = 310
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.732117
last_received_ts = 286.731506
last_seq = 10363
current_ts = 286.748810
current_received_ts = 286.748199
current_seq = 10364
count = 311
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.748810
last_received_ts = 286.748199
last_seq = 10364
current_ts = 286.765533
current_received_ts = 286.764923
current_seq = 10365
count = 312
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.765533
last_received_ts = 286.764923
last_seq = 10365
current_ts = 286.782227
current_received_ts = 286.781616
current_seq = 10366
count = 313
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 7us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.782227
last_received_ts = 286.781616
last_seq = 10366
current_ts = 286.798920
current_received_ts = 286.798309
current_seq = 10367
count = 314
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.798920
last_received_ts = 286.798309
last_seq = 10367
current_ts = 286.815643
current_received_ts = 286.815063
current_seq = 10368
count = 315
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.815643
last_received_ts = 286.815063
last_seq = 10368
current_ts = 286.832336
current_received_ts = 286.831726
current_seq = 10369
count = 316
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.832336
last_received_ts = 286.831726
last_seq = 10369
current_ts = 286.849060
current_received_ts = 286.848450
current_seq = 10370
count = 317
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 7us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.849060
last_received_ts = 286.848450
last_seq = 10370
current_ts = 286.865753
current_received_ts = 286.865112
current_seq = 10371
count = 318
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.865753
last_received_ts = 286.865112
last_seq = 10371
current_ts = 286.882446
current_received_ts = 286.881866
current_seq = 10372
count = 319
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.882446
last_received_ts = 286.881866
last_seq = 10372
current_ts = 286.899170
current_received_ts = 286.898560
current_seq = 10373
count = 320
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.899170
last_received_ts = 286.898560
last_seq = 10373
current_ts = 286.915863
current_received_ts = 286.915283
current_seq = 10374
count = 321
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.915863
last_received_ts = 286.915283
last_seq = 10374
current_ts = 286.932587
current_received_ts = 286.931976
current_seq = 10375
count = 322
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.932587
last_received_ts = 286.931976
last_seq = 10375
current_ts = 286.949280
current_received_ts = 286.948639
current_seq = 10376
count = 323
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.949280
last_received_ts = 286.948639
last_seq = 10376
current_ts = 286.966003
current_received_ts = 286.965393
current_seq = 10377
count = 324
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.966003
last_received_ts = 286.965393
last_seq = 10377
current_ts = 286.982697
current_received_ts = 286.982086
current_seq = 10378
count = 325
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.982697
last_received_ts = 286.982086
last_seq = 10378
current_ts = 286.999420
current_received_ts = 286.998810
current_seq = 10379
count = 326
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 286.999420
last_received_ts = 286.998810
last_seq = 10379
current_ts = 287.016113
current_received_ts = 287.015503
current_seq = 10380
count = 327
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 7us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.016113
last_received_ts = 287.015503
last_seq = 10380
current_ts = 287.032806
current_received_ts = 287.032227
current_seq = 10381
count = 328
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.032806
last_received_ts = 287.032227
last_seq = 10381
current_ts = 287.049530
current_received_ts = 287.048920
current_seq = 10382
count = 329
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.049530
last_received_ts = 287.048920
last_seq = 10382
current_ts = 287.066254
current_received_ts = 287.065582
current_seq = 10383
count = 330
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.066254
last_received_ts = 287.065582
last_seq = 10383
current_ts = 287.082947
current_received_ts = 287.082336
current_seq = 10384
count = 331
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.082947
last_received_ts = 287.082336
last_seq = 10384
current_ts = 287.099640
current_received_ts = 287.099060
current_seq = 10385
count = 332
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.099640
last_received_ts = 287.099060
last_seq = 10385
current_ts = 287.116333
current_received_ts = 287.115784
current_seq = 10386
count = 333
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.116333
last_received_ts = 287.115784
last_seq = 10386
current_ts = 287.133057
current_received_ts = 287.132507
current_seq = 10387
count = 334
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.133057
last_received_ts = 287.132507
last_seq = 10387
current_ts = 287.149750
current_received_ts = 287.149200
current_seq = 10388
count = 335
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.149750
last_received_ts = 287.149200
last_seq = 10388
current_ts = 287.166473
current_received_ts = 287.165924
current_seq = 10389
count = 336
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.166473
last_received_ts = 287.165924
last_seq = 10389
current_ts = 287.183167
current_received_ts = 287.182617
current_seq = 10390
count = 337
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.183167
last_received_ts = 287.182617
last_seq = 10390
current_ts = 287.199890
current_received_ts = 287.199310
current_seq = 10391
count = 338
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.199890
last_received_ts = 287.199310
last_seq = 10391
current_ts = 287.216583
current_received_ts = 287.216034
current_seq = 10392
count = 339
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.216583
last_received_ts = 287.216034
last_seq = 10392
current_ts = 287.233307
current_received_ts = 287.232727
current_seq = 10393
count = 340
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.233307
last_received_ts = 287.232727
last_seq = 10393
current_ts = 287.250000
current_received_ts = 287.249451
current_seq = 10394
count = 341
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 7us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.250000
last_received_ts = 287.249451
last_seq = 10394
current_ts = 287.266693
current_received_ts = 287.266113
current_seq = 10395
count = 342
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.266693
last_received_ts = 287.266113
last_seq = 10395
current_ts = 287.283417
current_received_ts = 287.282837
current_seq = 10396
count = 343
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 6us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.283417
last_received_ts = 287.282837
last_seq = 10396
current_ts = 287.300110
current_received_ts = 287.299530
current_seq = 10397
count = 344
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.300110
last_received_ts = 287.299530
last_seq = 10397
current_ts = 287.316833
current_received_ts = 287.316254
current_seq = 10398
count = 345
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.316833
last_received_ts = 287.316254
last_seq = 10398
current_ts = 287.333527
current_received_ts = 287.332977
current_seq = 10399
count = 346
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.333527
last_received_ts = 287.332977
last_seq = 10399
current_ts = 287.350250
current_received_ts = 287.349640
current_seq = 10400
count = 347
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.350250
last_received_ts = 287.349640
last_seq = 10400
current_ts = 287.366943
current_received_ts = 287.366333
current_seq = 10401
count = 348
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.366943
last_received_ts = 287.366333
last_seq = 10401
current_ts = 287.383667
current_received_ts = 287.383118
current_seq = 10402
count = 349
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.383667
last_received_ts = 287.383118
last_seq = 10402
current_ts = 287.400360
current_received_ts = 287.399780
current_seq = 10403
count = 350
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.400360
last_received_ts = 287.399780
last_seq = 10403
current_ts = 287.417053
current_received_ts = 287.416473
current_seq = 10404
count = 351
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.417053
last_received_ts = 287.416473
last_seq = 10404
current_ts = 287.433777
current_received_ts = 287.433197
current_seq = 10405
count = 352
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.433777
last_received_ts = 287.433197
last_seq = 10405
current_ts = 287.450470
current_received_ts = 287.449890
current_seq = 10406
count = 353
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.450470
last_received_ts = 287.449890
last_seq = 10406
current_ts = 287.467194
current_received_ts = 287.466614
current_seq = 10407
count = 354
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.467194
last_received_ts = 287.466614
last_seq = 10407
current_ts = 287.483887
current_received_ts = 287.483307
current_seq = 10408
count = 355
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 6us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.483887
last_received_ts = 287.483307
last_seq = 10408
current_ts = 287.500610
current_received_ts = 287.500031
current_seq = 10409
count = 356
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.500610
last_received_ts = 287.500031
last_seq = 10409
current_ts = 287.517303
current_received_ts = 287.516724
current_seq = 10410
count = 357
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.517303
last_received_ts = 287.516724
last_seq = 10410
current_ts = 287.533997
current_received_ts = 287.533447
current_seq = 10411
count = 358
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.533997
last_received_ts = 287.533447
last_seq = 10411
current_ts = 287.550720
current_received_ts = 287.550140
current_seq = 10412
count = 359
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.550720
last_received_ts = 287.550140
last_seq = 10412
current_ts = 287.567413
current_received_ts = 287.566864
current_seq = 10413
count = 360
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.567413
last_received_ts = 287.566864
last_seq = 10413
current_ts = 287.584137
current_received_ts = 287.583557
current_seq = 10414
count = 361
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.584137
last_received_ts = 287.583557
last_seq = 10414
current_ts = 287.600830
current_received_ts = 287.600281
current_seq = 10415
count = 362
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.600830
last_received_ts = 287.600281
last_seq = 10415
current_ts = 287.617554
current_received_ts = 287.616943
current_seq = 10416
count = 363
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.617554
last_received_ts = 287.616943
last_seq = 10416
current_ts = 287.634247
current_received_ts = 287.633698
current_seq = 10417
count = 364
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.634247
last_received_ts = 287.633698
last_seq = 10417
current_ts = 287.650940
current_received_ts = 287.650391
current_seq = 10418
count = 365
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.650940
last_received_ts = 287.650391
last_seq = 10418
current_ts = 287.667664
current_received_ts = 287.667084
current_seq = 10419
count = 366
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 7us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.667664
last_received_ts = 287.667084
last_seq = 10419
current_ts = 287.684357
current_received_ts = 287.683807
current_seq = 10420
count = 367
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.684357
last_received_ts = 287.683807
last_seq = 10420
current_ts = 287.701080
current_received_ts = 287.700500
current_seq = 10421
count = 368
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.701080
last_received_ts = 287.700500
last_seq = 10421
current_ts = 287.717773
current_received_ts = 287.717163
current_seq = 10422
count = 369
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.717773
last_received_ts = 287.717163
last_seq = 10422
current_ts = 287.734497
current_received_ts = 287.733917
current_seq = 10423
count = 370
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.734497
last_received_ts = 287.733917
last_seq = 10423
current_ts = 287.751190
current_received_ts = 287.750610
current_seq = 10424
count = 371
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.751190
last_received_ts = 287.750610
last_seq = 10424
current_ts = 287.767914
current_received_ts = 287.767303
current_seq = 10425
count = 372
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.767914
last_received_ts = 287.767303
last_seq = 10425
current_ts = 287.784607
current_received_ts = 287.784058
current_seq = 10426
count = 373
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.784607
last_received_ts = 287.784058
last_seq = 10426
current_ts = 287.801300
current_received_ts = 287.800720
current_seq = 10427
count = 374
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.801300
last_received_ts = 287.800720
last_seq = 10427
current_ts = 287.818024
current_received_ts = 287.817444
current_seq = 10428
count = 375
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.818024
last_received_ts = 287.817444
last_seq = 10428
current_ts = 287.834717
current_received_ts = 287.834167
current_seq = 10429
count = 376
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.834717
last_received_ts = 287.834167
last_seq = 10429
current_ts = 287.851440
current_received_ts = 287.850861
current_seq = 10430
count = 377
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.851440
last_received_ts = 287.850861
last_seq = 10430
current_ts = 287.868134
current_received_ts = 287.867554
current_seq = 10431
count = 378
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.868134
last_received_ts = 287.867554
last_seq = 10431
current_ts = 287.884857
current_received_ts = 287.884247
current_seq = 10432
count = 379
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.884857
last_received_ts = 287.884247
last_seq = 10432
current_ts = 287.901550
current_received_ts = 287.900970
current_seq = 10433
count = 380
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.901550
last_received_ts = 287.900970
last_seq = 10433
current_ts = 287.918274
current_received_ts = 287.917664
current_seq = 10434
count = 381
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 9us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.918274
last_received_ts = 287.917664
last_seq = 10434
current_ts = 287.934967
current_received_ts = 287.934387
current_seq = 10435
count = 382
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 8us
(kms_flip:2685) DEBUG: name = flip
last_ts = 287.934967
last_received_ts = 287.934387
last_seq = 10435
current_ts = 287.951691
current_received_ts = 287.951080
current_seq = 10436
count = 383
seq_step = 1
(kms_flip:2685) DEBUG: Vblank took 539us
(kms_flip:2685) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2685) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2685) igt_core-INFO: Stack trace:
(kms_flip:2685) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2685) igt_core-INFO:   #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0()
(kms_flip:2685) igt_core-INFO:   #2 ../tests/kms_flip.c:1887 run_test()
(kms_flip:2685) igt_core-INFO:   #3 ../tests/kms_flip.c:2122 __igt_unique____real_main2043()
(kms_flip:2685) igt_core-INFO:   #4 ../tests/kms_flip.c:2043 main()
(kms_flip:2685) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2685) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2685) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (6.828s)

Dmesg

<6> [281.085780] [IGT] kms_flip: starting dynamic subtest B-VGA1

<7> [281.086775] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:89]

<7> [281.086909] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:90]

<7> [281.121596] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:52:pipe A]

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

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

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

<7> [281.123493] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in has_pch_encoder (expected yes, found no)

<7> [281.124009] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in fdi_lanes (expected 1, found 0)

<7> [281.124558] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in fdi_m_n (expected tu 64 data 6039797/8388608 link 125829/524288, found tu 0, data 0/0 link 0/0)

<7> [281.125185] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)

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

<7> [281.125951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)

<7> [281.126185] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)

<7> [281.126422] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)

<7> [281.126748] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)

<7> [281.126984] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)

<7> [281.127236] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)

<7> [281.127500] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)

<7> [281.127734] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)

<7> [281.127978] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)

<7> [281.128274] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)

<7> [281.128526] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)

<7> [281.128791] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)

<7> [281.129018] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)

<7> [281.129244] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)

<7> [281.129507] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)

<7> [281.129823] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)

<7> [281.130078] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)

<7> [281.130306] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)

<7> [281.130592] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)

<7> [281.130831] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)

<7> [281.131058] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)

<7> [281.131313] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)

<7> [281.131612] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)

<7> [281.131856] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)

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

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

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

<7> [281.132877] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)

<7> [281.133129] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)

<7> [281.133357] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)

<7> [281.133640] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in port_clock (expected 64800, found 0)

<7> [281.133881] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:52:pipe A] fastset requirement not met, forcing full modeset

<7> [281.134108] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:52:pipe A] releasing PCH DPLL A

<7> [281.134358] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:52:pipe A] min cdclk: 72000 kHz -> 0 kHz

<7> [281.134686] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:52:pipe A] enable: no [modeset]

<7> [281.134960] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:34:primary A] fb: [NOFB], visible: no

<7> [281.135313] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A

<7> [281.151586] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found

<7> [281.152064] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found

<7> [281.152584] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found

<7> [281.169242] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:52:pipe A]

<7> [281.169789] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A

<7> [281.170493] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT]

<7> [281.170950] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D]

<7> [281.171389] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D]

<7> [281.171887] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1]

<7> [281.172615] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:52:pipe A]

<7> [281.172954] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B]

<7> [281.173081] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B]

<7> [281.173106] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:72:VGA-1]

<7> [281.173190] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:72:VGA-1] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)

<7> [281.173465] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0

<7> [281.173745] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1

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

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

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

<7> [281.174746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)

<7> [281.174980] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)

<7> [281.175214] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in fdi_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6039797/8388608 link 125829/524288)

<7> [281.175526] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)

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

<7> [281.176027] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)

<7> [281.176276] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)

<7> [281.176531] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)

<7> [281.176773] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)

<7> [281.177027] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)

<7> [281.177298] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)

<7> [281.177569] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)

<7> [281.177835] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)

<7> [281.178077] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)

<7> [281.178304] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)

<7> [281.178610] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)

<7> [281.178881] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)

<7> [281.179108] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)

<7> [281.179351] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)

<7> [281.179627] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)

<7> [281.179865] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)

<7> [281.180096] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)

<7> [281.180405] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)

<7> [281.180663] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)

<7> [281.180921] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)

<7> [281.181148] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)

<7> [281.181375] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)

<7> [281.181678] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)

<7> [281.181964] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)

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

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

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

<7> [281.182931] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in dpll_hw_state

<7> [281.183182] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [281.183483] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06

<7> [281.183744] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [281.183989] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09

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

<7> [281.184524] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)

<7> [281.184773] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)

<7> [281.185068] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)

<7> [281.185297] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] fastset requirement not met, forcing full modeset

<7> [281.185619] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:71:pipe B] min cdclk: 0 kHz -> 72000 kHz

<7> [281.185857] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:71:pipe B] allocated PCH DPLL A

<7> [281.186081] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:71:pipe B] reserving PCH DPLL A

<7> [281.186308] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:71:pipe B] enable: yes [modeset]

<7> [281.186647] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB

<7> [281.186891] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0

<7> [281.187127] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>

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

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

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

<7> [281.188141] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fdi: lanes: 1; data_m: 6039797, data_n: 8388608, link_m: 125829, link_n: 524288, tu: 64

<7> [281.188377] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0

<7> [281.188666] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1

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

<7> [281.189127] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0

<7> [281.189355] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0

<7> [281.189688] i915 0000:00:02.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> [281.189948] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa

<7> [281.190187] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa

<7> [281.190472] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa

<7> [281.190473] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on

<7> [281.190711] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1024x768": 60 64800 1024 1048 1184 1344 768 771 777 806 0x40 0xa

<7> [281.190954] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa

<7> [281.191237] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pipe src: 1024x768+0+0, pixel rate 64800, min cdclk 72000

<7> [281.191525] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0

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

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

<7> [281.192237] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09

<7> [281.192489] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

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

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

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

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

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

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

<7> [281.194274] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:53:primary B] fb: [FB:89] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes

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

<7> [281.194791] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0

<7> [281.196010] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on

<7> [281.196261] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT]

<7> [281.196521] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D]

<7> [281.196748] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D]

<7> [281.197540] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B

<7> [281.198607] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100

<7> [281.198884] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.

<7> [281.199782] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200

<7> [281.200009] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.

<7> [281.200301] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.

<7> [281.200590] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:71:pipe B]

<7> [281.200867] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A

<7> [281.252875] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1]

<7> [281.253428] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:71:pipe B]

<6> [287.914872] [IGT] kms_flip: finished subtest B-VGA1, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank@b-vga1