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

Detail	Value
Duration	1.57 seconds
Hostname	shard-dg1-16
Igt-Version	IGT-Version: 2.4-gac3bbe847 (x86_64) (Linux: 7.1.0-rc3-CI_DRM_18468-g311a7de0a4e3+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A4 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2184 __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-A4: FAIL (1.568s)
Err	Starting dynamic subtest: B-HDMI-A4 (kms_flip:2065) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2065) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-HDMI-A4 failed. ** DEBUG (kms_flip:2065) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0) (kms_flip:2065) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2065) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2065) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680) (kms_flip:2065) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:2065) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0) (kms_flip:2065) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2065) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2065) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680) (kms_flip:2065) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) (kms_flip:2065) intel_allocator_reloc-DEBUG: Using reloc allocator (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) (kms_flip:2065) intel_allocator_reloc-DEBUG: Using reloc allocator (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) (kms_flip:2065) intel_allocator_reloc-DEBUG: Using reloc allocator (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd) (kms_flip:2065) intel_allocator_reloc-DEBUG: Using reloc allocator (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2065) igt_kms-INFO: 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 (kms_flip:2065) DEBUG: No stale events found (kms_flip:2065) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 (kms_flip:2065) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 (kms_flip:2065) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 98.524490 current_received_ts = 98.524033 current_seq = 5 count = 0 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 22us (kms_flip:2065) DEBUG: name = flip last_ts = 98.524490 last_received_ts = 98.524033 last_seq = 5 current_ts = 98.541168 current_received_ts = 98.540718 current_seq = 6 count = 1 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 24us (kms_flip:2065) DEBUG: name = flip last_ts = 98.541168 last_received_ts = 98.540718 last_seq = 6 current_ts = 98.557831 current_received_ts = 98.557350 current_seq = 7 count = 2 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 27us (kms_flip:2065) DEBUG: name = flip last_ts = 98.557831 last_received_ts = 98.557350 last_seq = 7 current_ts = 98.574501 current_received_ts = 98.574051 current_seq = 8 count = 3 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 34us (kms_flip:2065) DEBUG: name = flip last_ts = 98.574501 last_received_ts = 98.574051 last_seq = 8 current_ts = 98.591171 current_received_ts = 98.590752 current_seq = 9 count = 4 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.591171 last_received_ts = 98.590752 last_seq = 9 current_ts = 98.607841 current_received_ts = 98.607422 current_seq = 10 count = 5 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.607841 last_received_ts = 98.607422 last_seq = 10 current_ts = 98.624512 current_received_ts = 98.624123 current_seq = 11 count = 6 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.624512 last_received_ts = 98.624123 last_seq = 11 current_ts = 98.641182 current_received_ts = 98.640762 current_seq = 12 count = 7 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.641182 last_received_ts = 98.640762 last_seq = 12 current_ts = 98.657852 current_received_ts = 98.657433 current_seq = 13 count = 8 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.657852 last_received_ts = 98.657433 last_seq = 13 current_ts = 98.674515 current_received_ts = 98.674103 current_seq = 14 count = 9 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.674515 last_received_ts = 98.674103 last_seq = 14 current_ts = 98.691185 current_received_ts = 98.690773 current_seq = 15 count = 10 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.691185 last_received_ts = 98.690773 last_seq = 15 current_ts = 98.707855 current_received_ts = 98.707443 current_seq = 16 count = 11 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.707855 last_received_ts = 98.707443 last_seq = 16 current_ts = 98.724525 current_received_ts = 98.724113 current_seq = 17 count = 12 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.724525 last_received_ts = 98.724113 last_seq = 17 current_ts = 98.741196 current_received_ts = 98.740784 current_seq = 18 count = 13 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.741196 last_received_ts = 98.740784 last_seq = 18 current_ts = 98.757866 current_received_ts = 98.757454 current_seq = 19 count = 14 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.757866 last_received_ts = 98.757454 last_seq = 19 current_ts = 98.774536 current_received_ts = 98.774117 current_seq = 20 count = 15 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.774536 last_received_ts = 98.774117 last_seq = 20 current_ts = 98.791206 current_received_ts = 98.790787 current_seq = 21 count = 16 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.791206 last_received_ts = 98.790787 last_seq = 21 current_ts = 98.807877 current_received_ts = 98.807457 current_seq = 22 count = 17 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.807877 last_received_ts = 98.807457 last_seq = 22 current_ts = 98.824539 current_received_ts = 98.824127 current_seq = 23 count = 18 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.824539 last_received_ts = 98.824127 last_seq = 23 current_ts = 98.841209 current_received_ts = 98.840797 current_seq = 24 count = 19 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.841209 last_received_ts = 98.840797 last_seq = 24 current_ts = 98.857880 current_received_ts = 98.857483 current_seq = 25 count = 20 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.857880 last_received_ts = 98.857483 last_seq = 25 current_ts = 98.874550 current_received_ts = 98.874138 current_seq = 26 count = 21 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.874550 last_received_ts = 98.874138 last_seq = 26 current_ts = 98.891220 current_received_ts = 98.890808 current_seq = 27 count = 22 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.891220 last_received_ts = 98.890808 last_seq = 27 current_ts = 98.907890 current_received_ts = 98.907471 current_seq = 28 count = 23 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.907890 last_received_ts = 98.907471 last_seq = 28 current_ts = 98.924561 current_received_ts = 98.924141 current_seq = 29 count = 24 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.924561 last_received_ts = 98.924141 last_seq = 29 current_ts = 98.941231 current_received_ts = 98.940811 current_seq = 30 count = 25 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 98.941231 last_received_ts = 98.940811 last_seq = 30 current_ts = 98.957901 current_received_ts = 98.957481 current_seq = 31 count = 26 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.957901 last_received_ts = 98.957481 last_seq = 31 current_ts = 98.974571 current_received_ts = 98.974152 current_seq = 32 count = 27 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.974571 last_received_ts = 98.974152 last_seq = 32 current_ts = 98.991234 current_received_ts = 98.990822 current_seq = 33 count = 28 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 98.991234 last_received_ts = 98.990822 last_seq = 33 current_ts = 99.007904 current_received_ts = 99.007492 current_seq = 34 count = 29 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.007904 last_received_ts = 99.007492 last_seq = 34 current_ts = 99.024574 current_received_ts = 99.024162 current_seq = 35 count = 30 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.024574 last_received_ts = 99.024162 last_seq = 35 current_ts = 99.041245 current_received_ts = 99.040825 current_seq = 36 count = 31 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.041245 last_received_ts = 99.040825 last_seq = 36 current_ts = 99.057915 current_received_ts = 99.057495 current_seq = 37 count = 32 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.057915 last_received_ts = 99.057495 last_seq = 37 current_ts = 99.074585 current_received_ts = 99.074165 current_seq = 38 count = 33 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.074585 last_received_ts = 99.074165 last_seq = 38 current_ts = 99.091255 current_received_ts = 99.090843 current_seq = 39 count = 34 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.091255 last_received_ts = 99.090843 last_seq = 39 current_ts = 99.107925 current_received_ts = 99.107506 current_seq = 40 count = 35 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.107925 last_received_ts = 99.107506 last_seq = 40 current_ts = 99.124596 current_received_ts = 99.124176 current_seq = 41 count = 36 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.124596 last_received_ts = 99.124176 last_seq = 41 current_ts = 99.141266 current_received_ts = 99.140846 current_seq = 42 count = 37 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.141266 last_received_ts = 99.140846 last_seq = 42 current_ts = 99.157928 current_received_ts = 99.157516 current_seq = 43 count = 38 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.157928 last_received_ts = 99.157516 last_seq = 43 current_ts = 99.174599 current_received_ts = 99.174187 current_seq = 44 count = 39 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.174599 last_received_ts = 99.174187 last_seq = 44 current_ts = 99.191269 current_received_ts = 99.190849 current_seq = 45 count = 40 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.191269 last_received_ts = 99.190849 last_seq = 45 current_ts = 99.207939 current_received_ts = 99.207520 current_seq = 46 count = 41 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.207939 last_received_ts = 99.207520 last_seq = 46 current_ts = 99.224609 current_received_ts = 99.224190 current_seq = 47 count = 42 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.224609 last_received_ts = 99.224190 last_seq = 47 current_ts = 99.241280 current_received_ts = 99.240860 current_seq = 48 count = 43 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.241280 last_received_ts = 99.240860 last_seq = 48 current_ts = 99.257950 current_received_ts = 99.257530 current_seq = 49 count = 44 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.257950 last_received_ts = 99.257530 last_seq = 49 current_ts = 99.274620 current_received_ts = 99.274200 current_seq = 50 count = 45 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.274620 last_received_ts = 99.274200 last_seq = 50 current_ts = 99.291290 current_received_ts = 99.290871 current_seq = 51 count = 46 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.291290 last_received_ts = 99.290871 last_seq = 51 current_ts = 99.307953 current_received_ts = 99.307541 current_seq = 52 count = 47 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.307953 last_received_ts = 99.307541 last_seq = 52 current_ts = 99.324623 current_received_ts = 99.324211 current_seq = 53 count = 48 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.324623 last_received_ts = 99.324211 last_seq = 53 current_ts = 99.341293 current_received_ts = 99.340874 current_seq = 54 count = 49 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.341293 last_received_ts = 99.340874 last_seq = 54 current_ts = 99.357964 current_received_ts = 99.357544 current_seq = 55 count = 50 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.357964 last_received_ts = 99.357544 last_seq = 55 current_ts = 99.374634 current_received_ts = 99.374214 current_seq = 56 count = 51 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.374634 last_received_ts = 99.374214 last_seq = 56 current_ts = 99.391304 current_received_ts = 99.390884 current_seq = 57 count = 52 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 53us (kms_flip:2065) DEBUG: name = flip last_ts = 99.391304 last_received_ts = 99.390884 last_seq = 57 current_ts = 99.407967 current_received_ts = 99.407524 current_seq = 58 count = 53 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.407967 last_received_ts = 99.407524 last_seq = 58 current_ts = 99.424637 current_received_ts = 99.424225 current_seq = 59 count = 54 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.424637 last_received_ts = 99.424225 last_seq = 59 current_ts = 99.441307 current_received_ts = 99.440895 current_seq = 60 count = 55 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.441307 last_received_ts = 99.440895 last_seq = 60 current_ts = 99.457977 current_received_ts = 99.457558 current_seq = 61 count = 56 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.457977 last_received_ts = 99.457558 last_seq = 61 current_ts = 99.474648 current_received_ts = 99.474258 current_seq = 62 count = 57 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.474648 last_received_ts = 99.474258 last_seq = 62 current_ts = 99.491318 current_received_ts = 99.490906 current_seq = 63 count = 58 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.491318 last_received_ts = 99.490906 last_seq = 63 current_ts = 99.507988 current_received_ts = 99.507568 current_seq = 64 count = 59 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.507988 last_received_ts = 99.507568 last_seq = 64 current_ts = 99.524658 current_received_ts = 99.524269 current_seq = 65 count = 60 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.524658 last_received_ts = 99.524269 last_seq = 65 current_ts = 99.541328 current_received_ts = 99.540909 current_seq = 66 count = 61 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.541328 last_received_ts = 99.540909 last_seq = 66 current_ts = 99.557999 current_received_ts = 99.557579 current_seq = 67 count = 62 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.557999 last_received_ts = 99.557579 last_seq = 67 current_ts = 99.574669 current_received_ts = 99.574280 current_seq = 68 count = 63 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.574669 last_received_ts = 99.574280 last_seq = 68 current_ts = 99.591331 current_received_ts = 99.590919 current_seq = 69 count = 64 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 96us (kms_flip:2065) DEBUG: name = flip last_ts = 99.591331 last_received_ts = 99.590919 last_seq = 69 current_ts = 99.608002 current_received_ts = 99.607590 current_seq = 70 count = 65 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.608002 last_received_ts = 99.607590 last_seq = 70 current_ts = 99.624672 current_received_ts = 99.624290 current_seq = 71 count = 66 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.624672 last_received_ts = 99.624290 last_seq = 71 current_ts = 99.641342 current_received_ts = 99.640923 current_seq = 72 count = 67 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 97us (kms_flip:2065) DEBUG: name = flip last_ts = 99.641342 last_received_ts = 99.640923 last_seq = 72 current_ts = 99.658012 current_received_ts = 99.657593 current_seq = 73 count = 68 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.658012 last_received_ts = 99.657593 last_seq = 73 current_ts = 99.674683 current_received_ts = 99.674294 current_seq = 74 count = 69 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.674683 last_received_ts = 99.674294 last_seq = 74 current_ts = 99.691353 current_received_ts = 99.690926 current_seq = 75 count = 70 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 93us (kms_flip:2065) DEBUG: name = flip last_ts = 99.691353 last_received_ts = 99.690926 last_seq = 75 current_ts = 99.708015 current_received_ts = 99.707603 current_seq = 76 count = 71 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.708015 last_received_ts = 99.707603 last_seq = 76 current_ts = 99.724678 current_received_ts = 99.724289 current_seq = 77 count = 72 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.724678 last_received_ts = 99.724289 last_seq = 77 current_ts = 99.741356 current_received_ts = 99.740944 current_seq = 78 count = 73 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 95us (kms_flip:2065) DEBUG: name = flip last_ts = 99.741356 last_received_ts = 99.740944 last_seq = 78 current_ts = 99.758026 current_received_ts = 99.757614 current_seq = 79 count = 74 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.758026 last_received_ts = 99.757614 last_seq = 79 current_ts = 99.774696 current_received_ts = 99.774300 current_seq = 80 count = 75 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.774696 last_received_ts = 99.774300 last_seq = 80 current_ts = 99.791367 current_received_ts = 99.790947 current_seq = 81 count = 76 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 95us (kms_flip:2065) DEBUG: name = flip last_ts = 99.791367 last_received_ts = 99.790947 last_seq = 81 current_ts = 99.808037 current_received_ts = 99.807617 current_seq = 82 count = 77 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 54us (kms_flip:2065) DEBUG: name = flip last_ts = 99.808037 last_received_ts = 99.807617 last_seq = 82 current_ts = 99.824707 current_received_ts = 99.824287 current_seq = 83 count = 78 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 55us (kms_flip:2065) DEBUG: name = flip last_ts = 99.824707 last_received_ts = 99.824287 last_seq = 83 current_ts = 99.841370 current_received_ts = 99.840958 current_seq = 84 count = 79 seq_step = 1 (kms_flip:2065) DEBUG: Vblank took 1489us (kms_flip:2065) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2065) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2065) igt_core-INFO: Stack trace: (kms_flip:2065) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2065) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:2065) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:2065) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() (kms_flip:2065) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:2065) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2065) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2065) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A4: FAIL (1.568s)
Dmesg	<6> [98.735127] [IGT] kms_flip: starting dynamic subtest B-HDMI-A4 <7> [98.737030] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:635] <7> [98.737897] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:638] <7> [98.739111] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [98.741216] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [98.762467] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [98.762858] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [98.770069] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [98.770393] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [98.790029] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [98.790369] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [98.817950] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:171:pipe A] <7> [98.818064] 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> [98.818238] 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> [98.818389] 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> [98.818540] 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> [98.818702] 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> [98.818853] 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> [98.819002] 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> [98.819151] 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> [98.819301] 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> [98.819451] 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> [98.819649] 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> [98.819798] 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> [98.819947] 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> [98.820096] 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> [98.820246] 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> [98.820396] 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> [98.820545] 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> [98.820739] 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> [98.820889] 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> [98.821039] 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> [98.821189] 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> [98.821338] 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> [98.821487] 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> [98.821680] 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> [98.821829] 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> [98.821979] 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> [98.822128] 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> [98.822276] 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> [98.822425] 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> [98.822605] 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> [98.822768] 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> [98.822918] 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> [98.823068] 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> [98.823218] 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> [98.823367] 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> [98.823517] 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> [98.823712] 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> [98.823862] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:171:pipe A] fastset requirement not met, forcing full modeset <7> [98.824012] i915 0000:03:00.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:171:pipe A] releasing DPLL 2 <7> [98.824190] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no <7> [98.824337] 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> [98.824525] 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> [98.824737] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:171:pipe A] min cdclk: 74250 kHz -> 0 kHz <7> [98.824889] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:171:pipe A] enable: no [modeset] <7> [98.825038] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [98.825187] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [98.825335] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [98.825483] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [98.825668] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [98.825817] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:145:plane 6A] fb: [NOFB], visible: no <7> [98.825965] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:155:plane 7A] fb: [NOFB], visible: no <7> [98.826113] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:165:cursor A] fb: [NOFB], visible: no <7> [98.826412] i915 0000:03:00.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [98.829497] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_TC2 <7> [98.829732] i915 0000:03:00.0: [drm:intel_dpll_disable [i915]] disable DPLL 2 (active 0x1, on? 1) for [CRTC:171:pipe A] <7> [98.829915] i915 0000:03:00.0: [drm:intel_dpll_disable [i915]] disabling DPLL 2 <7> [98.830090] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI A/PHY A] <7> [98.830239] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:589:DP-MST A] <7> [98.830387] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:590:DP-MST B] <7> [98.830534] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:591:DP-MST C] <7> [98.830732] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:592:DP-MST D] <7> [98.830880] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:606:DDI B/PHY B] <7> [98.831027] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DDI TC1/PHY C] <7> [98.831174] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST A] <7> [98.831322] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:613:DP-MST B] <7> [98.831470] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:614:DP-MST C] <7> [98.831662] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:615:DP-MST D] <7> [98.831811] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:622:DDI TC2/PHY D] <7> [98.831980] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:624:DP-MST A] <7> [98.832129] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DP-MST B] <7> [98.832277] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:626:DP-MST C] <7> [98.832425] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST D] <7> [98.832623] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:631:HDMI-A-4] <7> [98.832891] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [98.833103] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_3 <7> [98.833291] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [98.833476] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:171:pipe A] <7> [98.834366] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe C] <7> [98.834567] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe B] <7> [98.834827] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:585:pipe D] <7> [98.835015] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe C] <7> [98.835052] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:631:HDMI-A-4] <7> [98.835132] i915 0000:03:00.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:631:HDMI-A-4] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 36, max platform bpp 36) <7> [98.835296] i915 0000:03:00.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [98.835439] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe C] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [98.835635] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:622:DDI TC2/PHY D] [CRTC:309:pipe C] <7> [98.835779] 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> [98.835930] 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> [98.836079] 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> [98.836228] 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> [98.836378] 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> [98.836528] 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> [98.836719] 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> [98.836868] 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> [98.837016] 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> [98.837170] 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> [98.837319] 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> [98.837468] 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> [98.837672] 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> [98.837822] 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> [98.837972] 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> [98.838121] 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> [98.838270] 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> [98.838419] 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> [98.838601] 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> [98.838801] 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> [98.838950] 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> [98.839100] 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> [98.839249] 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> [98.839399] 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> [98.839548] 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> [98.839740] 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> [98.839889] 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> [98.840039] 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> [98.840188] 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> [98.840338] 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> [98.840487] 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> [98.840680] 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> [98.840830] 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> [98.840981] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in dpll_hw_state <7> [98.841130] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [98.841279] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: cfgcr0: 0x0, cfgcr1: 0x0, 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> [98.841429] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] found: <7> [98.841667] i915 0000:03:00.0: [drm:intel_pipe_config_compare [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> [98.841818] 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> [98.841968] 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> [98.842117] 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> [98.842267] 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> [98.842417] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe C] fastset requirement not met, forcing full modeset <7> [98.842633] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no <7> [98.842781] 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> [98.842968] 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> [98.843114] 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> [98.843260] 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> [98.843406] 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> [98.843552] 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> [98.843743] 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> [98.843908] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:309:pipe C] data rate 594000 num active planes 1 <7> [98.844057] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 34000 required 594 <7> [98.844204] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [98.844368] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:309:pipe C] min cdclk: 0 kHz -> 74250 kHz <7> [98.844537] i915 0000:03:00.0: [drm:intel_find_dpll [i915]] [CRTC:309:pipe C] allocated DPLL 2 <7> [98.844748] i915 0000:03:00.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:309:pipe C] reserving DPLL 2 <7> [98.844900] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:309:pipe C] enable: yes [modeset] <7> [98.845050] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [98.845199] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: C, pipe bpp: 24, dithering: 0 <7> [98.845347] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [98.845496] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [98.845689] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [98.845837] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [98.845986] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0 <7> [98.846135] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [98.846282] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [98.846430] 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> [98.846616] 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> [98.846765] 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> [98.846914] 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> [98.847064] 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> [98.847214] 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> [98.847364] 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> [98.847514] 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> [98.847703] 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> [98.847852] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] linetime: 119, ips linetime: 0 <7> [98.848000] 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> [98.848149] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [98.848298] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [98.848446] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [98.848637] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [98.848786] 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> [98.848936] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [98.849085] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [98.849233] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [98.849381] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [98.849529] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [98.849716] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [98.849865] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [98.850014] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [98.850162] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [98.850311] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [98.850459] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [98.850648] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [98.850796] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:173:plane 1C] fb: [FB:635] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [98.850946] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [98.851095] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [98.851244] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:203:plane 2C] fb: [NOFB], visible: no <7> [98.851393] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:233:plane 3C] fb: [NOFB], visible: no <7> [98.851542] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:263:plane 4C] fb: [NOFB], visible: no <7> [98.851741] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:273:plane 5C] fb: [NOFB], visible: no <7> [98.851889] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:283:plane 6C] fb: [NOFB], visible: no <7> [98.852037] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:293:plane 7C] fb: [NOFB], visible: no <7> [98.852184] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:303:cursor C] fb: [NOFB], visible: no <7> [98.852618] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [98.852787] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_3 <7> [98.852963] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_4 <7> [98.853156] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI A/PHY A] <7> [98.853305] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:589:DP-MST A] <7> [98.853453] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:590:DP-MST B] <7> [98.853652] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:591:DP-MST C] <7> [98.853801] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:592:DP-MST D] <7> [98.853949] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:606:DDI B/PHY B] <7> [98.854097] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DDI TC1/PHY C] <7> [98.854245] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST A] <7> [98.854393] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:613:DP-MST B] <7> [98.854541] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:614:DP-MST C] <7> [98.854728] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:615:DP-MST D] <7> [98.854877] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:622:DDI TC2/PHY D] <7> [98.855025] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:624:DP-MST A] <7> [98.855172] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DP-MST B] <7> [98.855320] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:626:DP-MST C] <7> [98.855467] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST D] <7> [98.855736] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [98.855933] i915 0000:03:00.0: [drm:intel_dpll_enable [i915]] enable DPLL 2 (active 0x4, on? 0) for [CRTC:309:pipe C] <7> [98.856084] i915 0000:03:00.0: [drm:intel_dpll_enable [i915]] enabling DPLL 2 <7> [98.856290] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_TC2 <7> [98.856521] i915 0000:03:00.0: [drm:intel_enable_transcoder [i915]] enabling pipe C <7> [98.891361] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:631:HDMI-A-4] <7> [98.891650] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:309:pipe C] <6> [100.302882] [IGT] kms_flip: finished subtest B-HDMI-A4, FAIL

