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

Detail	Value
Duration	1.43 seconds
Hostname	shard-snb1
Igt-Version	IGT-Version: 2.3-g734c9a354 (x86_64) (Linux: 7.0.0-rc3-CI_DRM_18112-g9583680736b0+ 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:2120 __igt_unique____real_main2043() #4 ../tests/kms_flip.c:2043 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-VGA1: FAIL (1.426s)
Err	Starting dynamic subtest: B-VGA1 (kms_flip:22627) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:22627) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-VGA1 failed. ** DEBUG (kms_flip:22627) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x100000000000001, size=0) (kms_flip:22627) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:22627) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:22627) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=4096) (kms_flip:22627) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:22627) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x100000000000001, size=0) (kms_flip:22627) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:22627) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:22627) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=4096) (kms_flip:22627) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:22627) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:22627) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:22627) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS (kms_flip:22627) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:22627) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:22627) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS (kms_flip:22627) igt_kms-INFO: 1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa (kms_flip:22627) DEBUG: No stale events found (kms_flip:22627) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 (kms_flip:22627) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 (kms_flip:22627) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 273.067810 current_received_ts = 273.067261 current_seq = 9293 count = 0 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 9us (kms_flip:22627) DEBUG: name = flip last_ts = 273.067810 last_received_ts = 273.067261 last_seq = 9293 current_ts = 273.084534 current_received_ts = 273.083984 current_seq = 9294 count = 1 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.084534 last_received_ts = 273.083984 last_seq = 9294 current_ts = 273.101257 current_received_ts = 273.100677 current_seq = 9295 count = 2 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.101257 last_received_ts = 273.100677 last_seq = 9295 current_ts = 273.117981 current_received_ts = 273.117401 current_seq = 9296 count = 3 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 9us (kms_flip:22627) DEBUG: name = flip last_ts = 273.117981 last_received_ts = 273.117401 last_seq = 9296 current_ts = 273.134674 current_received_ts = 273.134125 current_seq = 9297 count = 4 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.134674 last_received_ts = 273.134125 last_seq = 9297 current_ts = 273.151398 current_received_ts = 273.150848 current_seq = 9298 count = 5 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.151398 last_received_ts = 273.150848 last_seq = 9298 current_ts = 273.168121 current_received_ts = 273.167511 current_seq = 9299 count = 6 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.168121 last_received_ts = 273.167511 last_seq = 9299 current_ts = 273.184845 current_received_ts = 273.184265 current_seq = 9300 count = 7 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.184845 last_received_ts = 273.184265 last_seq = 9300 current_ts = 273.201569 current_received_ts = 273.200989 current_seq = 9301 count = 8 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.201569 last_received_ts = 273.200989 last_seq = 9301 current_ts = 273.218262 current_received_ts = 273.217712 current_seq = 9302 count = 9 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.218262 last_received_ts = 273.217712 last_seq = 9302 current_ts = 273.234985 current_received_ts = 273.234436 current_seq = 9303 count = 10 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.234985 last_received_ts = 273.234436 last_seq = 9303 current_ts = 273.251709 current_received_ts = 273.251099 current_seq = 9304 count = 11 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.251709 last_received_ts = 273.251099 last_seq = 9304 current_ts = 273.268402 current_received_ts = 273.267853 current_seq = 9305 count = 12 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 9us (kms_flip:22627) DEBUG: name = flip last_ts = 273.268402 last_received_ts = 273.267853 last_seq = 9305 current_ts = 273.285126 current_received_ts = 273.284546 current_seq = 9306 count = 13 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.285126 last_received_ts = 273.284546 last_seq = 9306 current_ts = 273.301819 current_received_ts = 273.301270 current_seq = 9307 count = 14 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.301819 last_received_ts = 273.301270 last_seq = 9307 current_ts = 273.318542 current_received_ts = 273.317993 current_seq = 9308 count = 15 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.318542 last_received_ts = 273.317993 last_seq = 9308 current_ts = 273.335266 current_received_ts = 273.334717 current_seq = 9309 count = 16 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.335266 last_received_ts = 273.334717 last_seq = 9309 current_ts = 273.351990 current_received_ts = 273.351410 current_seq = 9310 count = 17 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 7us (kms_flip:22627) DEBUG: name = flip last_ts = 273.351990 last_received_ts = 273.351410 last_seq = 9310 current_ts = 273.368683 current_received_ts = 273.368134 current_seq = 9311 count = 18 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.368683 last_received_ts = 273.368134 last_seq = 9311 current_ts = 273.385406 current_received_ts = 273.384857 current_seq = 9312 count = 19 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.385406 last_received_ts = 273.384857 last_seq = 9312 current_ts = 273.402130 current_received_ts = 273.401550 current_seq = 9313 count = 20 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.402130 last_received_ts = 273.401550 last_seq = 9313 current_ts = 273.418854 current_received_ts = 273.418274 current_seq = 9314 count = 21 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 7us (kms_flip:22627) DEBUG: name = flip last_ts = 273.418854 last_received_ts = 273.418274 last_seq = 9314 current_ts = 273.435547 current_received_ts = 273.434998 current_seq = 9315 count = 22 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.435547 last_received_ts = 273.434998 last_seq = 9315 current_ts = 273.452271 current_received_ts = 273.451721 current_seq = 9316 count = 23 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.452271 last_received_ts = 273.451721 last_seq = 9316 current_ts = 273.468994 current_received_ts = 273.468414 current_seq = 9317 count = 24 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.468994 last_received_ts = 273.468414 last_seq = 9317 current_ts = 273.485718 current_received_ts = 273.485138 current_seq = 9318 count = 25 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 9us (kms_flip:22627) DEBUG: name = flip last_ts = 273.485718 last_received_ts = 273.485138 last_seq = 9318 current_ts = 273.502411 current_received_ts = 273.501862 current_seq = 9319 count = 26 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.502411 last_received_ts = 273.501862 last_seq = 9319 current_ts = 273.519135 current_received_ts = 273.518585 current_seq = 9320 count = 27 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.519135 last_received_ts = 273.518585 last_seq = 9320 current_ts = 273.535858 current_received_ts = 273.535278 current_seq = 9321 count = 28 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 7us (kms_flip:22627) DEBUG: name = flip last_ts = 273.535858 last_received_ts = 273.535278 last_seq = 9321 current_ts = 273.552551 current_received_ts = 273.552032 current_seq = 9322 count = 29 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.552551 last_received_ts = 273.552032 last_seq = 9322 current_ts = 273.569275 current_received_ts = 273.568726 current_seq = 9323 count = 30 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.569275 last_received_ts = 273.568726 last_seq = 9323 current_ts = 273.585999 current_received_ts = 273.585449 current_seq = 9324 count = 31 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.585999 last_received_ts = 273.585449 last_seq = 9324 current_ts = 273.602692 current_received_ts = 273.602142 current_seq = 9325 count = 32 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.602692 last_received_ts = 273.602142 last_seq = 9325 current_ts = 273.619415 current_received_ts = 273.618866 current_seq = 9326 count = 33 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.619415 last_received_ts = 273.618866 last_seq = 9326 current_ts = 273.636139 current_received_ts = 273.635559 current_seq = 9327 count = 34 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 9us (kms_flip:22627) DEBUG: name = flip last_ts = 273.636139 last_received_ts = 273.635559 last_seq = 9327 current_ts = 273.652863 current_received_ts = 273.652283 current_seq = 9328 count = 35 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 9us (kms_flip:22627) DEBUG: name = flip last_ts = 273.652863 last_received_ts = 273.652283 last_seq = 9328 current_ts = 273.669556 current_received_ts = 273.669037 current_seq = 9329 count = 36 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.669556 last_received_ts = 273.669037 last_seq = 9329 current_ts = 273.686279 current_received_ts = 273.685730 current_seq = 9330 count = 37 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 7us (kms_flip:22627) DEBUG: name = flip last_ts = 273.686279 last_received_ts = 273.685730 last_seq = 9330 current_ts = 273.703003 current_received_ts = 273.702423 current_seq = 9331 count = 38 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.703003 last_received_ts = 273.702423 last_seq = 9331 current_ts = 273.719727 current_received_ts = 273.719147 current_seq = 9332 count = 39 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.719727 last_received_ts = 273.719147 last_seq = 9332 current_ts = 273.736420 current_received_ts = 273.735870 current_seq = 9333 count = 40 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.736420 last_received_ts = 273.735870 last_seq = 9333 current_ts = 273.753143 current_received_ts = 273.752594 current_seq = 9334 count = 41 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.753143 last_received_ts = 273.752594 last_seq = 9334 current_ts = 273.769867 current_received_ts = 273.769287 current_seq = 9335 count = 42 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 9us (kms_flip:22627) DEBUG: name = flip last_ts = 273.769867 last_received_ts = 273.769287 last_seq = 9335 current_ts = 273.786560 current_received_ts = 273.786041 current_seq = 9336 count = 43 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.786560 last_received_ts = 273.786041 last_seq = 9336 current_ts = 273.803284 current_received_ts = 273.802734 current_seq = 9337 count = 44 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.803284 last_received_ts = 273.802734 last_seq = 9337 current_ts = 273.820007 current_received_ts = 273.819458 current_seq = 9338 count = 45 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.820007 last_received_ts = 273.819458 last_seq = 9338 current_ts = 273.836731 current_received_ts = 273.836151 current_seq = 9339 count = 46 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.836731 last_received_ts = 273.836151 last_seq = 9339 current_ts = 273.853424 current_received_ts = 273.852844 current_seq = 9340 count = 47 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.853424 last_received_ts = 273.852844 last_seq = 9340 current_ts = 273.870148 current_received_ts = 273.869568 current_seq = 9341 count = 48 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.870148 last_received_ts = 273.869568 last_seq = 9341 current_ts = 273.886871 current_received_ts = 273.886292 current_seq = 9342 count = 49 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.886871 last_received_ts = 273.886292 last_seq = 9342 current_ts = 273.903564 current_received_ts = 273.902985 current_seq = 9343 count = 50 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 7us (kms_flip:22627) DEBUG: name = flip last_ts = 273.903564 last_received_ts = 273.902985 last_seq = 9343 current_ts = 273.920288 current_received_ts = 273.919739 current_seq = 9344 count = 51 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.920288 last_received_ts = 273.919739 last_seq = 9344 current_ts = 273.937012 current_received_ts = 273.936401 current_seq = 9345 count = 52 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.937012 last_received_ts = 273.936401 last_seq = 9345 current_ts = 273.953735 current_received_ts = 273.953156 current_seq = 9346 count = 53 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.953735 last_received_ts = 273.953156 last_seq = 9346 current_ts = 273.970428 current_received_ts = 273.969879 current_seq = 9347 count = 54 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.970428 last_received_ts = 273.969879 last_seq = 9347 current_ts = 273.987152 current_received_ts = 273.986603 current_seq = 9348 count = 55 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 273.987152 last_received_ts = 273.986603 last_seq = 9348 current_ts = 274.003876 current_received_ts = 274.003265 current_seq = 9349 count = 56 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 274.003876 last_received_ts = 274.003265 last_seq = 9349 current_ts = 274.020599 current_received_ts = 274.020050 current_seq = 9350 count = 57 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 274.020599 last_received_ts = 274.020050 last_seq = 9350 current_ts = 274.037292 current_received_ts = 274.036743 current_seq = 9351 count = 58 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 274.037292 last_received_ts = 274.036743 last_seq = 9351 current_ts = 274.054016 current_received_ts = 274.053406 current_seq = 9352 count = 59 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 7us (kms_flip:22627) DEBUG: name = flip last_ts = 274.054016 last_received_ts = 274.053406 last_seq = 9352 current_ts = 274.070740 current_received_ts = 274.070160 current_seq = 9353 count = 60 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 274.070740 last_received_ts = 274.070160 last_seq = 9353 current_ts = 274.087433 current_received_ts = 274.086884 current_seq = 9354 count = 61 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 274.087433 last_received_ts = 274.086884 last_seq = 9354 current_ts = 274.104156 current_received_ts = 274.103577 current_seq = 9355 count = 62 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 9us (kms_flip:22627) DEBUG: name = flip last_ts = 274.104156 last_received_ts = 274.103577 last_seq = 9355 current_ts = 274.120880 current_received_ts = 274.120300 current_seq = 9356 count = 63 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 274.120880 last_received_ts = 274.120300 last_seq = 9356 current_ts = 274.137604 current_received_ts = 274.137085 current_seq = 9357 count = 64 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 9us (kms_flip:22627) DEBUG: name = flip last_ts = 274.137604 last_received_ts = 274.137085 last_seq = 9357 current_ts = 274.154297 current_received_ts = 274.153748 current_seq = 9358 count = 65 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 9us (kms_flip:22627) DEBUG: name = flip last_ts = 274.154297 last_received_ts = 274.153748 last_seq = 9358 current_ts = 274.171021 current_received_ts = 274.170441 current_seq = 9359 count = 66 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 274.171021 last_received_ts = 274.170441 last_seq = 9359 current_ts = 274.187744 current_received_ts = 274.187164 current_seq = 9360 count = 67 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 274.187744 last_received_ts = 274.187164 last_seq = 9360 current_ts = 274.204468 current_received_ts = 274.203888 current_seq = 9361 count = 68 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 274.204468 last_received_ts = 274.203888 last_seq = 9361 current_ts = 274.221161 current_received_ts = 274.220612 current_seq = 9362 count = 69 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 9us (kms_flip:22627) DEBUG: name = flip last_ts = 274.221161 last_received_ts = 274.220612 last_seq = 9362 current_ts = 274.237885 current_received_ts = 274.237335 current_seq = 9363 count = 70 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 8us (kms_flip:22627) DEBUG: name = flip last_ts = 274.237885 last_received_ts = 274.237335 last_seq = 9363 current_ts = 274.254608 current_received_ts = 274.254059 current_seq = 9364 count = 71 seq_step = 1 (kms_flip:22627) DEBUG: Vblank took 614us (kms_flip:22627) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:22627) CRITICAL: Failed assertion: end - start < 500 (kms_flip:22627) igt_core-INFO: Stack trace: (kms_flip:22627) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:22627) igt_core-INFO: #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0() (kms_flip:22627) igt_core-INFO: #2 ../tests/kms_flip.c:1887 run_test() (kms_flip:22627) igt_core-INFO: #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043() (kms_flip:22627) igt_core-INFO: #4 ../tests/kms_flip.c:2043 main() (kms_flip:22627) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:22627) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:22627) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-VGA1: FAIL (1.426s)
Dmesg	<6> [272.485668] [IGT] kms_flip: starting dynamic subtest B-VGA1 <7> [272.486158] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:89] <7> [272.486296] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:90] <7> [272.521332] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:52:pipe A] <7> [272.521570] 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> [272.522202] 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> [272.522743] 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> [272.523299] 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> [272.523815] 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> [272.524364] 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> [272.524688] 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> [272.524970] 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> [272.525218] 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> [272.525484] 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> [272.525932] 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> [272.526300] 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> [272.526677] 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> [272.526910] 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> [272.527143] 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> [272.527376] 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> [272.527628] 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> [272.527862] 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> [272.528095] 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> [272.528327] 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> [272.528573] 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> [272.528806] 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> [272.529038] 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> [272.529270] 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> [272.529502] 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> [272.529822] 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> [272.530055] 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> [272.530288] 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> [272.530574] 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> [272.530811] 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> [272.531037] 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> [272.531263] 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> [272.531489] 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> [272.531782] 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> [272.532026] 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> [272.532253] 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> [272.532480] 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> [272.532758] 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> [272.532996] 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> [272.533224] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:52:pipe A] fastset requirement not met, forcing full modeset <7> [272.533450] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:52:pipe A] releasing PCH DPLL A <7> [272.533749] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:52:pipe A] min cdclk: 72000 kHz -> 0 kHz <7> [272.533991] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:52:pipe A] enable: no [modeset] <7> [272.534217] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:34:primary A] fb: [NOFB], visible: no <7> [272.534633] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [272.552366] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found <7> [272.552874] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found <7> [272.553335] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found <7> [272.567565] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:52:pipe A] <7> [272.568085] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A <7> [272.568831] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT] <7> [272.569309] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D] <7> [272.569814] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D] <7> [272.570306] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1] <7> [272.570939] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:52:pipe A] <7> [272.571344] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B] <7> [272.571494] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B] <7> [272.571518] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:72:VGA-1] <7> [272.571670] 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> [272.571915] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [272.572143] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1 <7> [272.572365] 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> [272.572628] 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> [272.572876] 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> [272.573103] 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> [272.573330] 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> [272.573579] 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> [272.573832] 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> [272.574059] 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> [272.574285] 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> [272.574512] 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> [272.574777] 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> [272.575018] 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> [272.575244] 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> [272.575471] 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> [272.575737] 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> [272.575988] 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> [272.576215] 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> [272.576441] 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> [272.576718] 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> [272.576966] 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> [272.577193] 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> [272.577419] 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> [272.577666] 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> [272.577910] 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> [272.578136] 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> [272.578362] 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> [272.578625] 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> [272.578869] 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> [272.579096] 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> [272.579322] 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> [272.579587] 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> [272.579856] 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> [272.580084] 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> [272.580310] 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> [272.580559] 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> [272.580820] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in dpll_hw_state <7> [272.581046] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [272.581272] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06 <7> [272.581498] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [272.581786] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09 <7> [272.582018] 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> [272.582244] 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> [272.582471] 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> [272.582737] 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> [272.582980] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] fastset requirement not met, forcing full modeset <7> [272.583238] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:71:pipe B] min cdclk: 0 kHz -> 72000 kHz <7> [272.583464] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:71:pipe B] allocated PCH DPLL A <7> [272.583706] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:71:pipe B] reserving PCH DPLL A <7> [272.583960] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:71:pipe B] enable: yes [modeset] <7> [272.584187] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB <7> [272.584413] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [272.584679] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [272.584941] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [272.585166] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [272.585391] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [272.585665] 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> [272.585906] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0 <7> [272.586132] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1 <7> [272.586356] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [272.586638] 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> [272.586876] 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> [272.587101] 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> [272.587326] 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> [272.587692] 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> [272.588056] 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> [272.588403] 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> [272.588806] 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> [272.588827] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on <7> [272.589058] 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> [272.589299] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0 <7> [272.589544] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [272.589870] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [272.590215] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09 <7> [272.590601] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [272.590955] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [272.591285] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [272.591570] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [272.591814] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [272.592039] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [272.592265] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [272.592616] 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> [272.592965] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [272.593309] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0 <7> [272.594654] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on <7> [272.595017] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT] <7> [272.595357] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D] <7> [272.595729] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D] <7> [272.596596] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [272.597687] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100 <7> [272.598032] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done. <7> [272.598936] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x600 <7> [272.599282] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done. <7> [272.599671] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done. <7> [272.600017] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:71:pipe B] <7> [272.600303] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A <7> [272.652335] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1] <7> [272.652921] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:71:pipe B] <6> [273.912389] [IGT] kms_flip: finished subtest B-VGA1, FAIL

