igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a3 on shard-dg1@IGTPW

Detail	Value
Duration	1.38 seconds
Hostname	shard-dg1-13
Igt-Version	IGT-Version: 2.4-g08dd1d029 (x86_64) (Linux: 7.1.0-rc6-CI_DRM_18617-g4354c7059304+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A3 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2106 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-HDMI-A3: FAIL (1.377s)
Err	Starting dynamic subtest: B-HDMI-A3 [164.262950] (kms_flip:2320) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [164.263072] (kms_flip:2320) CRITICAL: Failed assertion: end - start < 500 [164.263162] (kms_flip:2320) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-HDMI-A3 failed. ** DEBUG [162.959228] (kms_flip:2320) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0) [162.959330] (kms_flip:2320) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [162.959406] (kms_flip:2320) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [162.959745] (kms_flip:2320) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680) [162.959759] (kms_flip:2320) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) [162.959971] (kms_flip:2320) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0) [162.960067] (kms_flip:2320) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [162.960145] (kms_flip:2320) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [162.960461] (kms_flip:2320) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680) [162.960473] (kms_flip:2320) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) [162.960721] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [162.960827] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [162.963177] (kms_flip:2320) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) [162.964045] (kms_flip:2320) intel_allocator_reloc-DEBUG: Using reloc allocator [162.964117] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [162.964125] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [162.982412] (kms_flip:2320) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) [162.982759] (kms_flip:2320) intel_allocator_reloc-DEBUG: Using reloc allocator [162.982836] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [162.982845] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [162.982854] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [162.982862] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [162.989104] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [162.989125] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [162.991119] (kms_flip:2320) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) [162.991431] (kms_flip:2320) intel_allocator_reloc-DEBUG: Using reloc allocator [162.991507] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [162.991516] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [163.011302] (kms_flip:2320) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) [163.011622] (kms_flip:2320) intel_allocator_reloc-DEBUG: Using reloc allocator [163.011700] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [163.011709] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [163.011718] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [163.011726] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info [163.018168] (kms_flip:2320) igt_kms-INFO: 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 [163.020257] (kms_flip:2320) DEBUG: No stale events found [163.096639] (kms_flip:2320) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 [163.096733] (kms_flip:2320) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 [163.128393] (kms_flip:2320) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 163.284897 current_received_ts = 163.284409 current_seq = 20 count = 0 seq_step = 1 [163.128418] (kms_flip:2320) DEBUG: Vblank took 22us [163.144957] (kms_flip:2320) DEBUG: name = flip last_ts = 163.284897 last_received_ts = 163.284409 last_seq = 20 current_ts = 163.301575 current_received_ts = 163.300980 current_seq = 21 count = 1 seq_step = 1 [163.144991] (kms_flip:2320) DEBUG: Vblank took 31us [163.161727] (kms_flip:2320) DEBUG: name = flip last_ts = 163.301575 last_received_ts = 163.300980 last_seq = 21 current_ts = 163.318237 current_received_ts = 163.317749 current_seq = 22 count = 2 seq_step = 1 [163.161760] (kms_flip:2320) DEBUG: Vblank took 27us [163.178402] (kms_flip:2320) DEBUG: name = flip last_ts = 163.318237 last_received_ts = 163.317749 last_seq = 22 current_ts = 163.334900 current_received_ts = 163.334412 current_seq = 23 count = 3 seq_step = 1 [163.178445] (kms_flip:2320) DEBUG: Vblank took 34us [163.195176] (kms_flip:2320) DEBUG: name = flip last_ts = 163.334900 last_received_ts = 163.334412 last_seq = 23 current_ts = 163.351578 current_received_ts = 163.351181 current_seq = 24 count = 4 seq_step = 1 [163.195246] (kms_flip:2320) DEBUG: Vblank took 55us [163.211860] (kms_flip:2320) DEBUG: name = flip last_ts = 163.351578 last_received_ts = 163.351181 last_seq = 24 current_ts = 163.368240 current_received_ts = 163.367813 current_seq = 25 count = 5 seq_step = 1 [163.211929] (kms_flip:2320) DEBUG: Vblank took 55us [163.228478] (kms_flip:2320) DEBUG: name = flip last_ts = 163.368240 last_received_ts = 163.367813 last_seq = 25 current_ts = 163.384903 current_received_ts = 163.384491 current_seq = 26 count = 6 seq_step = 1 [163.228548] (kms_flip:2320) DEBUG: Vblank took 56us [163.245095] (kms_flip:2320) DEBUG: name = flip last_ts = 163.384903 last_received_ts = 163.384491 last_seq = 26 current_ts = 163.401581 current_received_ts = 163.401108 current_seq = 27 count = 7 seq_step = 1 [163.245166] (kms_flip:2320) DEBUG: Vblank took 54us [163.261811] (kms_flip:2320) DEBUG: name = flip last_ts = 163.401581 last_received_ts = 163.401108 last_seq = 27 current_ts = 163.418243 current_received_ts = 163.417816 current_seq = 28 count = 8 seq_step = 1 [163.261881] (kms_flip:2320) DEBUG: Vblank took 55us [163.278480] (kms_flip:2320) DEBUG: name = flip last_ts = 163.418243 last_received_ts = 163.417816 last_seq = 28 current_ts = 163.434906 current_received_ts = 163.434494 current_seq = 29 count = 9 seq_step = 1 [163.278550] (kms_flip:2320) DEBUG: Vblank took 55us [163.295141] (kms_flip:2320) DEBUG: name = flip last_ts = 163.434906 last_received_ts = 163.434494 last_seq = 29 current_ts = 163.451584 current_received_ts = 163.451157 current_seq = 30 count = 10 seq_step = 1 [163.295210] (kms_flip:2320) DEBUG: Vblank took 54us [163.311809] (kms_flip:2320) DEBUG: name = flip last_ts = 163.451584 last_received_ts = 163.451157 last_seq = 30 current_ts = 163.468246 current_received_ts = 163.467819 current_seq = 31 count = 11 seq_step = 1 [163.311878] (kms_flip:2320) DEBUG: Vblank took 55us [163.328521] (kms_flip:2320) DEBUG: name = flip last_ts = 163.468246 last_received_ts = 163.467819 last_seq = 31 current_ts = 163.484909 current_received_ts = 163.484543 current_seq = 32 count = 12 seq_step = 1 [163.328590] (kms_flip:2320) DEBUG: Vblank took 55us [163.345142] (kms_flip:2320) DEBUG: name = flip last_ts = 163.484909 last_received_ts = 163.484543 last_seq = 32 current_ts = 163.501587 current_received_ts = 163.501160 current_seq = 33 count = 13 seq_step = 1 [163.345211] (kms_flip:2320) DEBUG: Vblank took 55us [163.361811] (kms_flip:2320) DEBUG: name = flip last_ts = 163.501587 last_received_ts = 163.501160 last_seq = 33 current_ts = 163.518250 current_received_ts = 163.517838 current_seq = 34 count = 14 seq_step = 1 [163.361880] (kms_flip:2320) DEBUG: Vblank took 55us [163.378476] (kms_flip:2320) DEBUG: name = flip last_ts = 163.518250 last_received_ts = 163.517838 last_seq = 34 current_ts = 163.534927 current_received_ts = 163.534500 current_seq = 35 count = 15 seq_step = 1 [163.378547] (kms_flip:2320) DEBUG: Vblank took 55us [163.395134] (kms_flip:2320) DEBUG: name = flip last_ts = 163.534927 last_received_ts = 163.534500 last_seq = 35 current_ts = 163.551590 current_received_ts = 163.551163 current_seq = 36 count = 16 seq_step = 1 [163.395202] (kms_flip:2320) DEBUG: Vblank took 54us [163.411811] (kms_flip:2320) DEBUG: name = flip last_ts = 163.551590 last_received_ts = 163.551163 last_seq = 36 current_ts = 163.568253 current_received_ts = 163.567841 current_seq = 37 count = 17 seq_step = 1 [163.411880] (kms_flip:2320) DEBUG: Vblank took 55us [163.428475] (kms_flip:2320) DEBUG: name = flip last_ts = 163.568253 last_received_ts = 163.567841 last_seq = 37 current_ts = 163.584930 current_received_ts = 163.584503 current_seq = 38 count = 18 seq_step = 1 [163.428544] (kms_flip:2320) DEBUG: Vblank took 55us [163.445201] (kms_flip:2320) DEBUG: name = flip last_ts = 163.584930 last_received_ts = 163.584503 last_seq = 38 current_ts = 163.601593 current_received_ts = 163.601181 current_seq = 39 count = 19 seq_step = 1 [163.445270] (kms_flip:2320) DEBUG: Vblank took 54us [163.461813] (kms_flip:2320) DEBUG: name = flip last_ts = 163.601593 last_received_ts = 163.601181 last_seq = 39 current_ts = 163.618256 current_received_ts = 163.617844 current_seq = 40 count = 20 seq_step = 1 [163.461882] (kms_flip:2320) DEBUG: Vblank took 54us [163.478471] (kms_flip:2320) DEBUG: name = flip last_ts = 163.618256 last_received_ts = 163.617844 last_seq = 40 current_ts = 163.634933 current_received_ts = 163.634506 current_seq = 41 count = 21 seq_step = 1 [163.478539] (kms_flip:2320) DEBUG: Vblank took 55us [163.495125] (kms_flip:2320) DEBUG: name = flip last_ts = 163.634933 last_received_ts = 163.634506 last_seq = 41 current_ts = 163.651596 current_received_ts = 163.651154 current_seq = 42 count = 22 seq_step = 1 [163.495195] (kms_flip:2320) DEBUG: Vblank took 55us [163.511809] (kms_flip:2320) DEBUG: name = flip last_ts = 163.651596 last_received_ts = 163.651154 last_seq = 42 current_ts = 163.668259 current_received_ts = 163.667847 current_seq = 43 count = 23 seq_step = 1 [163.511880] (kms_flip:2320) DEBUG: Vblank took 55us [163.528475] (kms_flip:2320) DEBUG: name = flip last_ts = 163.668259 last_received_ts = 163.667847 last_seq = 43 current_ts = 163.684937 current_received_ts = 163.684509 current_seq = 44 count = 24 seq_step = 1 [163.528545] (kms_flip:2320) DEBUG: Vblank took 56us [163.545125] (kms_flip:2320) DEBUG: name = flip last_ts = 163.684937 last_received_ts = 163.684509 last_seq = 44 current_ts = 163.701599 current_received_ts = 163.701157 current_seq = 45 count = 25 seq_step = 1 [163.545194] (kms_flip:2320) DEBUG: Vblank took 54us [163.561870] (kms_flip:2320) DEBUG: name = flip last_ts = 163.701599 last_received_ts = 163.701157 last_seq = 45 current_ts = 163.718262 current_received_ts = 163.717911 current_seq = 46 count = 26 seq_step = 1 [163.561975] (kms_flip:2320) DEBUG: Vblank took 55us [163.578475] (kms_flip:2320) DEBUG: name = flip last_ts = 163.718262 last_received_ts = 163.717911 last_seq = 46 current_ts = 163.734940 current_received_ts = 163.734512 current_seq = 47 count = 27 seq_step = 1 [163.578545] (kms_flip:2320) DEBUG: Vblank took 55us [163.595054] (kms_flip:2320) DEBUG: name = flip last_ts = 163.734940 last_received_ts = 163.734512 last_seq = 47 current_ts = 163.751602 current_received_ts = 163.751099 current_seq = 48 count = 28 seq_step = 1 [163.595123] (kms_flip:2320) DEBUG: Vblank took 55us [163.611812] (kms_flip:2320) DEBUG: name = flip last_ts = 163.751602 last_received_ts = 163.751099 last_seq = 48 current_ts = 163.768280 current_received_ts = 163.767853 current_seq = 49 count = 29 seq_step = 1 [163.611881] (kms_flip:2320) DEBUG: Vblank took 55us [163.628472] (kms_flip:2320) DEBUG: name = flip last_ts = 163.768280 last_received_ts = 163.767853 last_seq = 49 current_ts = 163.784943 current_received_ts = 163.784515 current_seq = 50 count = 30 seq_step = 1 [163.628541] (kms_flip:2320) DEBUG: Vblank took 55us [163.645114] (kms_flip:2320) DEBUG: name = flip last_ts = 163.784943 last_received_ts = 163.784515 last_seq = 50 current_ts = 163.801605 current_received_ts = 163.801163 current_seq = 51 count = 31 seq_step = 1 [163.645184] (kms_flip:2320) DEBUG: Vblank took 55us [163.661808] (kms_flip:2320) DEBUG: name = flip last_ts = 163.801605 last_received_ts = 163.801163 last_seq = 51 current_ts = 163.818283 current_received_ts = 163.817856 current_seq = 52 count = 32 seq_step = 1 [163.661878] (kms_flip:2320) DEBUG: Vblank took 56us [163.678507] (kms_flip:2320) DEBUG: name = flip last_ts = 163.818283 last_received_ts = 163.817856 last_seq = 52 current_ts = 163.834946 current_received_ts = 163.834503 current_seq = 53 count = 33 seq_step = 1 [163.678575] (kms_flip:2320) DEBUG: Vblank took 54us [163.695112] (kms_flip:2320) DEBUG: name = flip last_ts = 163.834946 last_received_ts = 163.834503 last_seq = 53 current_ts = 163.851608 current_received_ts = 163.851166 current_seq = 54 count = 34 seq_step = 1 [163.695180] (kms_flip:2320) DEBUG: Vblank took 55us [163.711802] (kms_flip:2320) DEBUG: name = flip last_ts = 163.851608 last_received_ts = 163.851166 last_seq = 54 current_ts = 163.868286 current_received_ts = 163.867859 current_seq = 55 count = 35 seq_step = 1 [163.711871] (kms_flip:2320) DEBUG: Vblank took 55us [163.728472] (kms_flip:2320) DEBUG: name = flip last_ts = 163.868286 last_received_ts = 163.867859 last_seq = 55 current_ts = 163.884949 current_received_ts = 163.884521 current_seq = 56 count = 36 seq_step = 1 [163.728541] (kms_flip:2320) DEBUG: Vblank took 55us [163.745108] (kms_flip:2320) DEBUG: name = flip last_ts = 163.884949 last_received_ts = 163.884521 last_seq = 56 current_ts = 163.901611 current_received_ts = 163.901169 current_seq = 57 count = 37 seq_step = 1 [163.745177] (kms_flip:2320) DEBUG: Vblank took 54us [163.761806] (kms_flip:2320) DEBUG: name = flip last_ts = 163.901611 last_received_ts = 163.901169 last_seq = 57 current_ts = 163.918289 current_received_ts = 163.917862 current_seq = 58 count = 38 seq_step = 1 [163.761875] (kms_flip:2320) DEBUG: Vblank took 55us [163.778473] (kms_flip:2320) DEBUG: name = flip last_ts = 163.918289 last_received_ts = 163.917862 last_seq = 58 current_ts = 163.934952 current_received_ts = 163.934525 current_seq = 59 count = 39 seq_step = 1 [163.778543] (kms_flip:2320) DEBUG: Vblank took 54us [163.795126] (kms_flip:2320) DEBUG: name = flip last_ts = 163.934952 last_received_ts = 163.934525 last_seq = 59 current_ts = 163.951614 current_received_ts = 163.951187 current_seq = 60 count = 40 seq_step = 1 [163.795240] (kms_flip:2320) DEBUG: Vblank took 54us [163.811806] (kms_flip:2320) DEBUG: name = flip last_ts = 163.951614 last_received_ts = 163.951187 last_seq = 60 current_ts = 163.968292 current_received_ts = 163.967865 current_seq = 61 count = 41 seq_step = 1 [163.811876] (kms_flip:2320) DEBUG: Vblank took 56us [163.828375] (kms_flip:2320) DEBUG: name = flip last_ts = 163.968292 last_received_ts = 163.967865 last_seq = 61 current_ts = 163.984955 current_received_ts = 163.984436 current_seq = 62 count = 42 seq_step = 1 [163.828443] (kms_flip:2320) DEBUG: Vblank took 54us [163.845107] (kms_flip:2320) DEBUG: name = flip last_ts = 163.984955 last_received_ts = 163.984436 last_seq = 62 current_ts = 164.001633 current_received_ts = 164.001175 current_seq = 63 count = 43 seq_step = 1 [163.845176] (kms_flip:2320) DEBUG: Vblank took 55us [163.861802] (kms_flip:2320) DEBUG: name = flip last_ts = 164.001633 last_received_ts = 164.001175 last_seq = 63 current_ts = 164.018295 current_received_ts = 164.017868 current_seq = 64 count = 44 seq_step = 1 [163.861872] (kms_flip:2320) DEBUG: Vblank took 55us [163.878472] (kms_flip:2320) DEBUG: name = flip last_ts = 164.018295 last_received_ts = 164.017868 last_seq = 64 current_ts = 164.034958 current_received_ts = 164.034531 current_seq = 65 count = 45 seq_step = 1 [163.878541] (kms_flip:2320) DEBUG: Vblank took 55us [163.895118] (kms_flip:2320) DEBUG: name = flip last_ts = 164.034958 last_received_ts = 164.034531 last_seq = 65 current_ts = 164.051636 current_received_ts = 164.051178 current_seq = 66 count = 46 seq_step = 1 [163.895187] (kms_flip:2320) DEBUG: Vblank took 55us [163.911806] (kms_flip:2320) DEBUG: name = flip last_ts = 164.051636 last_received_ts = 164.051178 last_seq = 66 current_ts = 164.068298 current_received_ts = 164.067871 current_seq = 67 count = 47 seq_step = 1 [163.911956] (kms_flip:2320) DEBUG: Vblank took 133us [163.928471] (kms_flip:2320) DEBUG: name = flip last_ts = 164.068298 last_received_ts = 164.067871 last_seq = 67 current_ts = 164.084961 current_received_ts = 164.084549 current_seq = 68 count = 48 seq_step = 1 [163.928540] (kms_flip:2320) DEBUG: Vblank took 55us [163.945076] (kms_flip:2320) DEBUG: name = flip last_ts = 164.084961 last_received_ts = 164.084549 last_seq = 68 current_ts = 164.101639 current_received_ts = 164.101151 current_seq = 69 count = 49 seq_step = 1 [163.945145] (kms_flip:2320) DEBUG: Vblank took 54us [163.961804] (kms_flip:2320) DEBUG: name = flip last_ts = 164.101639 last_received_ts = 164.101151 last_seq = 69 current_ts = 164.118301 current_received_ts = 164.117874 current_seq = 70 count = 50 seq_step = 1 [163.961873] (kms_flip:2320) DEBUG: Vblank took 54us [163.978472] (kms_flip:2320) DEBUG: name = flip last_ts = 164.118301 last_received_ts = 164.117874 last_seq = 70 current_ts = 164.134964 current_received_ts = 164.134552 current_seq = 71 count = 51 seq_step = 1 [163.978541] (kms_flip:2320) DEBUG: Vblank took 55us [163.995155] (kms_flip:2320) DEBUG: name = flip last_ts = 164.134964 last_received_ts = 164.134552 last_seq = 71 current_ts = 164.151642 current_received_ts = 164.151230 current_seq = 72 count = 52 seq_step = 1 [163.995224] (kms_flip:2320) DEBUG: Vblank took 55us [164.011804] (kms_flip:2320) DEBUG: name = flip last_ts = 164.151642 last_received_ts = 164.151230 last_seq = 72 current_ts = 164.168304 current_received_ts = 164.167877 current_seq = 73 count = 53 seq_step = 1 [164.011873] (kms_flip:2320) DEBUG: Vblank took 55us [164.028501] (kms_flip:2320) DEBUG: name = flip last_ts = 164.168304 last_received_ts = 164.167877 last_seq = 73 current_ts = 164.184982 current_received_ts = 164.184586 current_seq = 74 count = 54 seq_step = 1 [164.028573] (kms_flip:2320) DEBUG: Vblank took 54us [164.045116] (kms_flip:2320) DEBUG: name = flip last_ts = 164.184982 last_received_ts = 164.184586 last_seq = 74 current_ts = 164.201645 current_received_ts = 164.201202 current_seq = 75 count = 55 seq_step = 1 [164.045186] (kms_flip:2320) DEBUG: Vblank took 55us [164.061800] (kms_flip:2320) DEBUG: name = flip last_ts = 164.201645 last_received_ts = 164.201202 last_seq = 75 current_ts = 164.218307 current_received_ts = 164.217880 current_seq = 76 count = 56 seq_step = 1 [164.061870] (kms_flip:2320) DEBUG: Vblank took 55us [164.078473] (kms_flip:2320) DEBUG: name = flip last_ts = 164.218307 last_received_ts = 164.217880 last_seq = 76 current_ts = 164.234985 current_received_ts = 164.234558 current_seq = 77 count = 57 seq_step = 1 [164.078543] (kms_flip:2320) DEBUG: Vblank took 55us [164.095167] (kms_flip:2320) DEBUG: name = flip last_ts = 164.234985 last_received_ts = 164.234558 last_seq = 77 current_ts = 164.251648 current_received_ts = 164.251251 current_seq = 78 count = 58 seq_step = 1 [164.095237] (kms_flip:2320) DEBUG: Vblank took 55us [164.111802] (kms_flip:2320) DEBUG: name = flip last_ts = 164.251648 last_received_ts = 164.251251 last_seq = 78 current_ts = 164.268311 current_received_ts = 164.267883 current_seq = 79 count = 59 seq_step = 1 [164.111871] (kms_flip:2320) DEBUG: Vblank took 54us [164.128471] (kms_flip:2320) DEBUG: name = flip last_ts = 164.268311 last_received_ts = 164.267883 last_seq = 79 current_ts = 164.284988 current_received_ts = 164.284561 current_seq = 80 count = 60 seq_step = 1 [164.128540] (kms_flip:2320) DEBUG: Vblank took 56us [164.145224] (kms_flip:2320) DEBUG: name = flip last_ts = 164.284988 last_received_ts = 164.284561 last_seq = 80 current_ts = 164.301651 current_received_ts = 164.301315 current_seq = 81 count = 61 seq_step = 1 [164.145292] (kms_flip:2320) DEBUG: Vblank took 55us [164.161803] (kms_flip:2320) DEBUG: name = flip last_ts = 164.301651 last_received_ts = 164.301315 last_seq = 81 current_ts = 164.318314 current_received_ts = 164.317902 current_seq = 82 count = 62 seq_step = 1 [164.161872] (kms_flip:2320) DEBUG: Vblank took 55us [164.178360] (kms_flip:2320) DEBUG: name = flip last_ts = 164.318314 last_received_ts = 164.317902 last_seq = 82 current_ts = 164.334976 current_received_ts = 164.334457 current_seq = 83 count = 63 seq_step = 1 [164.178429] (kms_flip:2320) DEBUG: Vblank took 54us [164.195169] (kms_flip:2320) DEBUG: name = flip last_ts = 164.334976 last_received_ts = 164.334457 last_seq = 83 current_ts = 164.351654 current_received_ts = 164.351257 current_seq = 84 count = 64 seq_step = 1 [164.195237] (kms_flip:2320) DEBUG: Vblank took 54us [164.211801] (kms_flip:2320) DEBUG: name = flip last_ts = 164.351654 last_received_ts = 164.351257 last_seq = 84 current_ts = 164.368317 current_received_ts = 164.367889 current_seq = 85 count = 65 seq_step = 1 [164.211870] (kms_flip:2320) DEBUG: Vblank took 55us [164.228474] (kms_flip:2320) DEBUG: name = flip last_ts = 164.368317 last_received_ts = 164.367889 last_seq = 85 current_ts = 164.384995 current_received_ts = 164.384567 current_seq = 86 count = 66 seq_step = 1 [164.228544] (kms_flip:2320) DEBUG: Vblank took 55us [164.245161] (kms_flip:2320) DEBUG: name = flip last_ts = 164.384995 last_received_ts = 164.384567 last_seq = 86 current_ts = 164.401657 current_received_ts = 164.401260 current_seq = 87 count = 67 seq_step = 1 [164.245230] (kms_flip:2320) DEBUG: Vblank took 55us [164.261854] (kms_flip:2320) DEBUG: name = flip last_ts = 164.401657 last_received_ts = 164.401260 last_seq = 87 current_ts = 164.418320 current_received_ts = 164.417908 current_seq = 88 count = 68 seq_step = 1 [164.262940] (kms_flip:2320) DEBUG: Vblank took 1070us [164.262950] (kms_flip:2320) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [164.263072] (kms_flip:2320) CRITICAL: Failed assertion: end - start < 500 [164.263162] (kms_flip:2320) CRITICAL: Last errno: 4, Interrupted system call [164.274794] (kms_flip:2320) igt_core-INFO: Stack trace: [164.289429] (kms_flip:2320) igt_core-INFO: #0 ../lib/igt_core.c:2106 __igt_fail_assert() [164.293327] (kms_flip:2320) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [164.293638] (kms_flip:2320) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [164.293786] (kms_flip:2320) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() [164.293986] (kms_flip:2320) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [164.319894] (kms_flip:2320) igt_core-INFO: #5 [__libc_init_first+0x8a] [164.323558] (kms_flip:2320) igt_core-INFO: #6 [__libc_start_main+0x8b] [164.324573] (kms_flip:2320) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A3: FAIL (1.377s)
Dmesg	<6> [163.063968] [IGT] kms_flip: starting dynamic subtest B-HDMI-A3 <7> [163.066920] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:637] <7> [163.067616] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:638] <7> [163.068886] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [163.070793] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [163.089200] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [163.089572] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [163.097860] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [163.098250] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [163.117813] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [163.118435] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [163.127251] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:171:pipe A] <7> [163.127369] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [163.127538] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [163.127689] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [163.127842] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [163.128033] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [163.128237] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [163.128388] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [163.128540] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [163.128692] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [163.128843] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [163.129026] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [163.129192] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [163.129344] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [163.129497] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [163.129648] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [163.129799] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [163.129951] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [163.130144] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [163.130295] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [163.130447] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [163.130598] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [163.130748] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [163.130899] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [163.131094] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [163.131247] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [163.131397] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [163.131548] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [163.131700] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [163.131851] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [163.132050] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [163.132236] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [163.132386] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [163.132538] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [163.132691] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [163.132842] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [163.133023] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [163.133189] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:171:pipe A] fastset requirement not met in port_clock (expected 148500, found 0) <7> [163.133342] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:171:pipe A] fastset requirement not met, forcing full modeset <7> [163.133494] i915 0000:03:00.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:171:pipe A] releasing DPLL 2 <7> [163.133673] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no <7> [163.133821] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:171:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [163.134056] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:165:cursor A] ddb (2012 - 2048) -> ( 0 - 0), size 36 -> 0 <7> [163.134225] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:171:pipe A] min cdclk: 74250 kHz -> 0 kHz <7> [163.134379] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:171:pipe A] enable: no [modeset] <7> [163.134530] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [163.134680] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [163.134830] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [163.135048] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [163.135198] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [163.135347] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:145:plane 6A] fb: [NOFB], visible: no <7> [163.135497] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:155:plane 7A] fb: [NOFB], visible: no <7> [163.135646] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:165:cursor A] fb: [NOFB], visible: no <7> [163.135905] i915 0000:03:00.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [163.141082] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_TC1 <7> [163.141271] i915 0000:03:00.0: [drm:intel_dpll_disable [i915]] disable DPLL 2 (active 0x1, on? 1) for [CRTC:171:pipe A] <7> [163.141456] i915 0000:03:00.0: [drm:intel_dpll_disable [i915]] disabling DPLL 2 <7> [163.141634] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI A/PHY A] <7> [163.141786] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:589:DP-MST A] <7> [163.141937] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:590:DP-MST B] <7> [163.142137] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:591:DP-MST C] <7> [163.142289] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:592:DP-MST D] <7> [163.142439] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:606:DDI B/PHY B] <7> [163.142589] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DDI TC1/PHY C] <7> [163.142760] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST A] <7> [163.142912] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:613:DP-MST B] <7> [163.143110] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:614:DP-MST C] <7> [163.143260] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:615:DP-MST D] <7> [163.143411] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:622:DDI TC2/PHY D] <7> [163.143561] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:624:DP-MST A] <7> [163.143711] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DP-MST B] <7> [163.143861] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:626:DP-MST C] <7> [163.144053] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST D] <7> [163.144204] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:619:HDMI-A-3] <7> [163.144475] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [163.144688] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_3 <7> [163.144879] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [163.145109] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:171:pipe A] <7> [163.145716] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe C] <7> [163.145906] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe B] <7> [163.146141] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:585:pipe D] <7> [163.146330] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe C] <7> [163.146368] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:619:HDMI-A-3] <7> [163.146452] i915 0000:03:00.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:619:HDMI-A-3] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 36, max platform bpp 36) <7> [163.146609] i915 0000:03:00.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [163.146751] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe C] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [163.146902] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:610:DDI TC1/PHY C] [CRTC:309:pipe C] <7> [163.147090] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [163.147243] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [163.147394] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [163.147546] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [163.147697] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [163.147849] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [163.148047] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [163.148199] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [163.148350] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [163.148506] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [163.148659] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [163.148810] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [163.148962] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [163.149164] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [163.149317] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [163.149468] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [163.149620] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [163.149771] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [163.149923] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [163.150144] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [163.150344] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [163.150496] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [163.150647] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [163.150798] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [163.150949] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [163.151142] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [163.151294] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [163.151445] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [163.151596] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [163.151748] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [163.151900] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [163.152096] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [163.152281] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [163.152433] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [163.152584] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [163.152735] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [163.152887] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in port_clock (expected 0, found 148500) <7> [163.153081] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe C] fastset requirement not met, forcing full modeset <7> [163.153259] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no <7> [163.153407] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:309:pipe C] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4 <7> [163.153597] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:173:plane 1C] ddb ( 0 - 0) -> ( 0 - 2012), size 0 -> 2012 <7> [163.153743] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:303:cursor C] ddb ( 0 - 0) -> (2012 - 2048), size 0 -> 36 <7> [163.153890] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,*twm, swm, stwm <7> [163.154086] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 5, 5, 5, 8, 8, 9, 10, 0, 0, 0 <7> [163.154234] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 81, 81, 81, 129, 129, 145, 161, 30, 0, 0 <7> [163.154381] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 91, 91, 91, 143, 143, 161, 179, 31, 0, 0 <7> [163.154547] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:309:pipe C] data rate 594000 num active planes 1 <7> [163.154697] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 34000 required 594 <7> [163.154845] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [163.155054] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:309:pipe C] min cdclk: 0 kHz -> 74250 kHz <7> [163.155224] i915 0000:03:00.0: [drm:intel_find_dpll [i915]] [CRTC:309:pipe C] allocated DPLL 2 <7> [163.155376] i915 0000:03:00.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:309:pipe C] reserving DPLL 2 <7> [163.155529] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:309:pipe C] enable: yes [modeset] <7> [163.155679] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [163.155831] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: C, pipe bpp: 24, dithering: 0 <7> [163.156011] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [163.156176] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [163.156326] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [163.156477] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [163.156627] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0 <7> [163.156778] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [163.156927] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [163.157195] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 42, guardband: 44 vsync start: 0, vsync end: 0 <7> [163.157348] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1081, vmax vblank: 1081, vmin vtotal: 1125, vmax vtotal: 1125 <7> [163.157498] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [163.157649] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [163.157800] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [163.157951] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [163.158146] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5 <7> [163.158298] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [163.158450] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port clock: 148500, pixel rate 148500, min cdclk 74250, min voltage level 0 <7> [163.158600] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] linetime: 119, ips linetime: 0 <7> [163.158750] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [163.158901] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [163.159093] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [163.159244] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [163.159394] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [163.159545] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1001d0, cfgcr1: 0xe84, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0 <7> [163.159697] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [163.159846] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [163.160026] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [163.160191] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [163.160341] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [163.160491] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [163.160641] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [163.160790] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [163.160941] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [163.161129] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [163.161280] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [163.161430] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [163.161580] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:173:plane 1C] fb: [FB:637] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [163.161732] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [163.161882] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [163.162075] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:203:plane 2C] fb: [NOFB], visible: no <7> [163.162226] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:233:plane 3C] fb: [NOFB], visible: no <7> [163.162375] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:263:plane 4C] fb: [NOFB], visible: no <7> [163.162526] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:273:plane 5C] fb: [NOFB], visible: no <7> [163.162675] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:283:plane 6C] fb: [NOFB], visible: no <7> [163.162825] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:293:plane 7C] fb: [NOFB], visible: no <7> [163.162998] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:303:cursor C] fb: [NOFB], visible: no <7> [163.163408] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [163.163578] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_3 <7> [163.163756] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_4 <7> [163.163952] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI A/PHY A] <7> [163.164153] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:589:DP-MST A] <7> [163.164303] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:590:DP-MST B] <7> [163.164454] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:591:DP-MST C] <7> [163.164604] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:592:DP-MST D] <7> [163.164754] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:606:DDI B/PHY B] <7> [163.164904] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DDI TC1/PHY C] <7> [163.165094] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST A] <7> [163.165244] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:613:DP-MST B] <7> [163.165395] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:614:DP-MST C] <7> [163.165544] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:615:DP-MST D] <7> [163.165694] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:622:DDI TC2/PHY D] <7> [163.165844] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:624:DP-MST A] <7> [163.166022] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DP-MST B] <7> [163.166186] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:626:DP-MST C] <7> [163.166337] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST D] <7> [163.166565] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [163.166762] i915 0000:03:00.0: [drm:intel_dpll_enable [i915]] enable DPLL 2 (active 0x4, on? 0) for [CRTC:309:pipe C] <7> [163.166916] i915 0000:03:00.0: [drm:intel_dpll_enable [i915]] enabling DPLL 2 <7> [163.167161] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_TC1 <7> [163.167396] i915 0000:03:00.0: [drm:intel_enable_transcoder [i915]] enabling pipe C <7> [163.202200] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:619:HDMI-A-3] <7> [163.202476] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:309:pipe C] <6> [164.441681] [IGT] kms_flip: finished subtest B-HDMI-A3, FAIL

