igt@kms_flip@flip-vs-expired-vblank-interruptible@a-hdmi-a2 on shard-glk@IGT

Detail	Value
Duration	1.75 seconds
Hostname	shard-glk1
Igt-Version	IGT-Version: 2.3-g1022f2615 (x86_64) (Linux: 6.19.0-rc4-CI_DRM_17775-g1124404e817b+ x86_64)
Out	Starting dynamic subtest: A-HDMI-A2 1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1889 run_test() #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045() #4 ../tests/kms_flip.c:2045 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-HDMI-A2: FAIL (1.747s)
Err	Starting dynamic subtest: A-HDMI-A2 (kms_flip:2540) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2540) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2540) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest A-HDMI-A2 failed. ** DEBUG (kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0) (kms_flip:2540) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2540) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680) (kms_flip:2540) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0) (kms_flip:2540) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2540) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) (kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680) (kms_flip:2540) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2540) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS (kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info (kms_flip:2540) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS (kms_flip:2540) igt_kms-INFO: 1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 (kms_flip:2540) DEBUG: No stale events found (kms_flip:2540) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 (kms_flip:2540) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 (kms_flip:2540) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 405.931213 current_received_ts = 405.930634 current_seq = 14826 count = 0 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 8us (kms_flip:2540) DEBUG: name = flip last_ts = 405.931213 last_received_ts = 405.930634 last_seq = 14826 current_ts = 405.947876 current_received_ts = 405.947266 current_seq = 14827 count = 1 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 6us (kms_flip:2540) DEBUG: name = flip last_ts = 405.947876 last_received_ts = 405.947266 last_seq = 14827 current_ts = 405.964569 current_received_ts = 405.964111 current_seq = 14828 count = 2 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 6us (kms_flip:2540) DEBUG: name = flip last_ts = 405.964569 last_received_ts = 405.964111 last_seq = 14828 current_ts = 405.981232 current_received_ts = 405.981354 current_seq = 14829 count = 3 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 405.981232 last_received_ts = 405.981354 last_seq = 14829 current_ts = 405.997894 current_received_ts = 405.997528 current_seq = 14830 count = 4 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 405.997894 last_received_ts = 405.997528 last_seq = 14830 current_ts = 406.014557 current_received_ts = 406.014343 current_seq = 14831 count = 5 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.014557 last_received_ts = 406.014343 last_seq = 14831 current_ts = 406.031219 current_received_ts = 406.031158 current_seq = 14832 count = 6 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 23us (kms_flip:2540) DEBUG: name = flip last_ts = 406.031219 last_received_ts = 406.031158 last_seq = 14832 current_ts = 406.047882 current_received_ts = 406.047852 current_seq = 14833 count = 7 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.047882 last_received_ts = 406.047852 last_seq = 14833 current_ts = 406.064545 current_received_ts = 406.064148 current_seq = 14834 count = 8 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 19us (kms_flip:2540) DEBUG: name = flip last_ts = 406.064545 last_received_ts = 406.064148 last_seq = 14834 current_ts = 406.081207 current_received_ts = 406.081635 current_seq = 14835 count = 9 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 19us (kms_flip:2540) DEBUG: name = flip last_ts = 406.081207 last_received_ts = 406.081635 last_seq = 14835 current_ts = 406.097870 current_received_ts = 406.097473 current_seq = 14836 count = 10 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.097870 last_received_ts = 406.097473 last_seq = 14836 current_ts = 406.114563 current_received_ts = 406.114380 current_seq = 14837 count = 11 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 23us (kms_flip:2540) DEBUG: name = flip last_ts = 406.114563 last_received_ts = 406.114380 last_seq = 14837 current_ts = 406.131226 current_received_ts = 406.130981 current_seq = 14838 count = 12 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.131226 last_received_ts = 406.130981 last_seq = 14838 current_ts = 406.147888 current_received_ts = 406.147491 current_seq = 14839 count = 13 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.147888 last_received_ts = 406.147491 last_seq = 14839 current_ts = 406.164551 current_received_ts = 406.164398 current_seq = 14840 count = 14 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.164551 last_received_ts = 406.164398 last_seq = 14840 current_ts = 406.181213 current_received_ts = 406.180786 current_seq = 14841 count = 15 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 19us (kms_flip:2540) DEBUG: name = flip last_ts = 406.181213 last_received_ts = 406.180786 last_seq = 14841 current_ts = 406.197906 current_received_ts = 406.197540 current_seq = 14842 count = 16 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.197906 last_received_ts = 406.197540 last_seq = 14842 current_ts = 406.214569 current_received_ts = 406.214355 current_seq = 14843 count = 17 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 20us (kms_flip:2540) DEBUG: name = flip last_ts = 406.214569 last_received_ts = 406.214355 last_seq = 14843 current_ts = 406.231232 current_received_ts = 406.230743 current_seq = 14844 count = 18 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.231232 last_received_ts = 406.230743 last_seq = 14844 current_ts = 406.247894 current_received_ts = 406.247467 current_seq = 14845 count = 19 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.247894 last_received_ts = 406.247467 last_seq = 14845 current_ts = 406.264557 current_received_ts = 406.264343 current_seq = 14846 count = 20 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.264557 last_received_ts = 406.264343 last_seq = 14846 current_ts = 406.281219 current_received_ts = 406.281097 current_seq = 14847 count = 21 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.281219 last_received_ts = 406.281097 last_seq = 14847 current_ts = 406.297882 current_received_ts = 406.297516 current_seq = 14848 count = 22 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.297882 last_received_ts = 406.297516 last_seq = 14848 current_ts = 406.314575 current_received_ts = 406.314423 current_seq = 14849 count = 23 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.314575 last_received_ts = 406.314423 last_seq = 14849 current_ts = 406.331238 current_received_ts = 406.330750 current_seq = 14850 count = 24 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 20us (kms_flip:2540) DEBUG: name = flip last_ts = 406.331238 last_received_ts = 406.330750 last_seq = 14850 current_ts = 406.347900 current_received_ts = 406.347900 current_seq = 14851 count = 25 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.347900 last_received_ts = 406.347900 last_seq = 14851 current_ts = 406.364563 current_received_ts = 406.364319 current_seq = 14852 count = 26 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.364563 last_received_ts = 406.364319 last_seq = 14852 current_ts = 406.381226 current_received_ts = 406.381104 current_seq = 14853 count = 27 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.381226 last_received_ts = 406.381104 last_seq = 14853 current_ts = 406.397919 current_received_ts = 406.397461 current_seq = 14854 count = 28 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.397919 last_received_ts = 406.397461 last_seq = 14854 current_ts = 406.414581 current_received_ts = 406.414429 current_seq = 14855 count = 29 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.414581 last_received_ts = 406.414429 last_seq = 14855 current_ts = 406.431244 current_received_ts = 406.431183 current_seq = 14856 count = 30 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.431244 last_received_ts = 406.431183 last_seq = 14856 current_ts = 406.447906 current_received_ts = 406.447479 current_seq = 14857 count = 31 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.447906 last_received_ts = 406.447479 last_seq = 14857 current_ts = 406.464569 current_received_ts = 406.464783 current_seq = 14858 count = 32 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 23us (kms_flip:2540) DEBUG: name = flip last_ts = 406.464569 last_received_ts = 406.464783 last_seq = 14858 current_ts = 406.481262 current_received_ts = 406.480774 current_seq = 14859 count = 33 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.481262 last_received_ts = 406.480774 last_seq = 14859 current_ts = 406.497925 current_received_ts = 406.497925 current_seq = 14860 count = 34 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.497925 last_received_ts = 406.497925 last_seq = 14860 current_ts = 406.514587 current_received_ts = 406.514832 current_seq = 14861 count = 35 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.514587 last_received_ts = 406.514832 last_seq = 14861 current_ts = 406.531250 current_received_ts = 406.531097 current_seq = 14862 count = 36 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 20us (kms_flip:2540) DEBUG: name = flip last_ts = 406.531250 last_received_ts = 406.531097 last_seq = 14862 current_ts = 406.547913 current_received_ts = 406.547852 current_seq = 14863 count = 37 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.547913 last_received_ts = 406.547852 last_seq = 14863 current_ts = 406.564575 current_received_ts = 406.564758 current_seq = 14864 count = 38 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.564575 last_received_ts = 406.564758 last_seq = 14864 current_ts = 406.581238 current_received_ts = 406.580719 current_seq = 14865 count = 39 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 20us (kms_flip:2540) DEBUG: name = flip last_ts = 406.581238 last_received_ts = 406.580719 last_seq = 14865 current_ts = 406.597900 current_received_ts = 406.597473 current_seq = 14866 count = 40 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.597900 last_received_ts = 406.597473 last_seq = 14866 current_ts = 406.614594 current_received_ts = 406.614471 current_seq = 14867 count = 41 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.614594 last_received_ts = 406.614471 last_seq = 14867 current_ts = 406.631256 current_received_ts = 406.631104 current_seq = 14868 count = 42 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.631256 last_received_ts = 406.631104 last_seq = 14868 current_ts = 406.647919 current_received_ts = 406.647430 current_seq = 14869 count = 43 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.647919 last_received_ts = 406.647430 last_seq = 14869 current_ts = 406.664581 current_received_ts = 406.664459 current_seq = 14870 count = 44 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 19us (kms_flip:2540) DEBUG: name = flip last_ts = 406.664581 last_received_ts = 406.664459 last_seq = 14870 current_ts = 406.681244 current_received_ts = 406.681061 current_seq = 14871 count = 45 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.681244 last_received_ts = 406.681061 last_seq = 14871 current_ts = 406.697906 current_received_ts = 406.697479 current_seq = 14872 count = 46 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 19us (kms_flip:2540) DEBUG: name = flip last_ts = 406.697906 last_received_ts = 406.697479 last_seq = 14872 current_ts = 406.714569 current_received_ts = 406.714600 current_seq = 14873 count = 47 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 19us (kms_flip:2540) DEBUG: name = flip last_ts = 406.714569 last_received_ts = 406.714600 last_seq = 14873 current_ts = 406.731262 current_received_ts = 406.730988 current_seq = 14874 count = 48 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 19us (kms_flip:2540) DEBUG: name = flip last_ts = 406.731262 last_received_ts = 406.730988 last_seq = 14874 current_ts = 406.747925 current_received_ts = 406.747437 current_seq = 14875 count = 49 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 23us (kms_flip:2540) DEBUG: name = flip last_ts = 406.747925 last_received_ts = 406.747437 last_seq = 14875 current_ts = 406.764587 current_received_ts = 406.764465 current_seq = 14876 count = 50 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 19us (kms_flip:2540) DEBUG: name = flip last_ts = 406.764587 last_received_ts = 406.764465 last_seq = 14876 current_ts = 406.781250 current_received_ts = 406.781097 current_seq = 14877 count = 51 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 24us (kms_flip:2540) DEBUG: name = flip last_ts = 406.781250 last_received_ts = 406.781097 last_seq = 14877 current_ts = 406.797913 current_received_ts = 406.797424 current_seq = 14878 count = 52 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.797913 last_received_ts = 406.797424 last_seq = 14878 current_ts = 406.814606 current_received_ts = 406.814911 current_seq = 14879 count = 53 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 20us (kms_flip:2540) DEBUG: name = flip last_ts = 406.814606 last_received_ts = 406.814911 last_seq = 14879 current_ts = 406.831268 current_received_ts = 406.831146 current_seq = 14880 count = 54 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 23us (kms_flip:2540) DEBUG: name = flip last_ts = 406.831268 last_received_ts = 406.831146 last_seq = 14880 current_ts = 406.847931 current_received_ts = 406.847473 current_seq = 14881 count = 55 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.847931 last_received_ts = 406.847473 last_seq = 14881 current_ts = 406.864594 current_received_ts = 406.864105 current_seq = 14882 count = 56 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.864594 last_received_ts = 406.864105 last_seq = 14882 current_ts = 406.881256 current_received_ts = 406.881531 current_seq = 14883 count = 57 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.881256 last_received_ts = 406.881531 last_seq = 14883 current_ts = 406.897919 current_received_ts = 406.897705 current_seq = 14884 count = 58 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 19us (kms_flip:2540) DEBUG: name = flip last_ts = 406.897919 last_received_ts = 406.897705 last_seq = 14884 current_ts = 406.914581 current_received_ts = 406.914490 current_seq = 14885 count = 59 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 406.914581 last_received_ts = 406.914490 last_seq = 14885 current_ts = 406.931244 current_received_ts = 406.931061 current_seq = 14886 count = 60 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.931244 last_received_ts = 406.931061 last_seq = 14886 current_ts = 406.947937 current_received_ts = 406.947510 current_seq = 14887 count = 61 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.947937 last_received_ts = 406.947510 last_seq = 14887 current_ts = 406.964600 current_received_ts = 406.964691 current_seq = 14888 count = 62 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 20us (kms_flip:2540) DEBUG: name = flip last_ts = 406.964600 last_received_ts = 406.964691 last_seq = 14888 current_ts = 406.981262 current_received_ts = 406.981232 current_seq = 14889 count = 63 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 18us (kms_flip:2540) DEBUG: name = flip last_ts = 406.981262 last_received_ts = 406.981232 last_seq = 14889 current_ts = 406.997925 current_received_ts = 406.997864 current_seq = 14890 count = 64 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 406.997925 last_received_ts = 406.997864 last_seq = 14890 current_ts = 407.014618 current_received_ts = 407.014404 current_seq = 14891 count = 65 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 407.014618 last_received_ts = 407.014404 last_seq = 14891 current_ts = 407.031281 current_received_ts = 407.030884 current_seq = 14892 count = 66 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 407.031281 last_received_ts = 407.030884 last_seq = 14892 current_ts = 407.047943 current_received_ts = 407.047852 current_seq = 14893 count = 67 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 407.047943 last_received_ts = 407.047852 last_seq = 14893 current_ts = 407.064606 current_received_ts = 407.064514 current_seq = 14894 count = 68 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 20us (kms_flip:2540) DEBUG: name = flip last_ts = 407.064606 last_received_ts = 407.064514 last_seq = 14894 current_ts = 407.081268 current_received_ts = 407.080719 current_seq = 14895 count = 69 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 20us (kms_flip:2540) DEBUG: name = flip last_ts = 407.081268 last_received_ts = 407.080719 last_seq = 14895 current_ts = 407.097931 current_received_ts = 407.097961 current_seq = 14896 count = 70 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 19us (kms_flip:2540) DEBUG: name = flip last_ts = 407.097931 last_received_ts = 407.097961 last_seq = 14896 current_ts = 407.114594 current_received_ts = 407.114380 current_seq = 14897 count = 71 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 407.114594 last_received_ts = 407.114380 last_seq = 14897 current_ts = 407.131256 current_received_ts = 407.131104 current_seq = 14898 count = 72 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 23us (kms_flip:2540) DEBUG: name = flip last_ts = 407.131256 last_received_ts = 407.131104 last_seq = 14898 current_ts = 407.147949 current_received_ts = 407.147522 current_seq = 14899 count = 73 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 407.147949 last_received_ts = 407.147522 last_seq = 14899 current_ts = 407.164612 current_received_ts = 407.164429 current_seq = 14900 count = 74 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 407.164612 last_received_ts = 407.164429 last_seq = 14900 current_ts = 407.181274 current_received_ts = 407.182495 current_seq = 14901 count = 75 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 21us (kms_flip:2540) DEBUG: name = flip last_ts = 407.181274 last_received_ts = 407.182495 last_seq = 14901 current_ts = 407.197937 current_received_ts = 407.197510 current_seq = 14902 count = 76 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 407.197937 last_received_ts = 407.197510 last_seq = 14902 current_ts = 407.214630 current_received_ts = 407.214752 current_seq = 14903 count = 77 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 22us (kms_flip:2540) DEBUG: name = flip last_ts = 407.214630 last_received_ts = 407.214752 last_seq = 14903 current_ts = 407.231262 current_received_ts = 407.231140 current_seq = 14904 count = 78 seq_step = 1 (kms_flip:2540) DEBUG: Vblank took 1046us (kms_flip:2540) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2540) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2540) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:2540) igt_core-INFO: Stack trace: (kms_flip:2540) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2540) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:2540) igt_core-INFO: #2 ../tests/kms_flip.c:1889 run_test() (kms_flip:2540) igt_core-INFO: #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045() (kms_flip:2540) igt_core-INFO: #4 ../tests/kms_flip.c:2045 main() (kms_flip:2540) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2540) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2540) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-HDMI-A2: FAIL (1.747s)
Dmesg	<6> [419.043315] [IGT] kms_flip: starting dynamic subtest A-HDMI-A2 <7> [419.046833] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:178] <7> [419.047575] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:182] <7> [419.085828] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:76:pipe A] <7> [419.087108] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:119:pipe B] <7> [419.088206] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:162:pipe C] <7> [419.088435] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.enable (expected yes, found no) <7> [419.088998] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.active (expected yes, found no) <7> [419.089470] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in cpu_transcoder (expected 2, found -1) <7> [419.089879] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in lane_count (expected 4, found 0) <7> [419.090311] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000) <7> [419.090724] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [419.091155] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [419.091565] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [419.091970] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [419.092403] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [419.092810] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [419.093237] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [419.093644] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [419.094052] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [419.094480] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [419.094888] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [419.095329] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [419.095739] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [419.096162] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [419.096570] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [419.096977] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [419.097405] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [419.097812] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [419.098237] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [419.098644] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [419.099052] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [419.099480] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [419.099889] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [419.100317] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [419.100727] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [419.101154] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [419.101564] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [419.101972] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [419.102395] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [419.102804] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [419.103231] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in has_infoframe (expected yes, found no) <7> [419.103644] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [419.104053] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [419.104478] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [419.104885] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in port_clock (expected 222750, found 0) <7> [419.105311] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [419.105719] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000) <7> [419.106128] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in avi infoframe <7> [419.106552] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [419.106961] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [419.106966] i915 0000:00:02.0: colorspace: RGB <7> [419.106970] i915 0000:00:02.0: scan mode: Underscan <7> [419.106973] i915 0000:00:02.0: colorimetry: No Data <7> [419.106977] i915 0000:00:02.0: picture aspect: No Data <7> [419.106980] i915 0000:00:02.0: active aspect: Same as Picture <7> [419.106983] i915 0000:00:02.0: itc: No Data <7> [419.106986] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [419.106990] i915 0000:00:02.0: quantization range: Full <7> [419.106993] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [419.106996] i915 0000:00:02.0: video code: 0 <7> [419.107000] i915 0000:00:02.0: ycc quantization range: Full <7> [419.107003] i915 0000:00:02.0: hdmi content type: Graphics <7> [419.107006] i915 0000:00:02.0: pixel repeat: 0 <7> [419.107009] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [419.107013] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [419.107435] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in spd infoframe <7> [419.107842] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [419.108267] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [419.108271] i915 0000:00:02.0: vendor: Intel <7> [419.108274] i915 0000:00:02.0: product: Integrated gfx <7> [419.108277] i915 0000:00:02.0: source device information: PC General (0x9) <7> [419.108281] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [419.108687] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hdmi infoframe <7> [419.109093] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [419.109509] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [419.109514] i915 0000:00:02.0: empty frame <7> [419.109517] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [419.109927] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:162:pipe C] fastset requirement not met, forcing full modeset <7> [419.110356] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:162:pipe C] releasing PORT PLL B <7> [419.111425] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:162:pipe C] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x4 -> 0x0 <7> [419.112218] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:156:cursor C] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0 <7> [419.112813] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:162:pipe C] min cdclk: 192000 kHz -> 0 kHz <7> [419.115215] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [419.115743] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz <7> [419.116184] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4 <7> [419.116603] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:162:pipe C] enable: no [modeset] <7> [419.117015] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:120:plane 1C] fb: [NOFB], visible: no <7> [419.117450] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:129:plane 2C] fb: [NOFB], visible: no <7> [419.117859] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:138:plane 3C] fb: [NOFB], visible: no <7> [419.118286] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:147:plane 4C] fb: [NOFB], visible: no <7> [419.118694] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:156:cursor C] fb: [NOFB], visible: no <7> [419.120950] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:164:HDMI-A-1][ENCODER:163:DDI B/PHY B] Disable audio codec on [CRTC:162:pipe C] <7> [419.153177] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [419.155476] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe C <7> [419.167693] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10 <7> [419.171199] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time <7> [419.277640] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [419.278879] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x4, on? 1) for [CRTC:162:pipe C] <7> [419.280567] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL B <7> [419.281005] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 79200 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 4 <7> [419.281483] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:163:DDI B/PHY B] <7> [419.283702] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:173:DDI C/PHY C] <7> [419.284327] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:164:HDMI-A-1] <7> [419.284993] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-b <7> [419.285655] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:162:pipe C] <7> [419.288880] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:76:pipe A] <7> [419.288712] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [419.289309] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz <7> [419.289730] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13 <7> [419.291663] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:76:pipe A] <7> [419.293964] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 316800 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 13 <7> [419.295001] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:174:HDMI-A-2] <7> [419.295440] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 12 bpc for HDMI output (pipe bpp: 36) <7> [419.295892] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:76:pipe A] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [419.296350] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:173:DDI C/PHY C] [CRTC:76:pipe A] <7> [419.296756] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [419.297197] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [419.297606] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [419.298015] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [419.298451] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d) <7> [419.298863] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [419.299299] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [419.299707] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [419.300113] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [419.300545] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [419.300954] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [419.301387] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [419.301794] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [419.302217] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [419.302625] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [419.303030] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [419.303452] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [419.303861] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [419.304276] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [419.304685] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [419.305092] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [419.305517] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [419.305926] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [419.306343] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [419.306752] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [419.307175] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [419.307581] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [419.307987] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [419.308405] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [419.308814] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [419.309237] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [419.309644] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [419.310048] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [419.310466] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [419.310875] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [419.311295] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in has_infoframe (expected no, found yes) <7> [419.311704] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [419.312111] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [419.312528] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [419.312933] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in port_clock (expected 0, found 222750) <7> [419.313357] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [419.313763] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006) <7> [419.314180] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in avi infoframe <7> [419.314588] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [419.314991] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [419.315414] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [419.315419] i915 0000:00:02.0: colorspace: RGB <7> [419.315423] i915 0000:00:02.0: scan mode: Underscan <7> [419.315426] i915 0000:00:02.0: colorimetry: No Data <7> [419.315429] i915 0000:00:02.0: picture aspect: No Data <7> [419.315432] i915 0000:00:02.0: active aspect: Same as Picture <7> [419.315436] i915 0000:00:02.0: itc: No Data <7> [419.315439] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [419.315442] i915 0000:00:02.0: quantization range: Full <7> [419.315445] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [419.315449] i915 0000:00:02.0: video code: 0 <7> [419.315452] i915 0000:00:02.0: ycc quantization range: Full <7> [419.315455] i915 0000:00:02.0: hdmi content type: Graphics <7> [419.315458] i915 0000:00:02.0: pixel repeat: 0 <7> [419.315462] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [419.315466] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in spd infoframe <7> [419.315873] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [419.316289] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [419.316693] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [419.316699] i915 0000:00:02.0: vendor: Intel <7> [419.316702] i915 0000:00:02.0: product: Integrated gfx <7> [419.316705] i915 0000:00:02.0: source device information: PC General (0x9) <7> [419.316709] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hdmi infoframe <7> [419.317114] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [419.317534] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [419.317938] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [419.317945] i915 0000:00:02.0: empty frame <7> [419.317949] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:76:pipe A] fastset requirement not met, forcing full modeset <7> [419.319688] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:76:pipe A] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x1 <7> [419.320323] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:34:plane 1A] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988 <7> [419.320757] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:70:cursor A] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32 <7> [419.321184] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:34:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,*twm, swm, stwm <7> [419.321598] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:34:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0 <7> [419.322002] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:34:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0 <7> [419.322436] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:34:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 17, 17, 17, 34, 34, 34, 34, 34, 31, 0, 0 <7> [419.324441] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL <7> [419.324461] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled <7> [419.327768] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:76:pipe A] min cdclk: 0 kHz -> 192000 kHz <7> [419.328673] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:76:pipe A] using pre-allocated PORT PLL C <7> [419.329171] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:76:pipe A] reserving PORT PLL C <7> [419.329595] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:76:pipe A] enable: yes [modeset] <7> [419.330005] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [419.330456] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 36, dithering: 0 <7> [419.330861] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [419.331289] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [419.331697] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [419.332101] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [419.332521] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [419.332929] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6 <7> [419.333358] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [419.333363] i915 0000:00:02.0: colorspace: RGB <7> [419.333367] i915 0000:00:02.0: scan mode: Underscan <7> [419.333371] i915 0000:00:02.0: colorimetry: No Data <7> [419.333374] i915 0000:00:02.0: picture aspect: No Data <7> [419.333377] i915 0000:00:02.0: active aspect: Same as Picture <7> [419.333380] i915 0000:00:02.0: itc: No Data <7> [419.333383] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [419.333387] i915 0000:00:02.0: quantization range: Full <7> [419.333390] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [419.333393] i915 0000:00:02.0: video code: 0 <7> [419.333397] i915 0000:00:02.0: ycc quantization range: Full <7> [419.333400] i915 0000:00:02.0: hdmi content type: Graphics <7> [419.333403] i915 0000:00:02.0: pixel repeat: 0 <7> [419.333406] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [419.333410] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [419.333413] i915 0000:00:02.0: vendor: Intel <7> [419.333417] i915 0000:00:02.0: product: Integrated gfx <7> [419.333420] i915 0000:00:02.0: source device information: PC General (0x9) <7> [419.333424] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [419.333427] i915 0000:00:02.0: empty frame <7> [419.333431] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 07 00 66 10 00 01 00 00 00 00 00 00 00 00 <7> [419.333839] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 05 e3 cd 0c 32 38 45 38 35 30 09 07 07 00 00 00 <7> [419.334271] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [419.334675] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [419.335080] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0 <7> [419.335504] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0 <7> [419.335908] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [419.336329] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [419.336736] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [419.337153] i915 0000:00:02.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=1083-1088 vt=1125, flags=0x9 <7> [419.337564] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x40 0x9 <7> [419.337968] i915 0000:00:02.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=1083-1088 vt=1125, flags=0x9 <7> [419.338391] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pipe src: 1920x1080+0+0, pixel rate 148500, min cdclk 192000 <7> [419.338796] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [419.339211] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [419.339616] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [419.340025] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [419.340445] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: ebb0: 0x6200, ebb4: 0x2000,pll0: 0x21, pll1: 0x100, pll2: 0x1a6666, pll3: 0x10000, pll6: 0x30904, pll8: 0x8, pll9: 0xa, pll10: 0x8003c00, pcsdw12: 0x4d <7> [419.340877] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [419.341307] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [419.341712] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [419.342115] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [419.342546] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [419.342950] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [419.343368] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [419.343772] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [419.344190] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:34:plane 1A] fb: [FB:178] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [419.344606] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [419.345012] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [419.345434] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:43:plane 2A] fb: [NOFB], visible: no <7> [419.345841] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:52:plane 3A] fb: [NOFB], visible: no <7> [419.346274] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:61:plane 4A] fb: [NOFB], visible: no <7> [419.346681] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:70:cursor A] fb: [NOFB], visible: no <7> [419.351492] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-c <7> [419.354106] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:163:DDI B/PHY B] <7> [419.354738] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:173:DDI C/PHY C] <7> [419.357199] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL C (active 0x1, on? 0) for [CRTC:76:pipe A] <7> [419.357791] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL C <7> [419.358545] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_C <7> [419.359067] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A <7> [419.360204] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] reserved 16588800 bytes of contiguous stolen space for FBC, limit: 1 <7> [419.360641] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] Enabling FBC on [PLANE:34:plane 1A] <7> [419.376816] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:174:HDMI-A-2][ENCODER:173:DDI C/PHY C] Enable audio codec on [CRTC:76:pipe A], 32 bytes ELD <7> [419.393447] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000) <7> [419.393964] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <7> [419.394745] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:174:HDMI-A-2] <7> [419.396508] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:76:pipe A] <6> [420.791928] [IGT] kms_flip: finished subtest A-HDMI-A2, FAIL

