igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a1 on shard-glk@CI_DRM

Detail	Value
Duration	4.20 seconds
Hostname	shard-glk9
Igt-Version	IGT-Version: 2.2-ge6fb6c83f (x86_64) (Linux: 6.18.0-CI_DRM_17615-ga8fcc7aa61a8+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A1 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 B-HDMI-A1: FAIL (4.202s)
Err	Starting dynamic subtest: B-HDMI-A1 (kms_flip:2285) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2285) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2285) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-HDMI-A1 failed. ** DEBUG (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.317001 last_received_ts = 143.316544 last_seq = 2955 current_ts = 143.333664 current_received_ts = 143.333267 current_seq = 2956 count = 96 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.333664 last_received_ts = 143.333267 last_seq = 2956 current_ts = 143.350342 current_received_ts = 143.350174 current_seq = 2957 count = 97 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 24us (kms_flip:2285) DEBUG: name = flip last_ts = 143.350342 last_received_ts = 143.350174 last_seq = 2957 current_ts = 143.367004 current_received_ts = 143.366562 current_seq = 2958 count = 98 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 20us (kms_flip:2285) DEBUG: name = flip last_ts = 143.367004 last_received_ts = 143.366562 last_seq = 2958 current_ts = 143.383667 current_received_ts = 143.383331 current_seq = 2959 count = 99 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.383667 last_received_ts = 143.383331 last_seq = 2959 current_ts = 143.400345 current_received_ts = 143.400192 current_seq = 2960 count = 100 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 143.400345 last_received_ts = 143.400192 last_seq = 2960 current_ts = 143.417007 current_received_ts = 143.416534 current_seq = 2961 count = 101 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.417007 last_received_ts = 143.416534 last_seq = 2961 current_ts = 143.433670 current_received_ts = 143.433334 current_seq = 2962 count = 102 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.433670 last_received_ts = 143.433334 last_seq = 2962 current_ts = 143.450333 current_received_ts = 143.450241 current_seq = 2963 count = 103 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 19us (kms_flip:2285) DEBUG: name = flip last_ts = 143.450333 last_received_ts = 143.450241 last_seq = 2963 current_ts = 143.466995 current_received_ts = 143.466522 current_seq = 2964 count = 104 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.466995 last_received_ts = 143.466522 last_seq = 2964 current_ts = 143.483673 current_received_ts = 143.483658 current_seq = 2965 count = 105 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 19us (kms_flip:2285) DEBUG: name = flip last_ts = 143.483673 last_received_ts = 143.483658 last_seq = 2965 current_ts = 143.500336 current_received_ts = 143.500168 current_seq = 2966 count = 106 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.500336 last_received_ts = 143.500168 last_seq = 2966 current_ts = 143.516998 current_received_ts = 143.516541 current_seq = 2967 count = 107 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.516998 last_received_ts = 143.516541 last_seq = 2967 current_ts = 143.533661 current_received_ts = 143.533325 current_seq = 2968 count = 108 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 143.533661 last_received_ts = 143.533325 last_seq = 2968 current_ts = 143.550339 current_received_ts = 143.550156 current_seq = 2969 count = 109 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 24us (kms_flip:2285) DEBUG: name = flip last_ts = 143.550339 last_received_ts = 143.550156 last_seq = 2969 current_ts = 143.567001 current_received_ts = 143.566513 current_seq = 2970 count = 110 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.567001 last_received_ts = 143.566513 last_seq = 2970 current_ts = 143.583679 current_received_ts = 143.583344 current_seq = 2971 count = 111 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.583679 last_received_ts = 143.583344 last_seq = 2971 current_ts = 143.600342 current_received_ts = 143.600250 current_seq = 2972 count = 112 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 19us (kms_flip:2285) DEBUG: name = flip last_ts = 143.600342 last_received_ts = 143.600250 last_seq = 2972 current_ts = 143.617004 current_received_ts = 143.616577 current_seq = 2973 count = 113 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 143.617004 last_received_ts = 143.616577 last_seq = 2973 current_ts = 143.633667 current_received_ts = 143.633530 current_seq = 2974 count = 114 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 24us (kms_flip:2285) DEBUG: name = flip last_ts = 143.633667 last_received_ts = 143.633530 last_seq = 2974 current_ts = 143.650345 current_received_ts = 143.649887 current_seq = 2975 count = 115 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.650345 last_received_ts = 143.649887 last_seq = 2975 current_ts = 143.667007 current_received_ts = 143.666656 current_seq = 2976 count = 116 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.667007 last_received_ts = 143.666656 last_seq = 2976 current_ts = 143.683670 current_received_ts = 143.684113 current_seq = 2977 count = 117 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 20us (kms_flip:2285) DEBUG: name = flip last_ts = 143.683670 last_received_ts = 143.684113 last_seq = 2977 current_ts = 143.700348 current_received_ts = 143.700180 current_seq = 2978 count = 118 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 26us (kms_flip:2285) DEBUG: name = flip last_ts = 143.700348 last_received_ts = 143.700180 last_seq = 2978 current_ts = 143.717010 current_received_ts = 143.716537 current_seq = 2979 count = 119 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.717010 last_received_ts = 143.716537 last_seq = 2979 current_ts = 143.733673 current_received_ts = 143.733643 current_seq = 2980 count = 120 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 20us (kms_flip:2285) DEBUG: name = flip last_ts = 143.733673 last_received_ts = 143.733643 last_seq = 2980 current_ts = 143.750336 current_received_ts = 143.750183 current_seq = 2981 count = 121 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.750336 last_received_ts = 143.750183 last_seq = 2981 current_ts = 143.766998 current_received_ts = 143.766891 current_seq = 2982 count = 122 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.766998 last_received_ts = 143.766891 last_seq = 2982 current_ts = 143.783676 current_received_ts = 143.783478 current_seq = 2983 count = 123 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.783676 last_received_ts = 143.783478 last_seq = 2983 current_ts = 143.800339 current_received_ts = 143.800278 current_seq = 2984 count = 124 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.800339 last_received_ts = 143.800278 last_seq = 2984 current_ts = 143.817001 current_received_ts = 143.816559 current_seq = 2985 count = 125 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.817001 last_received_ts = 143.816559 last_seq = 2985 current_ts = 143.833664 current_received_ts = 143.833527 current_seq = 2986 count = 126 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.833664 last_received_ts = 143.833527 last_seq = 2986 current_ts = 143.850342 current_received_ts = 143.850220 current_seq = 2987 count = 127 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.850342 last_received_ts = 143.850220 last_seq = 2987 current_ts = 143.867004 current_received_ts = 143.866821 current_seq = 2988 count = 128 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.867004 last_received_ts = 143.866821 last_seq = 2988 current_ts = 143.883667 current_received_ts = 143.883209 current_seq = 2989 count = 129 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.883667 last_received_ts = 143.883209 last_seq = 2989 current_ts = 143.900345 current_received_ts = 143.900284 current_seq = 2990 count = 130 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.900345 last_received_ts = 143.900284 last_seq = 2990 current_ts = 143.917007 current_received_ts = 143.916656 current_seq = 2991 count = 131 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.917007 last_received_ts = 143.916656 last_seq = 2991 current_ts = 143.933670 current_received_ts = 143.933502 current_seq = 2992 count = 132 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.933670 last_received_ts = 143.933502 last_seq = 2992 current_ts = 143.950333 current_received_ts = 143.950195 current_seq = 2993 count = 133 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.950333 last_received_ts = 143.950195 last_seq = 2993 current_ts = 143.967010 current_received_ts = 143.966888 current_seq = 2994 count = 134 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 143.967010 last_received_ts = 143.966888 last_seq = 2994 current_ts = 143.983673 current_received_ts = 143.983414 current_seq = 2995 count = 135 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 143.983673 last_received_ts = 143.983414 last_seq = 2995 current_ts = 144.000336 current_received_ts = 144.000244 current_seq = 2996 count = 136 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.000336 last_received_ts = 144.000244 last_seq = 2996 current_ts = 144.017014 current_received_ts = 144.016632 current_seq = 2997 count = 137 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.017014 last_received_ts = 144.016632 last_seq = 2997 current_ts = 144.033676 current_received_ts = 144.033493 current_seq = 2998 count = 138 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.033676 last_received_ts = 144.033493 last_seq = 2998 current_ts = 144.050339 current_received_ts = 144.050217 current_seq = 2999 count = 139 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.050339 last_received_ts = 144.050217 last_seq = 2999 current_ts = 144.067001 current_received_ts = 144.066513 current_seq = 3000 count = 140 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.067001 last_received_ts = 144.066513 last_seq = 3000 current_ts = 144.083679 current_received_ts = 144.083618 current_seq = 3001 count = 141 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.083679 last_received_ts = 144.083618 last_seq = 3001 current_ts = 144.100342 current_received_ts = 144.100357 current_seq = 3002 count = 142 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 20us (kms_flip:2285) DEBUG: name = flip last_ts = 144.100342 last_received_ts = 144.100357 last_seq = 3002 current_ts = 144.117004 current_received_ts = 144.116898 current_seq = 3003 count = 143 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.117004 last_received_ts = 144.116898 last_seq = 3003 current_ts = 144.133667 current_received_ts = 144.133514 current_seq = 3004 count = 144 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.133667 last_received_ts = 144.133514 last_seq = 3004 current_ts = 144.150330 current_received_ts = 144.150284 current_seq = 3005 count = 145 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 35us (kms_flip:2285) DEBUG: name = flip last_ts = 144.150330 last_received_ts = 144.150284 last_seq = 3005 current_ts = 144.167007 current_received_ts = 144.166580 current_seq = 3006 count = 146 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.167007 last_received_ts = 144.166580 last_seq = 3006 current_ts = 144.183670 current_received_ts = 144.183517 current_seq = 3007 count = 147 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.183670 last_received_ts = 144.183517 last_seq = 3007 current_ts = 144.200333 current_received_ts = 144.199875 current_seq = 3008 count = 148 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.200333 last_received_ts = 144.199875 last_seq = 3008 current_ts = 144.217010 current_received_ts = 144.216675 current_seq = 3009 count = 149 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.217010 last_received_ts = 144.216675 last_seq = 3009 current_ts = 144.233673 current_received_ts = 144.233246 current_seq = 3010 count = 150 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 24us (kms_flip:2285) DEBUG: name = flip last_ts = 144.233673 last_received_ts = 144.233246 last_seq = 3010 current_ts = 144.250336 current_received_ts = 144.250168 current_seq = 3011 count = 151 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.250336 last_received_ts = 144.250168 last_seq = 3011 current_ts = 144.266998 current_received_ts = 144.266556 current_seq = 3012 count = 152 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.266998 last_received_ts = 144.266556 last_seq = 3012 current_ts = 144.283676 current_received_ts = 144.283737 current_seq = 3013 count = 153 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 20us (kms_flip:2285) DEBUG: name = flip last_ts = 144.283676 last_received_ts = 144.283737 last_seq = 3013 current_ts = 144.300339 current_received_ts = 144.300186 current_seq = 3014 count = 154 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.300339 last_received_ts = 144.300186 last_seq = 3014 current_ts = 144.317001 current_received_ts = 144.316528 current_seq = 3015 count = 155 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.317001 last_received_ts = 144.316528 last_seq = 3015 current_ts = 144.333664 current_received_ts = 144.333344 current_seq = 3016 count = 156 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.333664 last_received_ts = 144.333344 last_seq = 3016 current_ts = 144.350342 current_received_ts = 144.350143 current_seq = 3017 count = 157 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 24us (kms_flip:2285) DEBUG: name = flip last_ts = 144.350342 last_received_ts = 144.350143 last_seq = 3017 current_ts = 144.367004 current_received_ts = 144.366821 current_seq = 3018 count = 158 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.367004 last_received_ts = 144.366821 last_seq = 3018 current_ts = 144.383667 current_received_ts = 144.383453 current_seq = 3019 count = 159 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.383667 last_received_ts = 144.383453 last_seq = 3019 current_ts = 144.400345 current_received_ts = 144.400314 current_seq = 3020 count = 160 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.400345 last_received_ts = 144.400314 last_seq = 3020 current_ts = 144.417007 current_received_ts = 144.416550 current_seq = 3021 count = 161 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.417007 last_received_ts = 144.416550 last_seq = 3021 current_ts = 144.433670 current_received_ts = 144.433487 current_seq = 3022 count = 162 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.433670 last_received_ts = 144.433487 last_seq = 3022 current_ts = 144.450333 current_received_ts = 144.450211 current_seq = 3023 count = 163 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.450333 last_received_ts = 144.450211 last_seq = 3023 current_ts = 144.467010 current_received_ts = 144.466873 current_seq = 3024 count = 164 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.467010 last_received_ts = 144.466873 last_seq = 3024 current_ts = 144.483673 current_received_ts = 144.483582 current_seq = 3025 count = 165 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.483673 last_received_ts = 144.483582 last_seq = 3025 current_ts = 144.500336 current_received_ts = 144.500137 current_seq = 3026 count = 166 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 24us (kms_flip:2285) DEBUG: name = flip last_ts = 144.500336 last_received_ts = 144.500137 last_seq = 3026 current_ts = 144.517014 current_received_ts = 144.516541 current_seq = 3027 count = 167 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.517014 last_received_ts = 144.516541 last_seq = 3027 current_ts = 144.533676 current_received_ts = 144.533340 current_seq = 3028 count = 168 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.533676 last_received_ts = 144.533340 last_seq = 3028 current_ts = 144.550339 current_received_ts = 144.550140 current_seq = 3029 count = 169 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 24us (kms_flip:2285) DEBUG: name = flip last_ts = 144.550339 last_received_ts = 144.550140 last_seq = 3029 current_ts = 144.567001 current_received_ts = 144.566559 current_seq = 3030 count = 170 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.567001 last_received_ts = 144.566559 last_seq = 3030 current_ts = 144.583679 current_received_ts = 144.583344 current_seq = 3031 count = 171 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.583679 last_received_ts = 144.583344 last_seq = 3031 current_ts = 144.600327 current_received_ts = 144.600143 current_seq = 3032 count = 172 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.600327 last_received_ts = 144.600143 last_seq = 3032 current_ts = 144.617004 current_received_ts = 144.616531 current_seq = 3033 count = 173 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.617004 last_received_ts = 144.616531 last_seq = 3033 current_ts = 144.633667 current_received_ts = 144.633347 current_seq = 3034 count = 174 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.633667 last_received_ts = 144.633347 last_seq = 3034 current_ts = 144.650345 current_received_ts = 144.650253 current_seq = 3035 count = 175 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 20us (kms_flip:2285) DEBUG: name = flip last_ts = 144.650345 last_received_ts = 144.650253 last_seq = 3035 current_ts = 144.667007 current_received_ts = 144.666565 current_seq = 3036 count = 176 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.667007 last_received_ts = 144.666565 last_seq = 3036 current_ts = 144.683670 current_received_ts = 144.683365 current_seq = 3037 count = 177 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.683670 last_received_ts = 144.683365 last_seq = 3037 current_ts = 144.700348 current_received_ts = 144.700256 current_seq = 3038 count = 178 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.700348 last_received_ts = 144.700256 last_seq = 3038 current_ts = 144.717010 current_received_ts = 144.716537 current_seq = 3039 count = 179 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 19us (kms_flip:2285) DEBUG: name = flip last_ts = 144.717010 last_received_ts = 144.716537 last_seq = 3039 current_ts = 144.733673 current_received_ts = 144.733551 current_seq = 3040 count = 180 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.733673 last_received_ts = 144.733551 last_seq = 3040 current_ts = 144.750351 current_received_ts = 144.750336 current_seq = 3041 count = 181 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.750351 last_received_ts = 144.750336 last_seq = 3041 current_ts = 144.766998 current_received_ts = 144.766556 current_seq = 3042 count = 182 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.766998 last_received_ts = 144.766556 last_seq = 3042 current_ts = 144.783676 current_received_ts = 144.783524 current_seq = 3043 count = 183 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.783676 last_received_ts = 144.783524 last_seq = 3043 current_ts = 144.800339 current_received_ts = 144.799850 current_seq = 3044 count = 184 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.800339 last_received_ts = 144.799850 last_seq = 3044 current_ts = 144.817017 current_received_ts = 144.816757 current_seq = 3045 count = 185 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 20us (kms_flip:2285) DEBUG: name = flip last_ts = 144.817017 last_received_ts = 144.816757 last_seq = 3045 current_ts = 144.833679 current_received_ts = 144.833496 current_seq = 3046 count = 186 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 20us (kms_flip:2285) DEBUG: name = flip last_ts = 144.833679 last_received_ts = 144.833496 last_seq = 3046 current_ts = 144.850342 current_received_ts = 144.850174 current_seq = 3047 count = 187 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.850342 last_received_ts = 144.850174 last_seq = 3047 current_ts = 144.867004 current_received_ts = 144.866516 current_seq = 3048 count = 188 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 144.867004 last_received_ts = 144.866516 last_seq = 3048 current_ts = 144.883682 current_received_ts = 144.883484 current_seq = 3049 count = 189 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.883682 last_received_ts = 144.883484 last_seq = 3049 current_ts = 144.900345 current_received_ts = 144.900330 current_seq = 3050 count = 190 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 144.900345 last_received_ts = 144.900330 last_seq = 3050 current_ts = 144.917007 current_received_ts = 144.916550 current_seq = 3051 count = 191 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.917007 last_received_ts = 144.916550 last_seq = 3051 current_ts = 144.933670 current_received_ts = 144.933456 current_seq = 3052 count = 192 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 24us (kms_flip:2285) DEBUG: name = flip last_ts = 144.933670 last_received_ts = 144.933456 last_seq = 3052 current_ts = 144.950333 current_received_ts = 144.950180 current_seq = 3053 count = 193 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.950333 last_received_ts = 144.950180 last_seq = 3053 current_ts = 144.967010 current_received_ts = 144.966507 current_seq = 3054 count = 194 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 144.967010 last_received_ts = 144.966507 last_seq = 3054 current_ts = 144.983673 current_received_ts = 144.983704 current_seq = 3055 count = 195 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 20us (kms_flip:2285) DEBUG: name = flip last_ts = 144.983673 last_received_ts = 144.983704 last_seq = 3055 current_ts = 145.000336 current_received_ts = 145.000153 current_seq = 3056 count = 196 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 145.000336 last_received_ts = 145.000153 last_seq = 3056 current_ts = 145.017014 current_received_ts = 145.016556 current_seq = 3057 count = 197 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 145.017014 last_received_ts = 145.016556 last_seq = 3057 current_ts = 145.033676 current_received_ts = 145.033661 current_seq = 3058 count = 198 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 145.033676 last_received_ts = 145.033661 last_seq = 3058 current_ts = 145.050339 current_received_ts = 145.050278 current_seq = 3059 count = 199 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 145.050339 last_received_ts = 145.050278 last_seq = 3059 current_ts = 145.067017 current_received_ts = 145.066559 current_seq = 3060 count = 200 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 145.067017 last_received_ts = 145.066559 last_seq = 3060 current_ts = 145.083664 current_received_ts = 145.083282 current_seq = 3061 count = 201 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 48us (kms_flip:2285) DEBUG: name = flip last_ts = 145.083664 last_received_ts = 145.083282 last_seq = 3061 current_ts = 145.100327 current_received_ts = 145.100433 current_seq = 3062 count = 202 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 145.100327 last_received_ts = 145.100433 last_seq = 3062 current_ts = 145.117004 current_received_ts = 145.116577 current_seq = 3063 count = 203 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 145.117004 last_received_ts = 145.116577 last_seq = 3063 current_ts = 145.133667 current_received_ts = 145.133499 current_seq = 3064 count = 204 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 145.133667 last_received_ts = 145.133499 last_seq = 3064 current_ts = 145.150330 current_received_ts = 145.150162 current_seq = 3065 count = 205 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 24us (kms_flip:2285) DEBUG: name = flip last_ts = 145.150330 last_received_ts = 145.150162 last_seq = 3065 current_ts = 145.167007 current_received_ts = 145.166534 current_seq = 3066 count = 206 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 145.167007 last_received_ts = 145.166534 last_seq = 3066 current_ts = 145.183670 current_received_ts = 145.183670 current_seq = 3067 count = 207 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 145.183670 last_received_ts = 145.183670 last_seq = 3067 current_ts = 145.200333 current_received_ts = 145.200180 current_seq = 3068 count = 208 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 145.200333 last_received_ts = 145.200180 last_seq = 3068 current_ts = 145.216995 current_received_ts = 145.216537 current_seq = 3069 count = 209 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 145.216995 last_received_ts = 145.216537 last_seq = 3069 current_ts = 145.233673 current_received_ts = 145.233521 current_seq = 3070 count = 210 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 145.233673 last_received_ts = 145.233521 last_seq = 3070 current_ts = 145.250336 current_received_ts = 145.250351 current_seq = 3071 count = 211 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 145.250336 last_received_ts = 145.250351 last_seq = 3071 current_ts = 145.267014 current_received_ts = 145.266907 current_seq = 3072 count = 212 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 23us (kms_flip:2285) DEBUG: name = flip last_ts = 145.267014 last_received_ts = 145.266907 last_seq = 3072 current_ts = 145.283676 current_received_ts = 145.283798 current_seq = 3073 count = 213 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 22us (kms_flip:2285) DEBUG: name = flip last_ts = 145.283676 last_received_ts = 145.283798 last_seq = 3073 current_ts = 145.300339 current_received_ts = 145.300186 current_seq = 3074 count = 214 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 21us (kms_flip:2285) DEBUG: name = flip last_ts = 145.300339 last_received_ts = 145.300186 last_seq = 3074 current_ts = 145.317017 current_received_ts = 145.316696 current_seq = 3075 count = 215 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 16us (kms_flip:2285) DEBUG: name = flip last_ts = 145.317017 last_received_ts = 145.316696 last_seq = 3075 current_ts = 145.333679 current_received_ts = 145.333145 current_seq = 3076 count = 216 seq_step = 1 (kms_flip:2285) DEBUG: Vblank took 920us (kms_flip:2285) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2285) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2285) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:2285) igt_core-INFO: Stack trace: (kms_flip:2285) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2285) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:2285) igt_core-INFO: #2 ../tests/kms_flip.c:1889 run_test() (kms_flip:2285) igt_core-INFO: #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045() (kms_flip:2285) igt_core-INFO: #4 ../tests/kms_flip.c:2045 main() (kms_flip:2285) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2285) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2285) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A1: FAIL (4.202s)
Dmesg	<6> [141.391462] [IGT] kms_flip: starting dynamic subtest B-HDMI-A1 <7> [141.393238] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:178] <7> [141.393596] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:180] <7> [141.429014] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:76:pipe A] <7> [141.429439] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [141.429973] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [141.430434] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [141.430862] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [141.431298] 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 0x0000000d, found 0x00000000) <7> [141.431705] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [141.432160] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [141.432566] 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 1920, found 0) <7> [141.432969] 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 2200, found 0) <7> [141.433390] 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 1920, found 0) <7> [141.433794] 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 2200, found 0) <7> [141.434226] 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 2008, found 0) <7> [141.434630] 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 2052, found 0) <7> [141.435066] 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 1080, found 0) <7> [141.435492] 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 1080, found 0) <7> [141.435895] 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 1083, found 0) <7> [141.436323] 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 1088, found 0) <7> [141.436728] 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 1125, found 0) <7> [141.437153] 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 1125, found 0) <7> [141.437556] 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 1920, found 0) <7> [141.437958] 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 2200, found 0) <7> [141.438377] 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 1920, found 0) <7> [141.438784] 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 2200, found 0) <7> [141.439216] 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 2008, found 0) <7> [141.439617] 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 2052, found 0) <7> [141.440020] 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 1080, found 0) <7> [141.440439] 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 1080, found 0) <7> [141.440840] 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 1083, found 0) <7> [141.441266] 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 1088, found 0) <7> [141.441670] 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 1125, found 0) <7> [141.442074] 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 1125, found 0) <7> [141.442492] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [141.442897] 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 1, found 0) <7> [141.443321] 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 8, found 0) <7> [141.443724] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [141.444152] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in has_infoframe (expected yes, found no) <7> [141.444566] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [141.444969] 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 148500, found 0) <7> [141.445392] 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 148500, found 0) <7> [141.445796] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in port_clock (expected 222750, found 0) <7> [141.446214] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [141.446618] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000) <7> [141.447020] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in avi infoframe <7> [141.447449] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [141.447850] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [141.447855] i915 0000:00:02.0: colorspace: RGB <7> [141.447858] i915 0000:00:02.0: scan mode: Underscan <7> [141.447862] i915 0000:00:02.0: colorimetry: No Data <7> [141.447866] i915 0000:00:02.0: picture aspect: No Data <7> [141.447869] i915 0000:00:02.0: active aspect: Same as Picture <7> [141.447873] i915 0000:00:02.0: itc: No Data <7> [141.447876] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [141.447879] i915 0000:00:02.0: quantization range: Full <7> [141.447883] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [141.447886] i915 0000:00:02.0: video code: 0 <7> [141.447889] i915 0000:00:02.0: ycc quantization range: Full <7> [141.447892] i915 0000:00:02.0: hdmi content type: Graphics <7> [141.447896] i915 0000:00:02.0: pixel repeat: 0 <7> [141.447899] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [141.447903] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [141.448320] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in spd infoframe <7> [141.448724] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [141.449148] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [141.449152] i915 0000:00:02.0: vendor: Intel <7> [141.449156] i915 0000:00:02.0: product: Integrated gfx <7> [141.449159] i915 0000:00:02.0: source device information: PC General (0x9) <7> [141.449163] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [141.449567] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:76:pipe A] fastset requirement not met in hdmi infoframe <7> [141.449969] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [141.450387] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [141.450392] i915 0000:00:02.0: empty frame <7> [141.450396] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [141.450799] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:76:pipe A] fastset requirement not met, forcing full modeset <7> [141.451233] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:76:pipe A] releasing PORT PLL B <7> [141.452315] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:76:pipe A] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [141.452802] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:70:cursor A] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0 <7> [141.453472] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:76:pipe A] min cdclk: 192000 kHz -> 0 kHz <7> [141.453939] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [141.454360] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz <7> [141.454761] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4 <7> [141.455184] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:76:pipe A] enable: no [modeset] <7> [141.455591] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:34:plane 1A] fb: [NOFB], visible: no <7> [141.455991] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:43:plane 2A] fb: [NOFB], visible: no <7> [141.456418] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:52:plane 3A] fb: [NOFB], visible: no <7> [141.456820] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:61:plane 4A] fb: [NOFB], visible: no <7> [141.457237] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:70:cursor A] fb: [NOFB], visible: no <7> [141.458042] 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:76:pipe A] <7> [141.486608] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [141.487629] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [141.499645] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10 <7> [141.504202] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time <7> [141.612470] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [141.613729] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x1, on? 1) for [CRTC:76:pipe A] <7> [141.616052] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL B <7> [141.616835] 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> [141.617318] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:163:DDI B/PHY B] <7> [141.617764] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:173:DDI C/PHY C] <7> [141.618179] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:164:HDMI-A-1] <7> [141.619195] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-b <7> [141.619676] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:76:pipe A] <7> [141.621054] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [141.621534] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz <7> [141.621937] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13 <7> [141.622680] 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> [141.624480] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:119:pipe B] <7> [141.624836] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:162:pipe C] <7> [141.625403] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:119:pipe B] <7> [141.625463] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:164:HDMI-A-1] <7> [141.625635] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 12 bpc for HDMI output (pipe bpp: 36) <7> [141.626183] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:119:pipe B] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [141.626589] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:163:DDI B/PHY B] [CRTC:119:pipe B] <7> [141.626986] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [141.627408] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [141.627809] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [141.628226] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [141.628626] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d) <7> [141.629031] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [141.629444] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [141.629846] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [141.630260] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [141.630662] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [141.631064] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [141.631476] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [141.631877] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [141.632290] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [141.632695] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [141.633096] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [141.633510] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [141.633913] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [141.634322] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [141.634723] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [141.635139] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [141.635540] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [141.635941] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [141.636361] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [141.636762] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [141.637176] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [141.637577] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [141.637980] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [141.638397] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [141.638803] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [141.639217] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [141.639623] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [141.640025] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [141.640441] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [141.640842] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [141.641253] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in has_infoframe (expected no, found yes) <7> [141.641657] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [141.642060] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [141.642473] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [141.642874] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in port_clock (expected 0, found 222750) <7> [141.643288] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [141.643690] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006) <7> [141.644091] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in avi infoframe <7> [141.644501] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [141.644901] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [141.645332] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [141.645337] i915 0000:00:02.0: colorspace: RGB <7> [141.645341] i915 0000:00:02.0: scan mode: Underscan <7> [141.645345] i915 0000:00:02.0: colorimetry: No Data <7> [141.645348] i915 0000:00:02.0: picture aspect: No Data <7> [141.645351] i915 0000:00:02.0: active aspect: Same as Picture <7> [141.645355] i915 0000:00:02.0: itc: No Data <7> [141.645358] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [141.645361] i915 0000:00:02.0: quantization range: Full <7> [141.645365] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [141.645368] i915 0000:00:02.0: video code: 0 <7> [141.645371] i915 0000:00:02.0: ycc quantization range: Full <7> [141.645374] i915 0000:00:02.0: hdmi content type: Graphics <7> [141.645378] i915 0000:00:02.0: pixel repeat: 0 <7> [141.645381] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [141.645385] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in spd infoframe <7> [141.645787] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [141.646223] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [141.646624] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [141.646628] i915 0000:00:02.0: vendor: Intel <7> [141.646632] i915 0000:00:02.0: product: Integrated gfx <7> [141.646635] i915 0000:00:02.0: source device information: PC General (0x9) <7> [141.646640] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hdmi infoframe <7> [141.647038] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [141.647478] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [141.647878] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [141.647885] i915 0000:00:02.0: empty frame <7> [141.647890] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:119:pipe B] fastset requirement not met, forcing full modeset <7> [141.648687] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:119:pipe B] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x2 <7> [141.649329] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:plane 1B] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988 <7> [141.649729] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:113:cursor B] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32 <7> [141.650150] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:77:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,*twm, swm, stwm <7> [141.650546] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:77:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0 <7> [141.650942] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:77:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0 <7> [141.651371] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:77:plane 1B] 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> [141.651962] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:119:pipe B] min cdclk: 0 kHz -> 192000 kHz <7> [141.652437] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:119:pipe B] using pre-allocated PORT PLL B <7> [141.652844] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:119:pipe B] reserving PORT PLL B <7> [141.653279] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:119:pipe B] enable: yes [modeset] <7> [141.653686] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [141.654090] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 36, dithering: 0 <7> [141.654525] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [141.654926] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [141.655352] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [141.655753] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [141.656182] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [141.656585] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6 <7> [141.656987] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [141.656992] i915 0000:00:02.0: colorspace: RGB <7> [141.656995] i915 0000:00:02.0: scan mode: Underscan <7> [141.656999] i915 0000:00:02.0: colorimetry: No Data <7> [141.657002] i915 0000:00:02.0: picture aspect: No Data <7> [141.657006] i915 0000:00:02.0: active aspect: Same as Picture <7> [141.657009] i915 0000:00:02.0: itc: No Data <7> [141.657012] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [141.657016] i915 0000:00:02.0: quantization range: Full <7> [141.657019] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [141.657022] i915 0000:00:02.0: video code: 0 <7> [141.657026] i915 0000:00:02.0: ycc quantization range: Full <7> [141.657029] i915 0000:00:02.0: hdmi content type: Graphics <7> [141.657032] i915 0000:00:02.0: pixel repeat: 0 <7> [141.657035] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [141.657040] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [141.657043] i915 0000:00:02.0: vendor: Intel <7> [141.657046] i915 0000:00:02.0: product: Integrated gfx <7> [141.657050] i915 0000:00:02.0: source device information: PC General (0x9) <7> [141.657054] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [141.657058] i915 0000:00:02.0: empty frame <7> [141.657061] 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> [141.657492] 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> [141.657894] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [141.658315] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [141.658719] 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> [141.659148] 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> [141.659551] 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> [141.659953] 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> [141.660375] 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> [141.660781] 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> [141.661212] 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> [141.661615] 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> [141.662018] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [141.662438] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [141.662840] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [141.663268] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [141.663672] 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> [141.664077] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [141.664497] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [141.664901] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [141.665331] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [141.665731] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [141.666152] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [141.666552] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [141.666953] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [141.667385] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:77:plane 1B] fb: [FB:178] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [141.667791] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [141.668234] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [141.668637] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:86:plane 2B] fb: [NOFB], visible: no <7> [141.669039] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:95:plane 3B] fb: [NOFB], visible: no <7> [141.669474] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:104:plane 4B] fb: [NOFB], visible: no <7> [141.669874] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:113:cursor B] fb: [NOFB], visible: no <7> [141.671403] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-b <7> [141.672923] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:163:DDI B/PHY B] <7> [141.673464] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:173:DDI C/PHY C] <7> [141.674094] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL B (active 0x2, on? 0) for [CRTC:119:pipe B] <7> [141.674555] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL B <7> [141.677126] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B <7> [141.677778] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [141.696175] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:164:HDMI-A-1][ENCODER:163:DDI B/PHY B] Enable audio codec on [CRTC:119:pipe B], 32 bytes ELD <7> [141.712858] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000) <7> [141.713374] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <7> [141.713953] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:164:HDMI-A-1] <7> [141.715308] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:119:pipe B] <6> [145.595880] [IGT] kms_flip: finished subtest B-HDMI-A1, FAIL