Detail

Value

Duration

1.38 seconds

Hostname

shard-dg1-13

Igt-Version

IGT-Version: 2.4-g08dd1d029 (x86_64) (Linux: 7.1.0-rc6-CI_DRM_18617-g4354c7059304+ x86_64)

Out

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

Err

Starting dynamic subtest: B-HDMI-A3
[164.262950] (kms_flip:2320) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[164.263072] (kms_flip:2320) CRITICAL: Failed assertion: end - start < 500
[164.263162] (kms_flip:2320) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-HDMI-A3 failed.
**** DEBUG ****
[162.959228] (kms_flip:2320) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
[162.959330] (kms_flip:2320) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[162.959406] (kms_flip:2320) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[162.959745] (kms_flip:2320) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
[162.959759] (kms_flip:2320) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
[162.959971] (kms_flip:2320) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
[162.960067] (kms_flip:2320) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[162.960145] (kms_flip:2320) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[162.960461] (kms_flip:2320) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
[162.960473] (kms_flip:2320) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
[162.960721] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[162.960827] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[162.963177] (kms_flip:2320) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
[162.964045] (kms_flip:2320) intel_allocator_reloc-DEBUG: Using reloc allocator
[162.964117] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[162.964125] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[162.982412] (kms_flip:2320) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
[162.982759] (kms_flip:2320) intel_allocator_reloc-DEBUG: Using reloc allocator
[162.982836] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[162.982845] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[162.982854] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[162.982862] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[162.989104] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[162.989125] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[162.991119] (kms_flip:2320) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
[162.991431] (kms_flip:2320) intel_allocator_reloc-DEBUG: Using reloc allocator
[162.991507] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[162.991516] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[163.011302] (kms_flip:2320) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
[163.011622] (kms_flip:2320) intel_allocator_reloc-DEBUG: Using reloc allocator
[163.011700] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[163.011709] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[163.011718] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[163.011726] (kms_flip:2320) intel_blt-DEBUG: Test requirement passed: cmds_info
[163.018168] (kms_flip:2320) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
[163.020257] (kms_flip:2320) DEBUG: No stale events found
[163.096639] (kms_flip:2320) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
[163.096733] (kms_flip:2320) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
[163.128393] (kms_flip:2320) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 163.284897
current_received_ts = 163.284409
current_seq = 20
count = 0
seq_step = 1
[163.128418] (kms_flip:2320) DEBUG: Vblank took 22us
[163.144957] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.284897
last_received_ts = 163.284409
last_seq = 20
current_ts = 163.301575
current_received_ts = 163.300980
current_seq = 21
count = 1
seq_step = 1
[163.144991] (kms_flip:2320) DEBUG: Vblank took 31us
[163.161727] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.301575
last_received_ts = 163.300980
last_seq = 21
current_ts = 163.318237
current_received_ts = 163.317749
current_seq = 22
count = 2
seq_step = 1
[163.161760] (kms_flip:2320) DEBUG: Vblank took 27us
[163.178402] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.318237
last_received_ts = 163.317749
last_seq = 22
current_ts = 163.334900
current_received_ts = 163.334412
current_seq = 23
count = 3
seq_step = 1
[163.178445] (kms_flip:2320) DEBUG: Vblank took 34us
[163.195176] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.334900
last_received_ts = 163.334412
last_seq = 23
current_ts = 163.351578
current_received_ts = 163.351181
current_seq = 24
count = 4
seq_step = 1
[163.195246] (kms_flip:2320) DEBUG: Vblank took 55us
[163.211860] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.351578
last_received_ts = 163.351181
last_seq = 24
current_ts = 163.368240
current_received_ts = 163.367813
current_seq = 25
count = 5
seq_step = 1
[163.211929] (kms_flip:2320) DEBUG: Vblank took 55us
[163.228478] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.368240
last_received_ts = 163.367813
last_seq = 25
current_ts = 163.384903
current_received_ts = 163.384491
current_seq = 26
count = 6
seq_step = 1
[163.228548] (kms_flip:2320) DEBUG: Vblank took 56us
[163.245095] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.384903
last_received_ts = 163.384491
last_seq = 26
current_ts = 163.401581
current_received_ts = 163.401108
current_seq = 27
count = 7
seq_step = 1
[163.245166] (kms_flip:2320) DEBUG: Vblank took 54us
[163.261811] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.401581
last_received_ts = 163.401108
last_seq = 27
current_ts = 163.418243
current_received_ts = 163.417816
current_seq = 28
count = 8
seq_step = 1
[163.261881] (kms_flip:2320) DEBUG: Vblank took 55us
[163.278480] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.418243
last_received_ts = 163.417816
last_seq = 28
current_ts = 163.434906
current_received_ts = 163.434494
current_seq = 29
count = 9
seq_step = 1
[163.278550] (kms_flip:2320) DEBUG: Vblank took 55us
[163.295141] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.434906
last_received_ts = 163.434494
last_seq = 29
current_ts = 163.451584
current_received_ts = 163.451157
current_seq = 30
count = 10
seq_step = 1
[163.295210] (kms_flip:2320) DEBUG: Vblank took 54us
[163.311809] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.451584
last_received_ts = 163.451157
last_seq = 30
current_ts = 163.468246
current_received_ts = 163.467819
current_seq = 31
count = 11
seq_step = 1
[163.311878] (kms_flip:2320) DEBUG: Vblank took 55us
[163.328521] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.468246
last_received_ts = 163.467819
last_seq = 31
current_ts = 163.484909
current_received_ts = 163.484543
current_seq = 32
count = 12
seq_step = 1
[163.328590] (kms_flip:2320) DEBUG: Vblank took 55us
[163.345142] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.484909
last_received_ts = 163.484543
last_seq = 32
current_ts = 163.501587
current_received_ts = 163.501160
current_seq = 33
count = 13
seq_step = 1
[163.345211] (kms_flip:2320) DEBUG: Vblank took 55us
[163.361811] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.501587
last_received_ts = 163.501160
last_seq = 33
current_ts = 163.518250
current_received_ts = 163.517838
current_seq = 34
count = 14
seq_step = 1
[163.361880] (kms_flip:2320) DEBUG: Vblank took 55us
[163.378476] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.518250
last_received_ts = 163.517838
last_seq = 34
current_ts = 163.534927
current_received_ts = 163.534500
current_seq = 35
count = 15
seq_step = 1
[163.378547] (kms_flip:2320) DEBUG: Vblank took 55us
[163.395134] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.534927
last_received_ts = 163.534500
last_seq = 35
current_ts = 163.551590
current_received_ts = 163.551163
current_seq = 36
count = 16
seq_step = 1
[163.395202] (kms_flip:2320) DEBUG: Vblank took 54us
[163.411811] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.551590
last_received_ts = 163.551163
last_seq = 36
current_ts = 163.568253
current_received_ts = 163.567841
current_seq = 37
count = 17
seq_step = 1
[163.411880] (kms_flip:2320) DEBUG: Vblank took 55us
[163.428475] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.568253
last_received_ts = 163.567841
last_seq = 37
current_ts = 163.584930
current_received_ts = 163.584503
current_seq = 38
count = 18
seq_step = 1
[163.428544] (kms_flip:2320) DEBUG: Vblank took 55us
[163.445201] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.584930
last_received_ts = 163.584503
last_seq = 38
current_ts = 163.601593
current_received_ts = 163.601181
current_seq = 39
count = 19
seq_step = 1
[163.445270] (kms_flip:2320) DEBUG: Vblank took 54us
[163.461813] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.601593
last_received_ts = 163.601181
last_seq = 39
current_ts = 163.618256
current_received_ts = 163.617844
current_seq = 40
count = 20
seq_step = 1
[163.461882] (kms_flip:2320) DEBUG: Vblank took 54us
[163.478471] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.618256
last_received_ts = 163.617844
last_seq = 40
current_ts = 163.634933
current_received_ts = 163.634506
current_seq = 41
count = 21
seq_step = 1
[163.478539] (kms_flip:2320) DEBUG: Vblank took 55us
[163.495125] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.634933
last_received_ts = 163.634506
last_seq = 41
current_ts = 163.651596
current_received_ts = 163.651154
current_seq = 42
count = 22
seq_step = 1
[163.495195] (kms_flip:2320) DEBUG: Vblank took 55us
[163.511809] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.651596
last_received_ts = 163.651154
last_seq = 42
current_ts = 163.668259
current_received_ts = 163.667847
current_seq = 43
count = 23
seq_step = 1
[163.511880] (kms_flip:2320) DEBUG: Vblank took 55us
[163.528475] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.668259
last_received_ts = 163.667847
last_seq = 43
current_ts = 163.684937
current_received_ts = 163.684509
current_seq = 44
count = 24
seq_step = 1
[163.528545] (kms_flip:2320) DEBUG: Vblank took 56us
[163.545125] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.684937
last_received_ts = 163.684509
last_seq = 44
current_ts = 163.701599
current_received_ts = 163.701157
current_seq = 45
count = 25
seq_step = 1
[163.545194] (kms_flip:2320) DEBUG: Vblank took 54us
[163.561870] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.701599
last_received_ts = 163.701157
last_seq = 45
current_ts = 163.718262
current_received_ts = 163.717911
current_seq = 46
count = 26
seq_step = 1
[163.561975] (kms_flip:2320) DEBUG: Vblank took 55us
[163.578475] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.718262
last_received_ts = 163.717911
last_seq = 46
current_ts = 163.734940
current_received_ts = 163.734512
current_seq = 47
count = 27
seq_step = 1
[163.578545] (kms_flip:2320) DEBUG: Vblank took 55us
[163.595054] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.734940
last_received_ts = 163.734512
last_seq = 47
current_ts = 163.751602
current_received_ts = 163.751099
current_seq = 48
count = 28
seq_step = 1
[163.595123] (kms_flip:2320) DEBUG: Vblank took 55us
[163.611812] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.751602
last_received_ts = 163.751099
last_seq = 48
current_ts = 163.768280
current_received_ts = 163.767853
current_seq = 49
count = 29
seq_step = 1
[163.611881] (kms_flip:2320) DEBUG: Vblank took 55us
[163.628472] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.768280
last_received_ts = 163.767853
last_seq = 49
current_ts = 163.784943
current_received_ts = 163.784515
current_seq = 50
count = 30
seq_step = 1
[163.628541] (kms_flip:2320) DEBUG: Vblank took 55us
[163.645114] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.784943
last_received_ts = 163.784515
last_seq = 50
current_ts = 163.801605
current_received_ts = 163.801163
current_seq = 51
count = 31
seq_step = 1
[163.645184] (kms_flip:2320) DEBUG: Vblank took 55us
[163.661808] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.801605
last_received_ts = 163.801163
last_seq = 51
current_ts = 163.818283
current_received_ts = 163.817856
current_seq = 52
count = 32
seq_step = 1
[163.661878] (kms_flip:2320) DEBUG: Vblank took 56us
[163.678507] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.818283
last_received_ts = 163.817856
last_seq = 52
current_ts = 163.834946
current_received_ts = 163.834503
current_seq = 53
count = 33
seq_step = 1
[163.678575] (kms_flip:2320) DEBUG: Vblank took 54us
[163.695112] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.834946
last_received_ts = 163.834503
last_seq = 53
current_ts = 163.851608
current_received_ts = 163.851166
current_seq = 54
count = 34
seq_step = 1
[163.695180] (kms_flip:2320) DEBUG: Vblank took 55us
[163.711802] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.851608
last_received_ts = 163.851166
last_seq = 54
current_ts = 163.868286
current_received_ts = 163.867859
current_seq = 55
count = 35
seq_step = 1
[163.711871] (kms_flip:2320) DEBUG: Vblank took 55us
[163.728472] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.868286
last_received_ts = 163.867859
last_seq = 55
current_ts = 163.884949
current_received_ts = 163.884521
current_seq = 56
count = 36
seq_step = 1
[163.728541] (kms_flip:2320) DEBUG: Vblank took 55us
[163.745108] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.884949
last_received_ts = 163.884521
last_seq = 56
current_ts = 163.901611
current_received_ts = 163.901169
current_seq = 57
count = 37
seq_step = 1
[163.745177] (kms_flip:2320) DEBUG: Vblank took 54us
[163.761806] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.901611
last_received_ts = 163.901169
last_seq = 57
current_ts = 163.918289
current_received_ts = 163.917862
current_seq = 58
count = 38
seq_step = 1
[163.761875] (kms_flip:2320) DEBUG: Vblank took 55us
[163.778473] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.918289
last_received_ts = 163.917862
last_seq = 58
current_ts = 163.934952
current_received_ts = 163.934525
current_seq = 59
count = 39
seq_step = 1
[163.778543] (kms_flip:2320) DEBUG: Vblank took 54us
[163.795126] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.934952
last_received_ts = 163.934525
last_seq = 59
current_ts = 163.951614
current_received_ts = 163.951187
current_seq = 60
count = 40
seq_step = 1
[163.795240] (kms_flip:2320) DEBUG: Vblank took 54us
[163.811806] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.951614
last_received_ts = 163.951187
last_seq = 60
current_ts = 163.968292
current_received_ts = 163.967865
current_seq = 61
count = 41
seq_step = 1
[163.811876] (kms_flip:2320) DEBUG: Vblank took 56us
[163.828375] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.968292
last_received_ts = 163.967865
last_seq = 61
current_ts = 163.984955
current_received_ts = 163.984436
current_seq = 62
count = 42
seq_step = 1
[163.828443] (kms_flip:2320) DEBUG: Vblank took 54us
[163.845107] (kms_flip:2320) DEBUG: name = flip
last_ts = 163.984955
last_received_ts = 163.984436
last_seq = 62
current_ts = 164.001633
current_received_ts = 164.001175
current_seq = 63
count = 43
seq_step = 1
[163.845176] (kms_flip:2320) DEBUG: Vblank took 55us
[163.861802] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.001633
last_received_ts = 164.001175
last_seq = 63
current_ts = 164.018295
current_received_ts = 164.017868
current_seq = 64
count = 44
seq_step = 1
[163.861872] (kms_flip:2320) DEBUG: Vblank took 55us
[163.878472] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.018295
last_received_ts = 164.017868
last_seq = 64
current_ts = 164.034958
current_received_ts = 164.034531
current_seq = 65
count = 45
seq_step = 1
[163.878541] (kms_flip:2320) DEBUG: Vblank took 55us
[163.895118] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.034958
last_received_ts = 164.034531
last_seq = 65
current_ts = 164.051636
current_received_ts = 164.051178
current_seq = 66
count = 46
seq_step = 1
[163.895187] (kms_flip:2320) DEBUG: Vblank took 55us
[163.911806] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.051636
last_received_ts = 164.051178
last_seq = 66
current_ts = 164.068298
current_received_ts = 164.067871
current_seq = 67
count = 47
seq_step = 1
[163.911956] (kms_flip:2320) DEBUG: Vblank took 133us
[163.928471] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.068298
last_received_ts = 164.067871
last_seq = 67
current_ts = 164.084961
current_received_ts = 164.084549
current_seq = 68
count = 48
seq_step = 1
[163.928540] (kms_flip:2320) DEBUG: Vblank took 55us
[163.945076] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.084961
last_received_ts = 164.084549
last_seq = 68
current_ts = 164.101639
current_received_ts = 164.101151
current_seq = 69
count = 49
seq_step = 1
[163.945145] (kms_flip:2320) DEBUG: Vblank took 54us
[163.961804] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.101639
last_received_ts = 164.101151
last_seq = 69
current_ts = 164.118301
current_received_ts = 164.117874
current_seq = 70
count = 50
seq_step = 1
[163.961873] (kms_flip:2320) DEBUG: Vblank took 54us
[163.978472] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.118301
last_received_ts = 164.117874
last_seq = 70
current_ts = 164.134964
current_received_ts = 164.134552
current_seq = 71
count = 51
seq_step = 1
[163.978541] (kms_flip:2320) DEBUG: Vblank took 55us
[163.995155] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.134964
last_received_ts = 164.134552
last_seq = 71
current_ts = 164.151642
current_received_ts = 164.151230
current_seq = 72
count = 52
seq_step = 1
[163.995224] (kms_flip:2320) DEBUG: Vblank took 55us
[164.011804] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.151642
last_received_ts = 164.151230
last_seq = 72
current_ts = 164.168304
current_received_ts = 164.167877
current_seq = 73
count = 53
seq_step = 1
[164.011873] (kms_flip:2320) DEBUG: Vblank took 55us
[164.028501] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.168304
last_received_ts = 164.167877
last_seq = 73
current_ts = 164.184982
current_received_ts = 164.184586
current_seq = 74
count = 54
seq_step = 1
[164.028573] (kms_flip:2320) DEBUG: Vblank took 54us
[164.045116] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.184982
last_received_ts = 164.184586
last_seq = 74
current_ts = 164.201645
current_received_ts = 164.201202
current_seq = 75
count = 55
seq_step = 1
[164.045186] (kms_flip:2320) DEBUG: Vblank took 55us
[164.061800] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.201645
last_received_ts = 164.201202
last_seq = 75
current_ts = 164.218307
current_received_ts = 164.217880
current_seq = 76
count = 56
seq_step = 1
[164.061870] (kms_flip:2320) DEBUG: Vblank took 55us
[164.078473] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.218307
last_received_ts = 164.217880
last_seq = 76
current_ts = 164.234985
current_received_ts = 164.234558
current_seq = 77
count = 57
seq_step = 1
[164.078543] (kms_flip:2320) DEBUG: Vblank took 55us
[164.095167] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.234985
last_received_ts = 164.234558
last_seq = 77
current_ts = 164.251648
current_received_ts = 164.251251
current_seq = 78
count = 58
seq_step = 1
[164.095237] (kms_flip:2320) DEBUG: Vblank took 55us
[164.111802] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.251648
last_received_ts = 164.251251
last_seq = 78
current_ts = 164.268311
current_received_ts = 164.267883
current_seq = 79
count = 59
seq_step = 1
[164.111871] (kms_flip:2320) DEBUG: Vblank took 54us
[164.128471] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.268311
last_received_ts = 164.267883
last_seq = 79
current_ts = 164.284988
current_received_ts = 164.284561
current_seq = 80
count = 60
seq_step = 1
[164.128540] (kms_flip:2320) DEBUG: Vblank took 56us
[164.145224] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.284988
last_received_ts = 164.284561
last_seq = 80
current_ts = 164.301651
current_received_ts = 164.301315
current_seq = 81
count = 61
seq_step = 1
[164.145292] (kms_flip:2320) DEBUG: Vblank took 55us
[164.161803] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.301651
last_received_ts = 164.301315
last_seq = 81
current_ts = 164.318314
current_received_ts = 164.317902
current_seq = 82
count = 62
seq_step = 1
[164.161872] (kms_flip:2320) DEBUG: Vblank took 55us
[164.178360] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.318314
last_received_ts = 164.317902
last_seq = 82
current_ts = 164.334976
current_received_ts = 164.334457
current_seq = 83
count = 63
seq_step = 1
[164.178429] (kms_flip:2320) DEBUG: Vblank took 54us
[164.195169] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.334976
last_received_ts = 164.334457
last_seq = 83
current_ts = 164.351654
current_received_ts = 164.351257
current_seq = 84
count = 64
seq_step = 1
[164.195237] (kms_flip:2320) DEBUG: Vblank took 54us
[164.211801] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.351654
last_received_ts = 164.351257
last_seq = 84
current_ts = 164.368317
current_received_ts = 164.367889
current_seq = 85
count = 65
seq_step = 1
[164.211870] (kms_flip:2320) DEBUG: Vblank took 55us
[164.228474] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.368317
last_received_ts = 164.367889
last_seq = 85
current_ts = 164.384995
current_received_ts = 164.384567
current_seq = 86
count = 66
seq_step = 1
[164.228544] (kms_flip:2320) DEBUG: Vblank took 55us
[164.245161] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.384995
last_received_ts = 164.384567
last_seq = 86
current_ts = 164.401657
current_received_ts = 164.401260
current_seq = 87
count = 67
seq_step = 1
[164.245230] (kms_flip:2320) DEBUG: Vblank took 55us
[164.261854] (kms_flip:2320) DEBUG: name = flip
last_ts = 164.401657
last_received_ts = 164.401260
last_seq = 87
current_ts = 164.418320
current_received_ts = 164.417908
current_seq = 88
count = 68
seq_step = 1
[164.262940] (kms_flip:2320) DEBUG: Vblank took 1070us
[164.262950] (kms_flip:2320) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[164.263072] (kms_flip:2320) CRITICAL: Failed assertion: end - start < 500
[164.263162] (kms_flip:2320) CRITICAL: Last errno: 4, Interrupted system call
[164.274794] (kms_flip:2320) igt_core-INFO: Stack trace:
[164.289429] (kms_flip:2320) igt_core-INFO:   #0 ../lib/igt_core.c:2106 __igt_fail_assert()
[164.293327] (kms_flip:2320) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[164.293638] (kms_flip:2320) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[164.293786] (kms_flip:2320) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
[164.293986] (kms_flip:2320) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[164.319894] (kms_flip:2320) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[164.323558] (kms_flip:2320) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[164.324573] (kms_flip:2320) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A3: FAIL (1.377s)