Detail

Value

Duration

1.75 seconds

Hostname

shard-glk1

Igt-Version

IGT-Version: 2.3-g1022f2615 (x86_64) (Linux: 6.19.0-rc4-CI_DRM_17775-g1124404e817b+ x86_64)

Out

Starting dynamic subtest: A-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1889 run_test()
  #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
  #4 ../tests/kms_flip.c:2045 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A2: FAIL (1.747s)

Err

Starting dynamic subtest: A-HDMI-A2
(kms_flip:2540) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2540) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2540) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest A-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
(kms_flip:2540) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2540) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:2540) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000001, size=0)
(kms_flip:2540) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2540) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:2540) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:2540) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:2540) DEBUG: No stale events found
(kms_flip:2540) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2540) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2540) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 405.931213
current_received_ts = 405.930634
current_seq = 14826
count = 0
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 8us
(kms_flip:2540) DEBUG: name = flip
last_ts = 405.931213
last_received_ts = 405.930634
last_seq = 14826
current_ts = 405.947876
current_received_ts = 405.947266
current_seq = 14827
count = 1
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 6us
(kms_flip:2540) DEBUG: name = flip
last_ts = 405.947876
last_received_ts = 405.947266
last_seq = 14827
current_ts = 405.964569
current_received_ts = 405.964111
current_seq = 14828
count = 2
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 6us
(kms_flip:2540) DEBUG: name = flip
last_ts = 405.964569
last_received_ts = 405.964111
last_seq = 14828
current_ts = 405.981232
current_received_ts = 405.981354
current_seq = 14829
count = 3
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 405.981232
last_received_ts = 405.981354
last_seq = 14829
current_ts = 405.997894
current_received_ts = 405.997528
current_seq = 14830
count = 4
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 405.997894
last_received_ts = 405.997528
last_seq = 14830
current_ts = 406.014557
current_received_ts = 406.014343
current_seq = 14831
count = 5
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.014557
last_received_ts = 406.014343
last_seq = 14831
current_ts = 406.031219
current_received_ts = 406.031158
current_seq = 14832
count = 6
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 23us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.031219
last_received_ts = 406.031158
last_seq = 14832
current_ts = 406.047882
current_received_ts = 406.047852
current_seq = 14833
count = 7
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.047882
last_received_ts = 406.047852
last_seq = 14833
current_ts = 406.064545
current_received_ts = 406.064148
current_seq = 14834
count = 8
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 19us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.064545
last_received_ts = 406.064148
last_seq = 14834
current_ts = 406.081207
current_received_ts = 406.081635
current_seq = 14835
count = 9
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 19us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.081207
last_received_ts = 406.081635
last_seq = 14835
current_ts = 406.097870
current_received_ts = 406.097473
current_seq = 14836
count = 10
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.097870
last_received_ts = 406.097473
last_seq = 14836
current_ts = 406.114563
current_received_ts = 406.114380
current_seq = 14837
count = 11
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 23us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.114563
last_received_ts = 406.114380
last_seq = 14837
current_ts = 406.131226
current_received_ts = 406.130981
current_seq = 14838
count = 12
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.131226
last_received_ts = 406.130981
last_seq = 14838
current_ts = 406.147888
current_received_ts = 406.147491
current_seq = 14839
count = 13
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.147888
last_received_ts = 406.147491
last_seq = 14839
current_ts = 406.164551
current_received_ts = 406.164398
current_seq = 14840
count = 14
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.164551
last_received_ts = 406.164398
last_seq = 14840
current_ts = 406.181213
current_received_ts = 406.180786
current_seq = 14841
count = 15
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 19us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.181213
last_received_ts = 406.180786
last_seq = 14841
current_ts = 406.197906
current_received_ts = 406.197540
current_seq = 14842
count = 16
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.197906
last_received_ts = 406.197540
last_seq = 14842
current_ts = 406.214569
current_received_ts = 406.214355
current_seq = 14843
count = 17
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 20us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.214569
last_received_ts = 406.214355
last_seq = 14843
current_ts = 406.231232
current_received_ts = 406.230743
current_seq = 14844
count = 18
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.231232
last_received_ts = 406.230743
last_seq = 14844
current_ts = 406.247894
current_received_ts = 406.247467
current_seq = 14845
count = 19
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.247894
last_received_ts = 406.247467
last_seq = 14845
current_ts = 406.264557
current_received_ts = 406.264343
current_seq = 14846
count = 20
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.264557
last_received_ts = 406.264343
last_seq = 14846
current_ts = 406.281219
current_received_ts = 406.281097
current_seq = 14847
count = 21
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.281219
last_received_ts = 406.281097
last_seq = 14847
current_ts = 406.297882
current_received_ts = 406.297516
current_seq = 14848
count = 22
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.297882
last_received_ts = 406.297516
last_seq = 14848
current_ts = 406.314575
current_received_ts = 406.314423
current_seq = 14849
count = 23
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.314575
last_received_ts = 406.314423
last_seq = 14849
current_ts = 406.331238
current_received_ts = 406.330750
current_seq = 14850
count = 24
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 20us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.331238
last_received_ts = 406.330750
last_seq = 14850
current_ts = 406.347900
current_received_ts = 406.347900
current_seq = 14851
count = 25
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.347900
last_received_ts = 406.347900
last_seq = 14851
current_ts = 406.364563
current_received_ts = 406.364319
current_seq = 14852
count = 26
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.364563
last_received_ts = 406.364319
last_seq = 14852
current_ts = 406.381226
current_received_ts = 406.381104
current_seq = 14853
count = 27
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.381226
last_received_ts = 406.381104
last_seq = 14853
current_ts = 406.397919
current_received_ts = 406.397461
current_seq = 14854
count = 28
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.397919
last_received_ts = 406.397461
last_seq = 14854
current_ts = 406.414581
current_received_ts = 406.414429
current_seq = 14855
count = 29
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.414581
last_received_ts = 406.414429
last_seq = 14855
current_ts = 406.431244
current_received_ts = 406.431183
current_seq = 14856
count = 30
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.431244
last_received_ts = 406.431183
last_seq = 14856
current_ts = 406.447906
current_received_ts = 406.447479
current_seq = 14857
count = 31
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.447906
last_received_ts = 406.447479
last_seq = 14857
current_ts = 406.464569
current_received_ts = 406.464783
current_seq = 14858
count = 32
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 23us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.464569
last_received_ts = 406.464783
last_seq = 14858
current_ts = 406.481262
current_received_ts = 406.480774
current_seq = 14859
count = 33
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.481262
last_received_ts = 406.480774
last_seq = 14859
current_ts = 406.497925
current_received_ts = 406.497925
current_seq = 14860
count = 34
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.497925
last_received_ts = 406.497925
last_seq = 14860
current_ts = 406.514587
current_received_ts = 406.514832
current_seq = 14861
count = 35
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.514587
last_received_ts = 406.514832
last_seq = 14861
current_ts = 406.531250
current_received_ts = 406.531097
current_seq = 14862
count = 36
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 20us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.531250
last_received_ts = 406.531097
last_seq = 14862
current_ts = 406.547913
current_received_ts = 406.547852
current_seq = 14863
count = 37
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.547913
last_received_ts = 406.547852
last_seq = 14863
current_ts = 406.564575
current_received_ts = 406.564758
current_seq = 14864
count = 38
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.564575
last_received_ts = 406.564758
last_seq = 14864
current_ts = 406.581238
current_received_ts = 406.580719
current_seq = 14865
count = 39
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 20us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.581238
last_received_ts = 406.580719
last_seq = 14865
current_ts = 406.597900
current_received_ts = 406.597473
current_seq = 14866
count = 40
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.597900
last_received_ts = 406.597473
last_seq = 14866
current_ts = 406.614594
current_received_ts = 406.614471
current_seq = 14867
count = 41
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.614594
last_received_ts = 406.614471
last_seq = 14867
current_ts = 406.631256
current_received_ts = 406.631104
current_seq = 14868
count = 42
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.631256
last_received_ts = 406.631104
last_seq = 14868
current_ts = 406.647919
current_received_ts = 406.647430
current_seq = 14869
count = 43
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.647919
last_received_ts = 406.647430
last_seq = 14869
current_ts = 406.664581
current_received_ts = 406.664459
current_seq = 14870
count = 44
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 19us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.664581
last_received_ts = 406.664459
last_seq = 14870
current_ts = 406.681244
current_received_ts = 406.681061
current_seq = 14871
count = 45
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.681244
last_received_ts = 406.681061
last_seq = 14871
current_ts = 406.697906
current_received_ts = 406.697479
current_seq = 14872
count = 46
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 19us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.697906
last_received_ts = 406.697479
last_seq = 14872
current_ts = 406.714569
current_received_ts = 406.714600
current_seq = 14873
count = 47
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 19us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.714569
last_received_ts = 406.714600
last_seq = 14873
current_ts = 406.731262
current_received_ts = 406.730988
current_seq = 14874
count = 48
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 19us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.731262
last_received_ts = 406.730988
last_seq = 14874
current_ts = 406.747925
current_received_ts = 406.747437
current_seq = 14875
count = 49
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 23us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.747925
last_received_ts = 406.747437
last_seq = 14875
current_ts = 406.764587
current_received_ts = 406.764465
current_seq = 14876
count = 50
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 19us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.764587
last_received_ts = 406.764465
last_seq = 14876
current_ts = 406.781250
current_received_ts = 406.781097
current_seq = 14877
count = 51
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 24us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.781250
last_received_ts = 406.781097
last_seq = 14877
current_ts = 406.797913
current_received_ts = 406.797424
current_seq = 14878
count = 52
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.797913
last_received_ts = 406.797424
last_seq = 14878
current_ts = 406.814606
current_received_ts = 406.814911
current_seq = 14879
count = 53
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 20us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.814606
last_received_ts = 406.814911
last_seq = 14879
current_ts = 406.831268
current_received_ts = 406.831146
current_seq = 14880
count = 54
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 23us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.831268
last_received_ts = 406.831146
last_seq = 14880
current_ts = 406.847931
current_received_ts = 406.847473
current_seq = 14881
count = 55
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.847931
last_received_ts = 406.847473
last_seq = 14881
current_ts = 406.864594
current_received_ts = 406.864105
current_seq = 14882
count = 56
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.864594
last_received_ts = 406.864105
last_seq = 14882
current_ts = 406.881256
current_received_ts = 406.881531
current_seq = 14883
count = 57
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.881256
last_received_ts = 406.881531
last_seq = 14883
current_ts = 406.897919
current_received_ts = 406.897705
current_seq = 14884
count = 58
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 19us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.897919
last_received_ts = 406.897705
last_seq = 14884
current_ts = 406.914581
current_received_ts = 406.914490
current_seq = 14885
count = 59
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.914581
last_received_ts = 406.914490
last_seq = 14885
current_ts = 406.931244
current_received_ts = 406.931061
current_seq = 14886
count = 60
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.931244
last_received_ts = 406.931061
last_seq = 14886
current_ts = 406.947937
current_received_ts = 406.947510
current_seq = 14887
count = 61
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.947937
last_received_ts = 406.947510
last_seq = 14887
current_ts = 406.964600
current_received_ts = 406.964691
current_seq = 14888
count = 62
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 20us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.964600
last_received_ts = 406.964691
last_seq = 14888
current_ts = 406.981262
current_received_ts = 406.981232
current_seq = 14889
count = 63
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 18us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.981262
last_received_ts = 406.981232
last_seq = 14889
current_ts = 406.997925
current_received_ts = 406.997864
current_seq = 14890
count = 64
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 406.997925
last_received_ts = 406.997864
last_seq = 14890
current_ts = 407.014618
current_received_ts = 407.014404
current_seq = 14891
count = 65
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.014618
last_received_ts = 407.014404
last_seq = 14891
current_ts = 407.031281
current_received_ts = 407.030884
current_seq = 14892
count = 66
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.031281
last_received_ts = 407.030884
last_seq = 14892
current_ts = 407.047943
current_received_ts = 407.047852
current_seq = 14893
count = 67
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.047943
last_received_ts = 407.047852
last_seq = 14893
current_ts = 407.064606
current_received_ts = 407.064514
current_seq = 14894
count = 68
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 20us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.064606
last_received_ts = 407.064514
last_seq = 14894
current_ts = 407.081268
current_received_ts = 407.080719
current_seq = 14895
count = 69
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 20us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.081268
last_received_ts = 407.080719
last_seq = 14895
current_ts = 407.097931
current_received_ts = 407.097961
current_seq = 14896
count = 70
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 19us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.097931
last_received_ts = 407.097961
last_seq = 14896
current_ts = 407.114594
current_received_ts = 407.114380
current_seq = 14897
count = 71
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.114594
last_received_ts = 407.114380
last_seq = 14897
current_ts = 407.131256
current_received_ts = 407.131104
current_seq = 14898
count = 72
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 23us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.131256
last_received_ts = 407.131104
last_seq = 14898
current_ts = 407.147949
current_received_ts = 407.147522
current_seq = 14899
count = 73
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.147949
last_received_ts = 407.147522
last_seq = 14899
current_ts = 407.164612
current_received_ts = 407.164429
current_seq = 14900
count = 74
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.164612
last_received_ts = 407.164429
last_seq = 14900
current_ts = 407.181274
current_received_ts = 407.182495
current_seq = 14901
count = 75
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 21us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.181274
last_received_ts = 407.182495
last_seq = 14901
current_ts = 407.197937
current_received_ts = 407.197510
current_seq = 14902
count = 76
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.197937
last_received_ts = 407.197510
last_seq = 14902
current_ts = 407.214630
current_received_ts = 407.214752
current_seq = 14903
count = 77
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 22us
(kms_flip:2540) DEBUG: name = flip
last_ts = 407.214630
last_received_ts = 407.214752
last_seq = 14903
current_ts = 407.231262
current_received_ts = 407.231140
current_seq = 14904
count = 78
seq_step = 1
(kms_flip:2540) DEBUG: Vblank took 1046us
(kms_flip:2540) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2540) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2540) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2540) igt_core-INFO: Stack trace:
(kms_flip:2540) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2540) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:2540) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:2540) igt_core-INFO:   #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
(kms_flip:2540) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:2540) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2540) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2540) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A2: FAIL (1.747s)