Detail

Value

Duration

4.20 seconds

Hostname

shard-glk9

Igt-Version

IGT-Version: 2.2-ge6fb6c83f (x86_64) (Linux: 6.18.0-CI_DRM_17615-ga8fcc7aa61a8+ x86_64)

Out

Starting dynamic subtest: B-HDMI-A1
  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 B-HDMI-A1: FAIL (4.202s)

Err

Starting dynamic subtest: B-HDMI-A1
(kms_flip:2285) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2285) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2285) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.317001
last_received_ts = 143.316544
last_seq = 2955
current_ts = 143.333664
current_received_ts = 143.333267
current_seq = 2956
count = 96
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.333664
last_received_ts = 143.333267
last_seq = 2956
current_ts = 143.350342
current_received_ts = 143.350174
current_seq = 2957
count = 97
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 24us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.350342
last_received_ts = 143.350174
last_seq = 2957
current_ts = 143.367004
current_received_ts = 143.366562
current_seq = 2958
count = 98
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 20us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.367004
last_received_ts = 143.366562
last_seq = 2958
current_ts = 143.383667
current_received_ts = 143.383331
current_seq = 2959
count = 99
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.383667
last_received_ts = 143.383331
last_seq = 2959
current_ts = 143.400345
current_received_ts = 143.400192
current_seq = 2960
count = 100
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.400345
last_received_ts = 143.400192
last_seq = 2960
current_ts = 143.417007
current_received_ts = 143.416534
current_seq = 2961
count = 101
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.417007
last_received_ts = 143.416534
last_seq = 2961
current_ts = 143.433670
current_received_ts = 143.433334
current_seq = 2962
count = 102
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.433670
last_received_ts = 143.433334
last_seq = 2962
current_ts = 143.450333
current_received_ts = 143.450241
current_seq = 2963
count = 103
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 19us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.450333
last_received_ts = 143.450241
last_seq = 2963
current_ts = 143.466995
current_received_ts = 143.466522
current_seq = 2964
count = 104
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.466995
last_received_ts = 143.466522
last_seq = 2964
current_ts = 143.483673
current_received_ts = 143.483658
current_seq = 2965
count = 105
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 19us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.483673
last_received_ts = 143.483658
last_seq = 2965
current_ts = 143.500336
current_received_ts = 143.500168
current_seq = 2966
count = 106
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.500336
last_received_ts = 143.500168
last_seq = 2966
current_ts = 143.516998
current_received_ts = 143.516541
current_seq = 2967
count = 107
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.516998
last_received_ts = 143.516541
last_seq = 2967
current_ts = 143.533661
current_received_ts = 143.533325
current_seq = 2968
count = 108
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.533661
last_received_ts = 143.533325
last_seq = 2968
current_ts = 143.550339
current_received_ts = 143.550156
current_seq = 2969
count = 109
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 24us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.550339
last_received_ts = 143.550156
last_seq = 2969
current_ts = 143.567001
current_received_ts = 143.566513
current_seq = 2970
count = 110
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.567001
last_received_ts = 143.566513
last_seq = 2970
current_ts = 143.583679
current_received_ts = 143.583344
current_seq = 2971
count = 111
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.583679
last_received_ts = 143.583344
last_seq = 2971
current_ts = 143.600342
current_received_ts = 143.600250
current_seq = 2972
count = 112
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 19us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.600342
last_received_ts = 143.600250
last_seq = 2972
current_ts = 143.617004
current_received_ts = 143.616577
current_seq = 2973
count = 113
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.617004
last_received_ts = 143.616577
last_seq = 2973
current_ts = 143.633667
current_received_ts = 143.633530
current_seq = 2974
count = 114
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 24us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.633667
last_received_ts = 143.633530
last_seq = 2974
current_ts = 143.650345
current_received_ts = 143.649887
current_seq = 2975
count = 115
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.650345
last_received_ts = 143.649887
last_seq = 2975
current_ts = 143.667007
current_received_ts = 143.666656
current_seq = 2976
count = 116
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.667007
last_received_ts = 143.666656
last_seq = 2976
current_ts = 143.683670
current_received_ts = 143.684113
current_seq = 2977
count = 117
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 20us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.683670
last_received_ts = 143.684113
last_seq = 2977
current_ts = 143.700348
current_received_ts = 143.700180
current_seq = 2978
count = 118
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 26us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.700348
last_received_ts = 143.700180
last_seq = 2978
current_ts = 143.717010
current_received_ts = 143.716537
current_seq = 2979
count = 119
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.717010
last_received_ts = 143.716537
last_seq = 2979
current_ts = 143.733673
current_received_ts = 143.733643
current_seq = 2980
count = 120
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 20us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.733673
last_received_ts = 143.733643
last_seq = 2980
current_ts = 143.750336
current_received_ts = 143.750183
current_seq = 2981
count = 121
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.750336
last_received_ts = 143.750183
last_seq = 2981
current_ts = 143.766998
current_received_ts = 143.766891
current_seq = 2982
count = 122
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.766998
last_received_ts = 143.766891
last_seq = 2982
current_ts = 143.783676
current_received_ts = 143.783478
current_seq = 2983
count = 123
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.783676
last_received_ts = 143.783478
last_seq = 2983
current_ts = 143.800339
current_received_ts = 143.800278
current_seq = 2984
count = 124
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.800339
last_received_ts = 143.800278
last_seq = 2984
current_ts = 143.817001
current_received_ts = 143.816559
current_seq = 2985
count = 125
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.817001
last_received_ts = 143.816559
last_seq = 2985
current_ts = 143.833664
current_received_ts = 143.833527
current_seq = 2986
count = 126
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.833664
last_received_ts = 143.833527
last_seq = 2986
current_ts = 143.850342
current_received_ts = 143.850220
current_seq = 2987
count = 127
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.850342
last_received_ts = 143.850220
last_seq = 2987
current_ts = 143.867004
current_received_ts = 143.866821
current_seq = 2988
count = 128
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.867004
last_received_ts = 143.866821
last_seq = 2988
current_ts = 143.883667
current_received_ts = 143.883209
current_seq = 2989
count = 129
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.883667
last_received_ts = 143.883209
last_seq = 2989
current_ts = 143.900345
current_received_ts = 143.900284
current_seq = 2990
count = 130
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.900345
last_received_ts = 143.900284
last_seq = 2990
current_ts = 143.917007
current_received_ts = 143.916656
current_seq = 2991
count = 131
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.917007
last_received_ts = 143.916656
last_seq = 2991
current_ts = 143.933670
current_received_ts = 143.933502
current_seq = 2992
count = 132
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.933670
last_received_ts = 143.933502
last_seq = 2992
current_ts = 143.950333
current_received_ts = 143.950195
current_seq = 2993
count = 133
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.950333
last_received_ts = 143.950195
last_seq = 2993
current_ts = 143.967010
current_received_ts = 143.966888
current_seq = 2994
count = 134
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.967010
last_received_ts = 143.966888
last_seq = 2994
current_ts = 143.983673
current_received_ts = 143.983414
current_seq = 2995
count = 135
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 143.983673
last_received_ts = 143.983414
last_seq = 2995
current_ts = 144.000336
current_received_ts = 144.000244
current_seq = 2996
count = 136
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.000336
last_received_ts = 144.000244
last_seq = 2996
current_ts = 144.017014
current_received_ts = 144.016632
current_seq = 2997
count = 137
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.017014
last_received_ts = 144.016632
last_seq = 2997
current_ts = 144.033676
current_received_ts = 144.033493
current_seq = 2998
count = 138
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.033676
last_received_ts = 144.033493
last_seq = 2998
current_ts = 144.050339
current_received_ts = 144.050217
current_seq = 2999
count = 139
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.050339
last_received_ts = 144.050217
last_seq = 2999
current_ts = 144.067001
current_received_ts = 144.066513
current_seq = 3000
count = 140
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.067001
last_received_ts = 144.066513
last_seq = 3000
current_ts = 144.083679
current_received_ts = 144.083618
current_seq = 3001
count = 141
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.083679
last_received_ts = 144.083618
last_seq = 3001
current_ts = 144.100342
current_received_ts = 144.100357
current_seq = 3002
count = 142
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 20us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.100342
last_received_ts = 144.100357
last_seq = 3002
current_ts = 144.117004
current_received_ts = 144.116898
current_seq = 3003
count = 143
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.117004
last_received_ts = 144.116898
last_seq = 3003
current_ts = 144.133667
current_received_ts = 144.133514
current_seq = 3004
count = 144
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.133667
last_received_ts = 144.133514
last_seq = 3004
current_ts = 144.150330
current_received_ts = 144.150284
current_seq = 3005
count = 145
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 35us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.150330
last_received_ts = 144.150284
last_seq = 3005
current_ts = 144.167007
current_received_ts = 144.166580
current_seq = 3006
count = 146
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.167007
last_received_ts = 144.166580
last_seq = 3006
current_ts = 144.183670
current_received_ts = 144.183517
current_seq = 3007
count = 147
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.183670
last_received_ts = 144.183517
last_seq = 3007
current_ts = 144.200333
current_received_ts = 144.199875
current_seq = 3008
count = 148
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.200333
last_received_ts = 144.199875
last_seq = 3008
current_ts = 144.217010
current_received_ts = 144.216675
current_seq = 3009
count = 149
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.217010
last_received_ts = 144.216675
last_seq = 3009
current_ts = 144.233673
current_received_ts = 144.233246
current_seq = 3010
count = 150
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 24us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.233673
last_received_ts = 144.233246
last_seq = 3010
current_ts = 144.250336
current_received_ts = 144.250168
current_seq = 3011
count = 151
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.250336
last_received_ts = 144.250168
last_seq = 3011
current_ts = 144.266998
current_received_ts = 144.266556
current_seq = 3012
count = 152
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.266998
last_received_ts = 144.266556
last_seq = 3012
current_ts = 144.283676
current_received_ts = 144.283737
current_seq = 3013
count = 153
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 20us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.283676
last_received_ts = 144.283737
last_seq = 3013
current_ts = 144.300339
current_received_ts = 144.300186
current_seq = 3014
count = 154
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.300339
last_received_ts = 144.300186
last_seq = 3014
current_ts = 144.317001
current_received_ts = 144.316528
current_seq = 3015
count = 155
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.317001
last_received_ts = 144.316528
last_seq = 3015
current_ts = 144.333664
current_received_ts = 144.333344
current_seq = 3016
count = 156
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.333664
last_received_ts = 144.333344
last_seq = 3016
current_ts = 144.350342
current_received_ts = 144.350143
current_seq = 3017
count = 157
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 24us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.350342
last_received_ts = 144.350143
last_seq = 3017
current_ts = 144.367004
current_received_ts = 144.366821
current_seq = 3018
count = 158
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.367004
last_received_ts = 144.366821
last_seq = 3018
current_ts = 144.383667
current_received_ts = 144.383453
current_seq = 3019
count = 159
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.383667
last_received_ts = 144.383453
last_seq = 3019
current_ts = 144.400345
current_received_ts = 144.400314
current_seq = 3020
count = 160
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.400345
last_received_ts = 144.400314
last_seq = 3020
current_ts = 144.417007
current_received_ts = 144.416550
current_seq = 3021
count = 161
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.417007
last_received_ts = 144.416550
last_seq = 3021
current_ts = 144.433670
current_received_ts = 144.433487
current_seq = 3022
count = 162
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.433670
last_received_ts = 144.433487
last_seq = 3022
current_ts = 144.450333
current_received_ts = 144.450211
current_seq = 3023
count = 163
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.450333
last_received_ts = 144.450211
last_seq = 3023
current_ts = 144.467010
current_received_ts = 144.466873
current_seq = 3024
count = 164
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.467010
last_received_ts = 144.466873
last_seq = 3024
current_ts = 144.483673
current_received_ts = 144.483582
current_seq = 3025
count = 165
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.483673
last_received_ts = 144.483582
last_seq = 3025
current_ts = 144.500336
current_received_ts = 144.500137
current_seq = 3026
count = 166
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 24us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.500336
last_received_ts = 144.500137
last_seq = 3026
current_ts = 144.517014
current_received_ts = 144.516541
current_seq = 3027
count = 167
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.517014
last_received_ts = 144.516541
last_seq = 3027
current_ts = 144.533676
current_received_ts = 144.533340
current_seq = 3028
count = 168
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.533676
last_received_ts = 144.533340
last_seq = 3028
current_ts = 144.550339
current_received_ts = 144.550140
current_seq = 3029
count = 169
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 24us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.550339
last_received_ts = 144.550140
last_seq = 3029
current_ts = 144.567001
current_received_ts = 144.566559
current_seq = 3030
count = 170
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.567001
last_received_ts = 144.566559
last_seq = 3030
current_ts = 144.583679
current_received_ts = 144.583344
current_seq = 3031
count = 171
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.583679
last_received_ts = 144.583344
last_seq = 3031
current_ts = 144.600327
current_received_ts = 144.600143
current_seq = 3032
count = 172
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.600327
last_received_ts = 144.600143
last_seq = 3032
current_ts = 144.617004
current_received_ts = 144.616531
current_seq = 3033
count = 173
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.617004
last_received_ts = 144.616531
last_seq = 3033
current_ts = 144.633667
current_received_ts = 144.633347
current_seq = 3034
count = 174
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.633667
last_received_ts = 144.633347
last_seq = 3034
current_ts = 144.650345
current_received_ts = 144.650253
current_seq = 3035
count = 175
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 20us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.650345
last_received_ts = 144.650253
last_seq = 3035
current_ts = 144.667007
current_received_ts = 144.666565
current_seq = 3036
count = 176
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.667007
last_received_ts = 144.666565
last_seq = 3036
current_ts = 144.683670
current_received_ts = 144.683365
current_seq = 3037
count = 177
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.683670
last_received_ts = 144.683365
last_seq = 3037
current_ts = 144.700348
current_received_ts = 144.700256
current_seq = 3038
count = 178
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.700348
last_received_ts = 144.700256
last_seq = 3038
current_ts = 144.717010
current_received_ts = 144.716537
current_seq = 3039
count = 179
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 19us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.717010
last_received_ts = 144.716537
last_seq = 3039
current_ts = 144.733673
current_received_ts = 144.733551
current_seq = 3040
count = 180
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.733673
last_received_ts = 144.733551
last_seq = 3040
current_ts = 144.750351
current_received_ts = 144.750336
current_seq = 3041
count = 181
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.750351
last_received_ts = 144.750336
last_seq = 3041
current_ts = 144.766998
current_received_ts = 144.766556
current_seq = 3042
count = 182
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.766998
last_received_ts = 144.766556
last_seq = 3042
current_ts = 144.783676
current_received_ts = 144.783524
current_seq = 3043
count = 183
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.783676
last_received_ts = 144.783524
last_seq = 3043
current_ts = 144.800339
current_received_ts = 144.799850
current_seq = 3044
count = 184
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.800339
last_received_ts = 144.799850
last_seq = 3044
current_ts = 144.817017
current_received_ts = 144.816757
current_seq = 3045
count = 185
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 20us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.817017
last_received_ts = 144.816757
last_seq = 3045
current_ts = 144.833679
current_received_ts = 144.833496
current_seq = 3046
count = 186
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 20us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.833679
last_received_ts = 144.833496
last_seq = 3046
current_ts = 144.850342
current_received_ts = 144.850174
current_seq = 3047
count = 187
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.850342
last_received_ts = 144.850174
last_seq = 3047
current_ts = 144.867004
current_received_ts = 144.866516
current_seq = 3048
count = 188
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.867004
last_received_ts = 144.866516
last_seq = 3048
current_ts = 144.883682
current_received_ts = 144.883484
current_seq = 3049
count = 189
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.883682
last_received_ts = 144.883484
last_seq = 3049
current_ts = 144.900345
current_received_ts = 144.900330
current_seq = 3050
count = 190
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.900345
last_received_ts = 144.900330
last_seq = 3050
current_ts = 144.917007
current_received_ts = 144.916550
current_seq = 3051
count = 191
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.917007
last_received_ts = 144.916550
last_seq = 3051
current_ts = 144.933670
current_received_ts = 144.933456
current_seq = 3052
count = 192
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 24us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.933670
last_received_ts = 144.933456
last_seq = 3052
current_ts = 144.950333
current_received_ts = 144.950180
current_seq = 3053
count = 193
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.950333
last_received_ts = 144.950180
last_seq = 3053
current_ts = 144.967010
current_received_ts = 144.966507
current_seq = 3054
count = 194
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.967010
last_received_ts = 144.966507
last_seq = 3054
current_ts = 144.983673
current_received_ts = 144.983704
current_seq = 3055
count = 195
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 20us
(kms_flip:2285) DEBUG: name = flip
last_ts = 144.983673
last_received_ts = 144.983704
last_seq = 3055
current_ts = 145.000336
current_received_ts = 145.000153
current_seq = 3056
count = 196
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.000336
last_received_ts = 145.000153
last_seq = 3056
current_ts = 145.017014
current_received_ts = 145.016556
current_seq = 3057
count = 197
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.017014
last_received_ts = 145.016556
last_seq = 3057
current_ts = 145.033676
current_received_ts = 145.033661
current_seq = 3058
count = 198
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.033676
last_received_ts = 145.033661
last_seq = 3058
current_ts = 145.050339
current_received_ts = 145.050278
current_seq = 3059
count = 199
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.050339
last_received_ts = 145.050278
last_seq = 3059
current_ts = 145.067017
current_received_ts = 145.066559
current_seq = 3060
count = 200
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.067017
last_received_ts = 145.066559
last_seq = 3060
current_ts = 145.083664
current_received_ts = 145.083282
current_seq = 3061
count = 201
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 48us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.083664
last_received_ts = 145.083282
last_seq = 3061
current_ts = 145.100327
current_received_ts = 145.100433
current_seq = 3062
count = 202
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.100327
last_received_ts = 145.100433
last_seq = 3062
current_ts = 145.117004
current_received_ts = 145.116577
current_seq = 3063
count = 203
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.117004
last_received_ts = 145.116577
last_seq = 3063
current_ts = 145.133667
current_received_ts = 145.133499
current_seq = 3064
count = 204
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.133667
last_received_ts = 145.133499
last_seq = 3064
current_ts = 145.150330
current_received_ts = 145.150162
current_seq = 3065
count = 205
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 24us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.150330
last_received_ts = 145.150162
last_seq = 3065
current_ts = 145.167007
current_received_ts = 145.166534
current_seq = 3066
count = 206
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.167007
last_received_ts = 145.166534
last_seq = 3066
current_ts = 145.183670
current_received_ts = 145.183670
current_seq = 3067
count = 207
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.183670
last_received_ts = 145.183670
last_seq = 3067
current_ts = 145.200333
current_received_ts = 145.200180
current_seq = 3068
count = 208
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.200333
last_received_ts = 145.200180
last_seq = 3068
current_ts = 145.216995
current_received_ts = 145.216537
current_seq = 3069
count = 209
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.216995
last_received_ts = 145.216537
last_seq = 3069
current_ts = 145.233673
current_received_ts = 145.233521
current_seq = 3070
count = 210
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.233673
last_received_ts = 145.233521
last_seq = 3070
current_ts = 145.250336
current_received_ts = 145.250351
current_seq = 3071
count = 211
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.250336
last_received_ts = 145.250351
last_seq = 3071
current_ts = 145.267014
current_received_ts = 145.266907
current_seq = 3072
count = 212
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 23us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.267014
last_received_ts = 145.266907
last_seq = 3072
current_ts = 145.283676
current_received_ts = 145.283798
current_seq = 3073
count = 213
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 22us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.283676
last_received_ts = 145.283798
last_seq = 3073
current_ts = 145.300339
current_received_ts = 145.300186
current_seq = 3074
count = 214
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 21us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.300339
last_received_ts = 145.300186
last_seq = 3074
current_ts = 145.317017
current_received_ts = 145.316696
current_seq = 3075
count = 215
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 16us
(kms_flip:2285) DEBUG: name = flip
last_ts = 145.317017
last_received_ts = 145.316696
last_seq = 3075
current_ts = 145.333679
current_received_ts = 145.333145
current_seq = 3076
count = 216
seq_step = 1
(kms_flip:2285) DEBUG: Vblank took 920us
(kms_flip:2285) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2285) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2285) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2285) igt_core-INFO: Stack trace:
(kms_flip:2285) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2285) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:2285) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:2285) igt_core-INFO:   #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
(kms_flip:2285) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:2285) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2285) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2285) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (4.202s)