Detail

Value

Duration

1.43 seconds

Hostname

shard-snb1

Igt-Version

IGT-Version: 2.3-g734c9a354 (x86_64) (Linux: 7.0.0-rc3-CI_DRM_18112-g9583680736b0+ 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:2120 __igt_unique____real_main2043()
  #4 ../tests/kms_flip.c:2043 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-VGA1: FAIL (1.426s)

Err

Starting dynamic subtest: B-VGA1
(kms_flip:22627) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:22627) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:22627) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
(kms_flip:22627) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:22627) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:22627) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=4096)
(kms_flip:22627) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:22627) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
(kms_flip:22627) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:22627) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:22627) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=4096)
(kms_flip:22627) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:22627) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:22627) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:22627) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:22627) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:22627) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:22627) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:22627) igt_kms-INFO:   1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 
(kms_flip:22627) DEBUG: No stale events found
(kms_flip:22627) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:22627) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:22627) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 273.067810
current_received_ts = 273.067261
current_seq = 9293
count = 0
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 9us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.067810
last_received_ts = 273.067261
last_seq = 9293
current_ts = 273.084534
current_received_ts = 273.083984
current_seq = 9294
count = 1
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.084534
last_received_ts = 273.083984
last_seq = 9294
current_ts = 273.101257
current_received_ts = 273.100677
current_seq = 9295
count = 2
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.101257
last_received_ts = 273.100677
last_seq = 9295
current_ts = 273.117981
current_received_ts = 273.117401
current_seq = 9296
count = 3
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 9us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.117981
last_received_ts = 273.117401
last_seq = 9296
current_ts = 273.134674
current_received_ts = 273.134125
current_seq = 9297
count = 4
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.134674
last_received_ts = 273.134125
last_seq = 9297
current_ts = 273.151398
current_received_ts = 273.150848
current_seq = 9298
count = 5
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.151398
last_received_ts = 273.150848
last_seq = 9298
current_ts = 273.168121
current_received_ts = 273.167511
current_seq = 9299
count = 6
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.168121
last_received_ts = 273.167511
last_seq = 9299
current_ts = 273.184845
current_received_ts = 273.184265
current_seq = 9300
count = 7
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.184845
last_received_ts = 273.184265
last_seq = 9300
current_ts = 273.201569
current_received_ts = 273.200989
current_seq = 9301
count = 8
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.201569
last_received_ts = 273.200989
last_seq = 9301
current_ts = 273.218262
current_received_ts = 273.217712
current_seq = 9302
count = 9
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.218262
last_received_ts = 273.217712
last_seq = 9302
current_ts = 273.234985
current_received_ts = 273.234436
current_seq = 9303
count = 10
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.234985
last_received_ts = 273.234436
last_seq = 9303
current_ts = 273.251709
current_received_ts = 273.251099
current_seq = 9304
count = 11
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.251709
last_received_ts = 273.251099
last_seq = 9304
current_ts = 273.268402
current_received_ts = 273.267853
current_seq = 9305
count = 12
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 9us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.268402
last_received_ts = 273.267853
last_seq = 9305
current_ts = 273.285126
current_received_ts = 273.284546
current_seq = 9306
count = 13
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.285126
last_received_ts = 273.284546
last_seq = 9306
current_ts = 273.301819
current_received_ts = 273.301270
current_seq = 9307
count = 14
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.301819
last_received_ts = 273.301270
last_seq = 9307
current_ts = 273.318542
current_received_ts = 273.317993
current_seq = 9308
count = 15
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.318542
last_received_ts = 273.317993
last_seq = 9308
current_ts = 273.335266
current_received_ts = 273.334717
current_seq = 9309
count = 16
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.335266
last_received_ts = 273.334717
last_seq = 9309
current_ts = 273.351990
current_received_ts = 273.351410
current_seq = 9310
count = 17
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 7us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.351990
last_received_ts = 273.351410
last_seq = 9310
current_ts = 273.368683
current_received_ts = 273.368134
current_seq = 9311
count = 18
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.368683
last_received_ts = 273.368134
last_seq = 9311
current_ts = 273.385406
current_received_ts = 273.384857
current_seq = 9312
count = 19
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.385406
last_received_ts = 273.384857
last_seq = 9312
current_ts = 273.402130
current_received_ts = 273.401550
current_seq = 9313
count = 20
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.402130
last_received_ts = 273.401550
last_seq = 9313
current_ts = 273.418854
current_received_ts = 273.418274
current_seq = 9314
count = 21
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 7us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.418854
last_received_ts = 273.418274
last_seq = 9314
current_ts = 273.435547
current_received_ts = 273.434998
current_seq = 9315
count = 22
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.435547
last_received_ts = 273.434998
last_seq = 9315
current_ts = 273.452271
current_received_ts = 273.451721
current_seq = 9316
count = 23
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.452271
last_received_ts = 273.451721
last_seq = 9316
current_ts = 273.468994
current_received_ts = 273.468414
current_seq = 9317
count = 24
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.468994
last_received_ts = 273.468414
last_seq = 9317
current_ts = 273.485718
current_received_ts = 273.485138
current_seq = 9318
count = 25
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 9us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.485718
last_received_ts = 273.485138
last_seq = 9318
current_ts = 273.502411
current_received_ts = 273.501862
current_seq = 9319
count = 26
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.502411
last_received_ts = 273.501862
last_seq = 9319
current_ts = 273.519135
current_received_ts = 273.518585
current_seq = 9320
count = 27
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.519135
last_received_ts = 273.518585
last_seq = 9320
current_ts = 273.535858
current_received_ts = 273.535278
current_seq = 9321
count = 28
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 7us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.535858
last_received_ts = 273.535278
last_seq = 9321
current_ts = 273.552551
current_received_ts = 273.552032
current_seq = 9322
count = 29
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.552551
last_received_ts = 273.552032
last_seq = 9322
current_ts = 273.569275
current_received_ts = 273.568726
current_seq = 9323
count = 30
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.569275
last_received_ts = 273.568726
last_seq = 9323
current_ts = 273.585999
current_received_ts = 273.585449
current_seq = 9324
count = 31
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.585999
last_received_ts = 273.585449
last_seq = 9324
current_ts = 273.602692
current_received_ts = 273.602142
current_seq = 9325
count = 32
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.602692
last_received_ts = 273.602142
last_seq = 9325
current_ts = 273.619415
current_received_ts = 273.618866
current_seq = 9326
count = 33
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.619415
last_received_ts = 273.618866
last_seq = 9326
current_ts = 273.636139
current_received_ts = 273.635559
current_seq = 9327
count = 34
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 9us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.636139
last_received_ts = 273.635559
last_seq = 9327
current_ts = 273.652863
current_received_ts = 273.652283
current_seq = 9328
count = 35
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 9us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.652863
last_received_ts = 273.652283
last_seq = 9328
current_ts = 273.669556
current_received_ts = 273.669037
current_seq = 9329
count = 36
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.669556
last_received_ts = 273.669037
last_seq = 9329
current_ts = 273.686279
current_received_ts = 273.685730
current_seq = 9330
count = 37
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 7us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.686279
last_received_ts = 273.685730
last_seq = 9330
current_ts = 273.703003
current_received_ts = 273.702423
current_seq = 9331
count = 38
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.703003
last_received_ts = 273.702423
last_seq = 9331
current_ts = 273.719727
current_received_ts = 273.719147
current_seq = 9332
count = 39
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.719727
last_received_ts = 273.719147
last_seq = 9332
current_ts = 273.736420
current_received_ts = 273.735870
current_seq = 9333
count = 40
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.736420
last_received_ts = 273.735870
last_seq = 9333
current_ts = 273.753143
current_received_ts = 273.752594
current_seq = 9334
count = 41
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.753143
last_received_ts = 273.752594
last_seq = 9334
current_ts = 273.769867
current_received_ts = 273.769287
current_seq = 9335
count = 42
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 9us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.769867
last_received_ts = 273.769287
last_seq = 9335
current_ts = 273.786560
current_received_ts = 273.786041
current_seq = 9336
count = 43
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.786560
last_received_ts = 273.786041
last_seq = 9336
current_ts = 273.803284
current_received_ts = 273.802734
current_seq = 9337
count = 44
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.803284
last_received_ts = 273.802734
last_seq = 9337
current_ts = 273.820007
current_received_ts = 273.819458
current_seq = 9338
count = 45
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.820007
last_received_ts = 273.819458
last_seq = 9338
current_ts = 273.836731
current_received_ts = 273.836151
current_seq = 9339
count = 46
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.836731
last_received_ts = 273.836151
last_seq = 9339
current_ts = 273.853424
current_received_ts = 273.852844
current_seq = 9340
count = 47
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.853424
last_received_ts = 273.852844
last_seq = 9340
current_ts = 273.870148
current_received_ts = 273.869568
current_seq = 9341
count = 48
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.870148
last_received_ts = 273.869568
last_seq = 9341
current_ts = 273.886871
current_received_ts = 273.886292
current_seq = 9342
count = 49
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.886871
last_received_ts = 273.886292
last_seq = 9342
current_ts = 273.903564
current_received_ts = 273.902985
current_seq = 9343
count = 50
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 7us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.903564
last_received_ts = 273.902985
last_seq = 9343
current_ts = 273.920288
current_received_ts = 273.919739
current_seq = 9344
count = 51
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.920288
last_received_ts = 273.919739
last_seq = 9344
current_ts = 273.937012
current_received_ts = 273.936401
current_seq = 9345
count = 52
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.937012
last_received_ts = 273.936401
last_seq = 9345
current_ts = 273.953735
current_received_ts = 273.953156
current_seq = 9346
count = 53
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.953735
last_received_ts = 273.953156
last_seq = 9346
current_ts = 273.970428
current_received_ts = 273.969879
current_seq = 9347
count = 54
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.970428
last_received_ts = 273.969879
last_seq = 9347
current_ts = 273.987152
current_received_ts = 273.986603
current_seq = 9348
count = 55
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 273.987152
last_received_ts = 273.986603
last_seq = 9348
current_ts = 274.003876
current_received_ts = 274.003265
current_seq = 9349
count = 56
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.003876
last_received_ts = 274.003265
last_seq = 9349
current_ts = 274.020599
current_received_ts = 274.020050
current_seq = 9350
count = 57
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.020599
last_received_ts = 274.020050
last_seq = 9350
current_ts = 274.037292
current_received_ts = 274.036743
current_seq = 9351
count = 58
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.037292
last_received_ts = 274.036743
last_seq = 9351
current_ts = 274.054016
current_received_ts = 274.053406
current_seq = 9352
count = 59
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 7us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.054016
last_received_ts = 274.053406
last_seq = 9352
current_ts = 274.070740
current_received_ts = 274.070160
current_seq = 9353
count = 60
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.070740
last_received_ts = 274.070160
last_seq = 9353
current_ts = 274.087433
current_received_ts = 274.086884
current_seq = 9354
count = 61
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.087433
last_received_ts = 274.086884
last_seq = 9354
current_ts = 274.104156
current_received_ts = 274.103577
current_seq = 9355
count = 62
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 9us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.104156
last_received_ts = 274.103577
last_seq = 9355
current_ts = 274.120880
current_received_ts = 274.120300
current_seq = 9356
count = 63
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.120880
last_received_ts = 274.120300
last_seq = 9356
current_ts = 274.137604
current_received_ts = 274.137085
current_seq = 9357
count = 64
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 9us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.137604
last_received_ts = 274.137085
last_seq = 9357
current_ts = 274.154297
current_received_ts = 274.153748
current_seq = 9358
count = 65
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 9us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.154297
last_received_ts = 274.153748
last_seq = 9358
current_ts = 274.171021
current_received_ts = 274.170441
current_seq = 9359
count = 66
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.171021
last_received_ts = 274.170441
last_seq = 9359
current_ts = 274.187744
current_received_ts = 274.187164
current_seq = 9360
count = 67
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.187744
last_received_ts = 274.187164
last_seq = 9360
current_ts = 274.204468
current_received_ts = 274.203888
current_seq = 9361
count = 68
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.204468
last_received_ts = 274.203888
last_seq = 9361
current_ts = 274.221161
current_received_ts = 274.220612
current_seq = 9362
count = 69
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 9us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.221161
last_received_ts = 274.220612
last_seq = 9362
current_ts = 274.237885
current_received_ts = 274.237335
current_seq = 9363
count = 70
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 8us
(kms_flip:22627) DEBUG: name = flip
last_ts = 274.237885
last_received_ts = 274.237335
last_seq = 9363
current_ts = 274.254608
current_received_ts = 274.254059
current_seq = 9364
count = 71
seq_step = 1
(kms_flip:22627) DEBUG: Vblank took 614us
(kms_flip:22627) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:22627) CRITICAL: Failed assertion: end - start < 500
(kms_flip:22627) igt_core-INFO: Stack trace:
(kms_flip:22627) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:22627) igt_core-INFO:   #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0()
(kms_flip:22627) igt_core-INFO:   #2 ../tests/kms_flip.c:1887 run_test()
(kms_flip:22627) igt_core-INFO:   #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043()
(kms_flip:22627) igt_core-INFO:   #4 ../tests/kms_flip.c:2043 main()
(kms_flip:22627) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:22627) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:22627) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (1.426s)