Dmesg

<6> [419.043315] [IGT] kms_flip: starting dynamic subtest A-HDMI-A2

<7> [419.046833] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:178]

<7> [419.047575] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:182]

<7> [419.085828] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:76:pipe A]

<7> [419.087108] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:119:pipe B]

<7> [419.088206] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:162:pipe C]

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

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

<7> [419.089470] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in cpu_transcoder (expected 2, found -1)

<7> [419.089879] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in lane_count (expected 4, found 0)

<7> [419.090311] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000)

<7> [419.090724] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000)

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

<7> [419.091565] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0)

<7> [419.091970] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0)

<7> [419.092403] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0)

<7> [419.092810] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0)

<7> [419.093237] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0)

<7> [419.093644] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0)

<7> [419.094052] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0)

<7> [419.094480] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0)

<7> [419.094888] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0)

<7> [419.095329] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0)

<7> [419.095739] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0)

<7> [419.096162] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0)

<7> [419.096570] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0)

<7> [419.096977] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0)

<7> [419.097405] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0)

<7> [419.097812] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0)

<7> [419.098237] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0)

<7> [419.098644] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0)

<7> [419.099052] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0)

<7> [419.099480] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0)

<7> [419.099889] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0)

<7> [419.100317] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0)

<7> [419.100727] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0)