Dmesg

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

<7> [163.066920] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:637]

<7> [163.067616] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:638]

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

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

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

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

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

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

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

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

<7> [163.127251] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:171:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [163.133494] i915 0000:03:00.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:171:pipe A] releasing DPLL 2

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

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

<7> [163.134056] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:165:cursor A] ddb (2012 - 2048) -> ( 0 - 0), size 36 -> 0

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

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

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

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

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

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

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

<7> [163.135347] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:145:plane 6A] fb: [NOFB], visible: no

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

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

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

<7> [163.141082] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_TC1

<7> [163.141271] i915 0000:03:00.0: [drm:intel_dpll_disable [i915]] disable DPLL 2 (active 0x1, on? 1) for [CRTC:171:pipe A]

<7> [163.141456] i915 0000:03:00.0: [drm:intel_dpll_disable [i915]] disabling DPLL 2

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

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

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

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

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

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

<7> [163.142589] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DDI TC1/PHY C]

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

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

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

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

<7> [163.143411] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:622:DDI TC2/PHY D]

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

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

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

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

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

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

<7> [163.144688] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_3

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

<7> [163.145109] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:171:pipe A]

<7> [163.145716] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe C]

<7> [163.145906] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe B]

<7> [163.146141] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:585:pipe D]

<7> [163.146330] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe C]

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

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

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