Dmesg

<6> [141.391462] [IGT] kms_flip: starting dynamic subtest B-HDMI-A1

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

<7> [141.393596] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:180]

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

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

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

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

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

<7> [141.431298] 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 0x0000000d, found 0x00000000)

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

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

<7> [141.432566] 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 1920, found 0)

<7> [141.432969] 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 2200, found 0)

<7> [141.433390] 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 1920, found 0)

<7> [141.433794] 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 2200, found 0)

<7> [141.434226] 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 2008, found 0)

<7> [141.434630] 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 2052, found 0)

<7> [141.435066] 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 1080, found 0)

<7> [141.435492] 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 1080, found 0)

<7> [141.435895] 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 1083, found 0)

<7> [141.436323] 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 1088, found 0)

<7> [141.436728] 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 1125, found 0)

<7> [141.437153] 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 1125, found 0)

<7> [141.437556] 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 1920, found 0)

<7> [141.437958] 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 2200, found 0)

<7> [141.438377] 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 1920, found 0)

<7> [141.438784] 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 2200, found 0)

<7> [141.439216] 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 2008, found 0)

<7> [141.439617] 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 2052, found 0)

<7> [141.440020] 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 1080, found 0)

<7> [141.440439] 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 1080, found 0)

<7> [141.440840] 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 1083, found 0)