<7> [419.101154] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0)

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

<7> [419.101972] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0)

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

<7> [419.102804] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in has_hdmi_sink (expected yes, found no)

<7> [419.103231] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in has_infoframe (expected yes, found no)

<7> [419.103644] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in pipe_bpp (expected 36, found 0)

<7> [419.104053] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0)

<7> [419.104478] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0)

<7> [419.104885] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in port_clock (expected 222750, found 0)

<7> [419.105311] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000)

<7> [419.105719] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000)

<7> [419.106128] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in avi infoframe

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

<7> [419.106961] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [419.106966] i915 0000:00:02.0: colorspace: RGB

<7> [419.106970] i915 0000:00:02.0: scan mode: Underscan

<7> [419.106973] i915 0000:00:02.0: colorimetry: No Data

<7> [419.106977] i915 0000:00:02.0: picture aspect: No Data

<7> [419.106980] i915 0000:00:02.0: active aspect: Same as Picture

<7> [419.106983] i915 0000:00:02.0: itc: No Data

<7> [419.106986] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [419.106990] i915 0000:00:02.0: quantization range: Full

<7> [419.106993] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [419.106996] i915 0000:00:02.0: video code: 0

<7> [419.107000] i915 0000:00:02.0: ycc quantization range: Full

<7> [419.107003] i915 0000:00:02.0: hdmi content type: Graphics