Detail

Value

Duration

1.57 seconds

Hostname

shard-dg1-16

Igt-Version

IGT-Version: 2.4-gac3bbe847 (x86_64) (Linux: 7.1.0-rc3-CI_DRM_18468-g311a7de0a4e3+ x86_64)

Out

Starting dynamic subtest: B-HDMI-A4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2184 __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-A4: FAIL (1.568s)

Err

Starting dynamic subtest: B-HDMI-A4
(kms_flip:2065) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2065) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-HDMI-A4 failed.
**** DEBUG ****
(kms_flip:2065) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
(kms_flip:2065) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2065) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2065) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:2065) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2065) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
(kms_flip:2065) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2065) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2065) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:2065) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2065) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2065) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2065) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2065) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2065) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2065) DEBUG: No stale events found
(kms_flip:2065) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2065) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2065) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 98.524490
current_received_ts = 98.524033
current_seq = 5
count = 0
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 22us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.524490
last_received_ts = 98.524033
last_seq = 5
current_ts = 98.541168
current_received_ts = 98.540718
current_seq = 6
count = 1
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 24us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.541168
last_received_ts = 98.540718
last_seq = 6
current_ts = 98.557831
current_received_ts = 98.557350
current_seq = 7
count = 2
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 27us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.557831
last_received_ts = 98.557350
last_seq = 7
current_ts = 98.574501
current_received_ts = 98.574051
current_seq = 8
count = 3
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 34us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.574501
last_received_ts = 98.574051
last_seq = 8
current_ts = 98.591171
current_received_ts = 98.590752
current_seq = 9
count = 4
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.591171
last_received_ts = 98.590752
last_seq = 9
current_ts = 98.607841
current_received_ts = 98.607422
current_seq = 10
count = 5
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.607841
last_received_ts = 98.607422
last_seq = 10
current_ts = 98.624512
current_received_ts = 98.624123
current_seq = 11
count = 6
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.624512
last_received_ts = 98.624123
last_seq = 11
current_ts = 98.641182
current_received_ts = 98.640762
current_seq = 12
count = 7
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.641182
last_received_ts = 98.640762
last_seq = 12
current_ts = 98.657852
current_received_ts = 98.657433
current_seq = 13
count = 8
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.657852
last_received_ts = 98.657433
last_seq = 13
current_ts = 98.674515
current_received_ts = 98.674103
current_seq = 14
count = 9
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.674515
last_received_ts = 98.674103
last_seq = 14
current_ts = 98.691185
current_received_ts = 98.690773
current_seq = 15
count = 10
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.691185
last_received_ts = 98.690773
last_seq = 15
current_ts = 98.707855
current_received_ts = 98.707443
current_seq = 16
count = 11
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.707855
last_received_ts = 98.707443
last_seq = 16
current_ts = 98.724525
current_received_ts = 98.724113
current_seq = 17
count = 12
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.724525
last_received_ts = 98.724113
last_seq = 17
current_ts = 98.741196
current_received_ts = 98.740784
current_seq = 18
count = 13
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.741196
last_received_ts = 98.740784
last_seq = 18
current_ts = 98.757866
current_received_ts = 98.757454
current_seq = 19
count = 14
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.757866
last_received_ts = 98.757454
last_seq = 19
current_ts = 98.774536
current_received_ts = 98.774117
current_seq = 20
count = 15
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.774536
last_received_ts = 98.774117
last_seq = 20
current_ts = 98.791206
current_received_ts = 98.790787
current_seq = 21
count = 16
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.791206
last_received_ts = 98.790787
last_seq = 21
current_ts = 98.807877
current_received_ts = 98.807457
current_seq = 22
count = 17
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.807877
last_received_ts = 98.807457
last_seq = 22
current_ts = 98.824539
current_received_ts = 98.824127
current_seq = 23
count = 18
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.824539
last_received_ts = 98.824127
last_seq = 23
current_ts = 98.841209
current_received_ts = 98.840797
current_seq = 24
count = 19
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.841209
last_received_ts = 98.840797
last_seq = 24
current_ts = 98.857880
current_received_ts = 98.857483
current_seq = 25
count = 20
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.857880
last_received_ts = 98.857483
last_seq = 25
current_ts = 98.874550
current_received_ts = 98.874138
current_seq = 26
count = 21
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.874550
last_received_ts = 98.874138
last_seq = 26
current_ts = 98.891220
current_received_ts = 98.890808
current_seq = 27
count = 22
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.891220
last_received_ts = 98.890808
last_seq = 27
current_ts = 98.907890
current_received_ts = 98.907471
current_seq = 28
count = 23
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.907890
last_received_ts = 98.907471
last_seq = 28
current_ts = 98.924561
current_received_ts = 98.924141
current_seq = 29
count = 24
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.924561
last_received_ts = 98.924141
last_seq = 29
current_ts = 98.941231
current_received_ts = 98.940811
current_seq = 30
count = 25
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.941231
last_received_ts = 98.940811
last_seq = 30
current_ts = 98.957901
current_received_ts = 98.957481
current_seq = 31
count = 26
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.957901
last_received_ts = 98.957481
last_seq = 31
current_ts = 98.974571
current_received_ts = 98.974152
current_seq = 32
count = 27
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.974571
last_received_ts = 98.974152
last_seq = 32
current_ts = 98.991234
current_received_ts = 98.990822
current_seq = 33
count = 28
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 98.991234
last_received_ts = 98.990822
last_seq = 33
current_ts = 99.007904
current_received_ts = 99.007492
current_seq = 34
count = 29
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.007904
last_received_ts = 99.007492
last_seq = 34
current_ts = 99.024574
current_received_ts = 99.024162
current_seq = 35
count = 30
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.024574
last_received_ts = 99.024162
last_seq = 35
current_ts = 99.041245
current_received_ts = 99.040825
current_seq = 36
count = 31
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.041245
last_received_ts = 99.040825
last_seq = 36
current_ts = 99.057915
current_received_ts = 99.057495
current_seq = 37
count = 32
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.057915
last_received_ts = 99.057495
last_seq = 37
current_ts = 99.074585
current_received_ts = 99.074165
current_seq = 38
count = 33
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.074585
last_received_ts = 99.074165
last_seq = 38
current_ts = 99.091255
current_received_ts = 99.090843
current_seq = 39
count = 34
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.091255
last_received_ts = 99.090843
last_seq = 39
current_ts = 99.107925
current_received_ts = 99.107506
current_seq = 40
count = 35
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.107925
last_received_ts = 99.107506
last_seq = 40
current_ts = 99.124596
current_received_ts = 99.124176
current_seq = 41
count = 36
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.124596
last_received_ts = 99.124176
last_seq = 41
current_ts = 99.141266
current_received_ts = 99.140846
current_seq = 42
count = 37
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.141266
last_received_ts = 99.140846
last_seq = 42
current_ts = 99.157928
current_received_ts = 99.157516
current_seq = 43
count = 38
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.157928
last_received_ts = 99.157516
last_seq = 43
current_ts = 99.174599
current_received_ts = 99.174187
current_seq = 44
count = 39
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.174599
last_received_ts = 99.174187
last_seq = 44
current_ts = 99.191269
current_received_ts = 99.190849
current_seq = 45
count = 40
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.191269
last_received_ts = 99.190849
last_seq = 45
current_ts = 99.207939
current_received_ts = 99.207520
current_seq = 46
count = 41
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.207939
last_received_ts = 99.207520
last_seq = 46
current_ts = 99.224609
current_received_ts = 99.224190
current_seq = 47
count = 42
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.224609
last_received_ts = 99.224190
last_seq = 47
current_ts = 99.241280
current_received_ts = 99.240860
current_seq = 48
count = 43
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.241280
last_received_ts = 99.240860
last_seq = 48
current_ts = 99.257950
current_received_ts = 99.257530
current_seq = 49
count = 44
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.257950
last_received_ts = 99.257530
last_seq = 49
current_ts = 99.274620
current_received_ts = 99.274200
current_seq = 50
count = 45
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.274620
last_received_ts = 99.274200
last_seq = 50
current_ts = 99.291290
current_received_ts = 99.290871
current_seq = 51
count = 46
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.291290
last_received_ts = 99.290871
last_seq = 51
current_ts = 99.307953
current_received_ts = 99.307541
current_seq = 52
count = 47
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.307953
last_received_ts = 99.307541
last_seq = 52
current_ts = 99.324623
current_received_ts = 99.324211
current_seq = 53
count = 48
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.324623
last_received_ts = 99.324211
last_seq = 53
current_ts = 99.341293
current_received_ts = 99.340874
current_seq = 54
count = 49
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.341293
last_received_ts = 99.340874
last_seq = 54
current_ts = 99.357964
current_received_ts = 99.357544
current_seq = 55
count = 50
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.357964
last_received_ts = 99.357544
last_seq = 55
current_ts = 99.374634
current_received_ts = 99.374214
current_seq = 56
count = 51
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.374634
last_received_ts = 99.374214
last_seq = 56
current_ts = 99.391304
current_received_ts = 99.390884
current_seq = 57
count = 52
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 53us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.391304
last_received_ts = 99.390884
last_seq = 57
current_ts = 99.407967
current_received_ts = 99.407524
current_seq = 58
count = 53
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.407967
last_received_ts = 99.407524
last_seq = 58
current_ts = 99.424637
current_received_ts = 99.424225
current_seq = 59
count = 54
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.424637
last_received_ts = 99.424225
last_seq = 59
current_ts = 99.441307
current_received_ts = 99.440895
current_seq = 60
count = 55
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.441307
last_received_ts = 99.440895
last_seq = 60
current_ts = 99.457977
current_received_ts = 99.457558
current_seq = 61
count = 56
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.457977
last_received_ts = 99.457558
last_seq = 61
current_ts = 99.474648
current_received_ts = 99.474258
current_seq = 62
count = 57
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.474648
last_received_ts = 99.474258
last_seq = 62
current_ts = 99.491318
current_received_ts = 99.490906
current_seq = 63
count = 58
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.491318
last_received_ts = 99.490906
last_seq = 63
current_ts = 99.507988
current_received_ts = 99.507568
current_seq = 64
count = 59
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.507988
last_received_ts = 99.507568
last_seq = 64
current_ts = 99.524658
current_received_ts = 99.524269
current_seq = 65
count = 60
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.524658
last_received_ts = 99.524269
last_seq = 65
current_ts = 99.541328
current_received_ts = 99.540909
current_seq = 66
count = 61
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.541328
last_received_ts = 99.540909
last_seq = 66
current_ts = 99.557999
current_received_ts = 99.557579
current_seq = 67
count = 62
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.557999
last_received_ts = 99.557579
last_seq = 67
current_ts = 99.574669
current_received_ts = 99.574280
current_seq = 68
count = 63
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.574669
last_received_ts = 99.574280
last_seq = 68
current_ts = 99.591331
current_received_ts = 99.590919
current_seq = 69
count = 64
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 96us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.591331
last_received_ts = 99.590919
last_seq = 69
current_ts = 99.608002
current_received_ts = 99.607590
current_seq = 70
count = 65
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.608002
last_received_ts = 99.607590
last_seq = 70
current_ts = 99.624672
current_received_ts = 99.624290
current_seq = 71
count = 66
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.624672
last_received_ts = 99.624290
last_seq = 71
current_ts = 99.641342
current_received_ts = 99.640923
current_seq = 72
count = 67
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 97us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.641342
last_received_ts = 99.640923
last_seq = 72
current_ts = 99.658012
current_received_ts = 99.657593
current_seq = 73
count = 68
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.658012
last_received_ts = 99.657593
last_seq = 73
current_ts = 99.674683
current_received_ts = 99.674294
current_seq = 74
count = 69
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.674683
last_received_ts = 99.674294
last_seq = 74
current_ts = 99.691353
current_received_ts = 99.690926
current_seq = 75
count = 70
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 93us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.691353
last_received_ts = 99.690926
last_seq = 75
current_ts = 99.708015
current_received_ts = 99.707603
current_seq = 76
count = 71
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.708015
last_received_ts = 99.707603
last_seq = 76
current_ts = 99.724678
current_received_ts = 99.724289
current_seq = 77
count = 72
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.724678
last_received_ts = 99.724289
last_seq = 77
current_ts = 99.741356
current_received_ts = 99.740944
current_seq = 78
count = 73
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 95us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.741356
last_received_ts = 99.740944
last_seq = 78
current_ts = 99.758026
current_received_ts = 99.757614
current_seq = 79
count = 74
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.758026
last_received_ts = 99.757614
last_seq = 79
current_ts = 99.774696
current_received_ts = 99.774300
current_seq = 80
count = 75
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.774696
last_received_ts = 99.774300
last_seq = 80
current_ts = 99.791367
current_received_ts = 99.790947
current_seq = 81
count = 76
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 95us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.791367
last_received_ts = 99.790947
last_seq = 81
current_ts = 99.808037
current_received_ts = 99.807617
current_seq = 82
count = 77
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 54us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.808037
last_received_ts = 99.807617
last_seq = 82
current_ts = 99.824707
current_received_ts = 99.824287
current_seq = 83
count = 78
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 55us
(kms_flip:2065) DEBUG: name = flip
last_ts = 99.824707
last_received_ts = 99.824287
last_seq = 83
current_ts = 99.841370
current_received_ts = 99.840958
current_seq = 84
count = 79
seq_step = 1
(kms_flip:2065) DEBUG: Vblank took 1489us
(kms_flip:2065) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2065) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2065) igt_core-INFO: Stack trace:
(kms_flip:2065) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2065) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:2065) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:2065) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
(kms_flip:2065) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:2065) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2065) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2065) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A4: FAIL (1.568s)