<7> [141.441266] 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 1088, found 0)

<7> [141.441670] 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 1125, found 0)

<7> [141.442074] 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 1125, found 0)

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

<7> [141.442897] 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 1, found 0)

<7> [141.443321] 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 8, found 0)

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

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

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

<7> [141.444969] 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 148500, found 0)

<7> [141.445392] 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 148500, found 0)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [141.451233] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:76:pipe A] releasing PORT PLL B

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

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

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

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

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

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

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

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

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

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

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

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

<7> [141.458042] 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:76:pipe A]

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

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

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

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

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

<7> [141.613729] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x1, on? 1) for [CRTC:76:pipe A]

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

<7> [141.616835] 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> [141.617318] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:163:DDI B/PHY B]

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

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

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

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

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

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

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

<7> [141.622680] 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> [141.624480] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:119:pipe B]

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

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

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

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

<7> [141.626183] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:119:pipe B] hw max bpp: 36, pipe bpp: 36, dithering: 0

<7> [141.626589] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:163:DDI B/PHY B] [CRTC:119:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [141.644091] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in avi infoframe

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [141.645385] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in spd infoframe

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

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

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

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

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

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

<7> [141.646640] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:119:pipe B] fastset requirement not met in hdmi infoframe

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

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

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

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

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

<7> [141.648687] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:119:pipe B] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x2