<7> [419.107006] i915 0000:00:02.0: pixel repeat: 0

<7> [419.107009] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

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

<7> [419.107435] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in spd infoframe

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

<7> [419.108267] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [419.108271] i915 0000:00:02.0: vendor: Intel

<7> [419.108274] i915 0000:00:02.0: product: Integrated gfx

<7> [419.108277] i915 0000:00:02.0: source device information: PC General (0x9)

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

<7> [419.108687] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:162:pipe C] fastset requirement not met in hdmi infoframe

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

<7> [419.109509] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [419.109514] i915 0000:00:02.0: empty frame

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

<7> [419.109927] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:162:pipe C] fastset requirement not met, forcing full modeset

<7> [419.110356] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:162:pipe C] releasing PORT PLL B

<7> [419.111425] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:162:pipe C] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x4 -> 0x0

<7> [419.112218] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:156:cursor C] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0

<7> [419.112813] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:162:pipe C] min cdclk: 192000 kHz -> 0 kHz

<7> [419.115215] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change

<7> [419.115743] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz

<7> [419.116184] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4

<7> [419.116603] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:162:pipe C] enable: no [modeset]

<7> [419.117015] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:120:plane 1C] fb: [NOFB], visible: no

<7> [419.117450] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:129:plane 2C] fb: [NOFB], visible: no