Dmesg

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

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

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

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

<7> [272.521570] 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> [272.522202] 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> [272.522743] 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> [272.523299] 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> [272.523815] 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> [272.524364] 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> [272.524688] 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> [272.524970] 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> [272.525218] 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> [272.525484] 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> [272.525932] 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> [272.526300] 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> [272.526677] 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> [272.526910] 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> [272.527143] 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> [272.527376] 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> [272.527628] 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> [272.527862] 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> [272.528095] 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> [272.528327] 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> [272.528573] 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> [272.528806] 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> [272.529038] 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> [272.529270] 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> [272.529502] 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> [272.529822] 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> [272.530055] 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> [272.530288] 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> [272.530574] 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> [272.530811] 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> [272.531037] 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> [272.531263] 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> [272.531489] 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> [272.531782] 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> [272.532026] 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> [272.532253] 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> [272.532480] 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> [272.532758] 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> [272.532996] 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> [272.533224] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:52:pipe A] fastset requirement not met, forcing full modeset

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [272.571670] 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> [272.571915] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0

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

<7> [272.572365] 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> [272.572628] 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> [272.572876] 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> [272.573103] 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> [272.573330] 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> [272.573579] 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> [272.573832] 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> [272.574059] 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> [272.574285] 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> [272.574512] 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> [272.574777] 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> [272.575018] 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> [272.575244] 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> [272.575471] 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> [272.575737] 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> [272.575988] 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> [272.576215] 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> [272.576441] 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> [272.576718] 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> [272.576966] 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> [272.577193] 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> [272.577419] 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> [272.577666] 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> [272.577910] 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> [272.578136] 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> [272.578362] 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> [272.578625] 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> [272.578869] 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> [272.579096] 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> [272.579322] 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> [272.579587] 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> [272.579856] 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> [272.580084] 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> [272.580310] 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> [272.580559] 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> [272.580820] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in dpll_hw_state

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

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

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

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

<7> [272.582018] 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> [272.582244] 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> [272.582471] 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> [272.582737] 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> [272.582980] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] fastset requirement not met, forcing full modeset

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

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

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

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

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

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

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

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

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

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

<7> [272.585665] 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> [272.585906] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0

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

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

<7> [272.586638] 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> [272.586876] 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> [272.587101] 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> [272.587326] 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> [272.587692] 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> [272.588056] 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> [272.588403] 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> [272.588806] 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> [272.588827] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on

<7> [272.589058] 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> [272.589299] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0

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

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

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

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

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

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

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

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

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

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

<7> [272.592616] 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> [272.592965] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0

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

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

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

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

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

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

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

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

<7> [272.598936] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x600

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

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

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

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

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

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

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

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