<7> [141.649329] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:plane 1B] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988

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

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

<7> [141.650546] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:77:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0

<7> [141.650942] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:77:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0

<7> [141.651371] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:77:plane 1B] 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> [141.651962] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:119:pipe B] min cdclk: 0 kHz -> 192000 kHz

<7> [141.652437] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:119:pipe B] using pre-allocated PORT PLL B

<7> [141.652844] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:119:pipe B] reserving PORT PLL B

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [141.657061] 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> [141.657492] 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> [141.657894] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

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

<7> [141.658719] 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> [141.659148] 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> [141.659551] 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> [141.659953] 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> [141.660375] 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> [141.660781] 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> [141.661212] 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> [141.661615] 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> [141.662018] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0

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

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

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

<7> [141.663672] 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> [141.664077] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

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

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

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

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

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

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

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

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

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

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

<7> [141.668637] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:86:plane 2B] fb: [NOFB], visible: no

<7> [141.669039] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:95:plane 3B] fb: [NOFB], visible: no

<7> [141.669474] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:104:plane 4B] fb: [NOFB], visible: no

<7> [141.669874] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:113:cursor B] fb: [NOFB], visible: no

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

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

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

<7> [141.674094] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL B (active 0x2, on? 0) for [CRTC:119:pipe B]

<7> [141.674555] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL B

<7> [141.677126] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B

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

<7> [141.696175] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:164:HDMI-A-1][ENCODER:163:DDI B/PHY B] Enable audio codec on [CRTC:119:pipe B], 32 bytes ELD

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

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

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

<7> [141.715308] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:119:pipe B]

<6> [145.595880] [IGT] kms_flip: finished subtest B-HDMI-A1, FAIL

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