<7> [419.117859] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:138:plane 3C] fb: [NOFB], visible: no

<7> [419.118286] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:147:plane 4C] fb: [NOFB], visible: no

<7> [419.118694] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:156:cursor C] fb: [NOFB], visible: no

<7> [419.120950] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:164:HDMI-A-1][ENCODER:163:DDI B/PHY B] Disable audio codec on [CRTC:162:pipe C]

<7> [419.153177] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B

<7> [419.155476] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe C

<7> [419.167693] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10

<7> [419.171199] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time

<7> [419.277640] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B

<7> [419.278879] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x4, on? 1) for [CRTC:162:pipe C]

<7> [419.280567] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL B

<7> [419.281005] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 79200 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 4

<7> [419.281483] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:163:DDI B/PHY B]

<7> [419.283702] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:173:DDI C/PHY C]

<7> [419.284327] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:164:HDMI-A-1]

<7> [419.284993] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-b

<7> [419.285655] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:162:pipe C]

<7> [419.288880] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:76:pipe A]

<7> [419.288712] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change

<7> [419.289309] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz

<7> [419.289730] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13

<7> [419.291663] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:76:pipe A]

<7> [419.293964] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 316800 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 13

<7> [419.295001] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:174:HDMI-A-2]

<7> [419.295440] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 12 bpc for HDMI output (pipe bpp: 36)