Dmesg

<6> [98.735127] [IGT] kms_flip: starting dynamic subtest B-HDMI-A4

<7> [98.737030] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:635]

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

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

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

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

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

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

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

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

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

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

<7> [98.818064] 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> [98.818238] 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> [98.818389] 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> [98.818540] 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> [98.818702] 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> [98.818853] 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> [98.819002] 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> [98.819151] 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> [98.819301] 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> [98.819451] 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> [98.819649] 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> [98.819798] 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> [98.819947] 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> [98.820096] 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> [98.820246] 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> [98.820396] 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> [98.820545] 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> [98.820739] 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> [98.820889] 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> [98.821039] 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> [98.821189] 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> [98.821338] 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> [98.821487] 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> [98.821680] 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> [98.821829] 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> [98.821979] 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> [98.822128] 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> [98.822276] 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> [98.822425] 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> [98.822605] 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> [98.822768] 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> [98.822918] 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> [98.823068] 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> [98.823218] 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> [98.823367] 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> [98.823517] 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> [98.823712] 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> [98.823862] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:171:pipe A] fastset requirement not met, forcing full modeset

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

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

<7> [98.824337] 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> [98.824525] 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> [98.824737] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:171:pipe A] min cdclk: 74250 kHz -> 0 kHz

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

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

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

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

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

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

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

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

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

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