<7> [163.146751] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe C] hw max bpp: 24, pipe bpp: 24, dithering: 0

<7> [163.146902] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:610:DDI TC1/PHY C] [CRTC:309:pipe C]

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

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

<7> [163.147394] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [163.153081] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe C] fastset requirement not met, forcing full modeset

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

<7> [163.153407] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:309:pipe C] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4

<7> [163.153597] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:173:plane 1C] ddb ( 0 - 0) -> ( 0 - 2012), size 0 -> 2012

<7> [163.153743] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:303:cursor C] ddb ( 0 - 0) -> (2012 - 2048), size 0 -> 36

<7> [163.153890] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5,*wm6,*wm7,*twm, swm, stwm

<7> [163.154086] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 5, 5, 5, 8, 8, 9, 10, 0, 0, 0

<7> [163.154234] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 81, 81, 81, 129, 129, 145, 161, 30, 0, 0

<7> [163.154381] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:173:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 91, 91, 91, 143, 143, 161, 179, 31, 0, 0

<7> [163.154547] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:309:pipe C] data rate 594000 num active planes 1

<7> [163.154697] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 34000 required 594

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

<7> [163.155054] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:309:pipe C] min cdclk: 0 kHz -> 74250 kHz

<7> [163.155224] i915 0000:03:00.0: [drm:intel_find_dpll [i915]] [CRTC:309:pipe C] allocated DPLL 2