<7> [419.295892] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:76:pipe A] hw max bpp: 36, pipe bpp: 36, dithering: 0

<7> [419.296350] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:173:DDI C/PHY C] [CRTC:76:pipe A]

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

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

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

<7> [419.298015] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in lane_count (expected 0, found 4)

<7> [419.298451] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [419.313357] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071)

<7> [419.313763] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006)

<7> [419.314180] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in avi infoframe

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

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

<7> [419.315414] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [419.315419] i915 0000:00:02.0: colorspace: RGB

<7> [419.315423] i915 0000:00:02.0: scan mode: Underscan

<7> [419.315426] i915 0000:00:02.0: colorimetry: No Data

<7> [419.315429] i915 0000:00:02.0: picture aspect: No Data

<7> [419.315432] i915 0000:00:02.0: active aspect: Same as Picture

<7> [419.315436] i915 0000:00:02.0: itc: No Data

<7> [419.315439] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [419.315442] i915 0000:00:02.0: quantization range: Full

<7> [419.315445] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [419.315449] i915 0000:00:02.0: video code: 0

<7> [419.315452] i915 0000:00:02.0: ycc quantization range: Full

<7> [419.315455] i915 0000:00:02.0: hdmi content type: Graphics

<7> [419.315458] i915 0000:00:02.0: pixel repeat: 0