<7> [98.829497] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_TC2

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [98.832623] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:631:HDMI-A-4]

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

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

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

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

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

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

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

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

<7> [98.835052] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:631:HDMI-A-4]

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

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

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

<7> [98.835635] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:622:DDI TC2/PHY D] [CRTC:309:pipe C]

<7> [98.835779] 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> [98.835930] 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> [98.836079] 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> [98.836228] 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> [98.836378] 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> [98.836528] 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> [98.836719] 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> [98.836868] 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> [98.837016] 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> [98.837170] 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> [98.837319] 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> [98.837468] 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> [98.837672] 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> [98.837822] 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> [98.837972] 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> [98.838121] 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> [98.838270] 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> [98.838419] 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> [98.838601] 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> [98.838801] 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> [98.838950] 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> [98.839100] 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> [98.839249] 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> [98.839399] 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> [98.839548] 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> [98.839740] 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> [98.839889] 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> [98.840039] 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> [98.840188] 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> [98.840338] 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> [98.840487] 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> [98.840680] 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> [98.840830] 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> [98.840981] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe C] fastset requirement not met in dpll_hw_state

<7> [98.841130] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [98.841279] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: cfgcr0: 0x0, cfgcr1: 0x0, 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> [98.841429] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [98.841667] i915 0000:03:00.0: [drm:intel_pipe_config_compare [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> [98.841818] 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> [98.841968] 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> [98.842117] 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> [98.842267] 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> [98.842417] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe C] fastset requirement not met, forcing full modeset

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

<7> [98.842781] 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> [98.842968] 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> [98.843114] 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> [98.843260] 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> [98.843406] 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> [98.843552] 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> [98.843743] 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> [98.843908] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:309:pipe C] data rate 594000 num active planes 1

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [98.846430] 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> [98.846616] 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> [98.846765] 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> [98.846914] 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> [98.847064] 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> [98.847214] 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> [98.847364] 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> [98.847514] 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> [98.847703] 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> [98.847852] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] linetime: 119, ips linetime: 0

<7> [98.848000] 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> [98.848149] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0

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

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

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

<7> [98.848786] 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> [98.848936] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [98.856290] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_TC2

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

<7> [98.891361] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:631:HDMI-A-4]

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

<6> [100.302882] [IGT] kms_flip: finished subtest B-HDMI-A4, FAIL

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