<7> [163.155376] i915 0000:03:00.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:309:pipe C] reserving DPLL 2

<7> [163.155529] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:309:pipe C] enable: yes [modeset]

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

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

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

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

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

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

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

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

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

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

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

<7> [163.157498] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

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

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

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

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

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

<7> [163.158450] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port clock: 148500, pixel rate 148500, min cdclk 74250, min voltage level 0

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

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

<7> [163.158901] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0

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

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

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

<7> [163.159545] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1001d0, cfgcr1: 0xe84, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0

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

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

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

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

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

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

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

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

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

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

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

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

<7> [163.161580] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:173:plane 1C] fb: [FB:637] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes

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

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

<7> [163.162075] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:203:plane 2C] fb: [NOFB], visible: no

<7> [163.162226] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:233:plane 3C] fb: [NOFB], visible: no

<7> [163.162375] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:263:plane 4C] fb: [NOFB], visible: no

<7> [163.162526] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:273:plane 5C] fb: [NOFB], visible: no

<7> [163.162675] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:283:plane 6C] fb: [NOFB], visible: no

<7> [163.162825] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:293:plane 7C] fb: [NOFB], visible: no

<7> [163.162998] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:303:cursor C] fb: [NOFB], visible: no

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

<7> [163.163578] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_3

<7> [163.163756] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_4

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

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

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

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

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

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

<7> [163.164904] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DDI TC1/PHY C]

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

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

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

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

<7> [163.165694] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:622:DDI TC2/PHY D]

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

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

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

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

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

<7> [163.166762] i915 0000:03:00.0: [drm:intel_dpll_enable [i915]] enable DPLL 2 (active 0x4, on? 0) for [CRTC:309:pipe C]

<7> [163.166916] i915 0000:03:00.0: [drm:intel_dpll_enable [i915]] enabling DPLL 2

<7> [163.167161] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_TC1

<7> [163.167396] i915 0000:03:00.0: [drm:intel_enable_transcoder [i915]] enabling pipe C

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

<7> [163.202476] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:309:pipe C]

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

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