<7> [419.315462] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [419.315466] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in spd infoframe

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

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

<7> [419.316693] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [419.316699] i915 0000:00:02.0: vendor: Intel

<7> [419.316702] i915 0000:00:02.0: product: Integrated gfx

<7> [419.316705] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [419.316709] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hdmi infoframe

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

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

<7> [419.317938] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [419.317945] i915 0000:00:02.0: empty frame

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

<7> [419.319688] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:76:pipe A] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x1

<7> [419.320323] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:34:plane 1A] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988

<7> [419.320757] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:70:cursor A] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32

<7> [419.321184] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:34:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5,*wm6,*wm7,*twm, swm, stwm

<7> [419.321598] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:34:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0

<7> [419.322002] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:34:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0

<7> [419.322436] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:34:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 17, 17, 17, 34, 34, 34, 34, 34, 31, 0, 0

<7> [419.324441] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL

<7> [419.324461] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled

<7> [419.327768] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:76:pipe A] min cdclk: 0 kHz -> 192000 kHz

<7> [419.328673] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:76:pipe A] using pre-allocated PORT PLL C

<7> [419.329171] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:76:pipe A] reserving PORT PLL C

<7> [419.329595] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:76:pipe A] enable: yes [modeset]

<7> [419.330005] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB

<7> [419.330456] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 36, dithering: 0

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

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

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

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

<7> [419.332521] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71

<7> [419.332929] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6

<7> [419.333358] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [419.333363] i915 0000:00:02.0: colorspace: RGB

<7> [419.333367] i915 0000:00:02.0: scan mode: Underscan

<7> [419.333371] i915 0000:00:02.0: colorimetry: No Data

<7> [419.333374] i915 0000:00:02.0: picture aspect: No Data

<7> [419.333377] i915 0000:00:02.0: active aspect: Same as Picture

<7> [419.333380] i915 0000:00:02.0: itc: No Data

<7> [419.333383] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [419.333387] i915 0000:00:02.0: quantization range: Full

<7> [419.333390] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [419.333393] i915 0000:00:02.0: video code: 0

<7> [419.333397] i915 0000:00:02.0: ycc quantization range: Full

<7> [419.333400] i915 0000:00:02.0: hdmi content type: Graphics

<7> [419.333403] i915 0000:00:02.0: pixel repeat: 0

<7> [419.333406] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [419.333410] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [419.333413] i915 0000:00:02.0: vendor: Intel

<7> [419.333417] i915 0000:00:02.0: product: Integrated gfx

<7> [419.333420] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [419.333424] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [419.333427] i915 0000:00:02.0: empty frame

<7> [419.333431] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 07 00 66 10 00 01 00 00 00 00 00 00 00 00

<7> [419.333839] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 05 e3 cd 0c 32 38 45 38 35 30 09 07 07 00 00 00

<7> [419.334271] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

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

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

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

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

<7> [419.336329] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9

<7> [419.336736] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9

<7> [419.337153] i915 0000:00:02.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=1083-1088 vt=1125, flags=0x9

<7> [419.337564] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x40 0x9

<7> [419.337968] i915 0000:00:02.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=1083-1088 vt=1125, flags=0x9

<7> [419.338391] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pipe src: 1920x1080+0+0, pixel rate 148500, min cdclk 192000

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

<7> [419.339211] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0

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

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

<7> [419.340445] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: ebb0: 0x6200, ebb4: 0x2000,pll0: 0x21, pll1: 0x100, pll2: 0x1a6666, pll3: 0x10000, pll6: 0x30904, pll8: 0x8, pll9: 0xa, pll10: 0x8003c00, pcsdw12: 0x4d

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

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

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

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

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

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

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

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

<7> [419.344190] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:34:plane 1A] fb: [FB:178] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes

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

<7> [419.345012] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0

<7> [419.345434] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:43:plane 2A] fb: [NOFB], visible: no

<7> [419.345841] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:52:plane 3A] fb: [NOFB], visible: no

<7> [419.346274] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:61:plane 4A] fb: [NOFB], visible: no

<7> [419.346681] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:70:cursor A] fb: [NOFB], visible: no

<7> [419.351492] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-c

<7> [419.354106] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:163:DDI B/PHY B]

<7> [419.354738] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:173:DDI C/PHY C]

<7> [419.357199] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL C (active 0x1, on? 0) for [CRTC:76:pipe A]

<7> [419.357791] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL C

<7> [419.358545] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_C

<7> [419.359067] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A

<7> [419.360204] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] reserved 16588800 bytes of contiguous stolen space for FBC, limit: 1

<7> [419.360641] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] Enabling FBC on [PLANE:34:plane 1A]

<7> [419.376816] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:174:HDMI-A-2][ENCODER:173:DDI C/PHY C] Enable audio codec on [CRTC:76:pipe A], 32 bytes ELD

<7> [419.393447] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000)

<7> [419.393964] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N

<7> [419.394745] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:174:HDMI-A-2]

<7> [419.396508] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:76:pipe A]

<6> [420.791928] [IGT] kms_flip: finished subtest A-HDMI-A2, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank-interruptible@a-hdmi-a2