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

Detail	Value
Duration	5.21 seconds
Hostname	shard-glk4
Igt-Version	IGT-Version: 2.4-g2a9f1c1ae (x86_64) (Linux: 7.0.0-rc7-CI_DRM_18290-g2dc939ed1bd6+ x86_64)
Out	Starting dynamic subtest: C-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:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1919 run_test() #3 ../tests/kms_flip.c:2219 __igt_unique____real_main2104() #4 ../tests/kms_flip.c:2104 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest C-HDMI-A1: FAIL (5.215s)
Err	Starting dynamic subtest: C-HDMI-A1 (kms_flip:2529) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2529) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2529) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest C-HDMI-A1 failed. ** DEBUG (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 457.927002 last_received_ts = 457.926544 last_seq = 4117 current_ts = 457.943665 current_received_ts = 457.943451 current_seq = 4118 count = 162 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 457.943665 last_received_ts = 457.943451 last_seq = 4118 current_ts = 457.960358 current_received_ts = 457.959961 current_seq = 4119 count = 163 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 457.960358 last_received_ts = 457.959961 last_seq = 4119 current_ts = 457.977020 current_received_ts = 457.976654 current_seq = 4120 count = 164 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 457.977020 last_received_ts = 457.976654 last_seq = 4120 current_ts = 457.993683 current_received_ts = 457.993469 current_seq = 4121 count = 165 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 457.993683 last_received_ts = 457.993469 last_seq = 4121 current_ts = 458.010345 current_received_ts = 458.010162 current_seq = 4122 count = 166 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 26us (kms_flip:2529) DEBUG: name = flip last_ts = 458.010345 last_received_ts = 458.010162 last_seq = 4122 current_ts = 458.027008 current_received_ts = 458.026794 current_seq = 4123 count = 167 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.027008 last_received_ts = 458.026794 last_seq = 4123 current_ts = 458.043671 current_received_ts = 458.043396 current_seq = 4124 count = 168 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 25us (kms_flip:2529) DEBUG: name = flip last_ts = 458.043671 last_received_ts = 458.043396 last_seq = 4124 current_ts = 458.060364 current_received_ts = 458.060638 current_seq = 4125 count = 169 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 20us (kms_flip:2529) DEBUG: name = flip last_ts = 458.060364 last_received_ts = 458.060638 last_seq = 4125 current_ts = 458.077026 current_received_ts = 458.076935 current_seq = 4126 count = 170 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 70us (kms_flip:2529) DEBUG: name = flip last_ts = 458.077026 last_received_ts = 458.076935 last_seq = 4126 current_ts = 458.093689 current_received_ts = 458.093506 current_seq = 4127 count = 171 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.093689 last_received_ts = 458.093506 last_seq = 4127 current_ts = 458.110352 current_received_ts = 458.110168 current_seq = 4128 count = 172 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 458.110352 last_received_ts = 458.110168 last_seq = 4128 current_ts = 458.127014 current_received_ts = 458.126923 current_seq = 4129 count = 173 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 64us (kms_flip:2529) DEBUG: name = flip last_ts = 458.127014 last_received_ts = 458.126923 last_seq = 4129 current_ts = 458.143677 current_received_ts = 458.143494 current_seq = 4130 count = 174 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 458.143677 last_received_ts = 458.143494 last_seq = 4130 current_ts = 458.160339 current_received_ts = 458.159851 current_seq = 4131 count = 175 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.160339 last_received_ts = 458.159851 last_seq = 4131 current_ts = 458.177032 current_received_ts = 458.176666 current_seq = 4132 count = 176 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 458.177032 last_received_ts = 458.176666 last_seq = 4132 current_ts = 458.193695 current_received_ts = 458.193481 current_seq = 4133 count = 177 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.193695 last_received_ts = 458.193481 last_seq = 4133 current_ts = 458.210358 current_received_ts = 458.210175 current_seq = 4134 count = 178 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.210358 last_received_ts = 458.210175 last_seq = 4134 current_ts = 458.227020 current_received_ts = 458.226501 current_seq = 4135 count = 179 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 458.227020 last_received_ts = 458.226501 last_seq = 4135 current_ts = 458.243683 current_received_ts = 458.243927 current_seq = 4136 count = 180 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 21us (kms_flip:2529) DEBUG: name = flip last_ts = 458.243683 last_received_ts = 458.243927 last_seq = 4136 current_ts = 458.260345 current_received_ts = 458.260162 current_seq = 4137 count = 181 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 25us (kms_flip:2529) DEBUG: name = flip last_ts = 458.260345 last_received_ts = 458.260162 last_seq = 4137 current_ts = 458.277008 current_received_ts = 458.276550 current_seq = 4138 count = 182 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.277008 last_received_ts = 458.276550 last_seq = 4138 current_ts = 458.293671 current_received_ts = 458.293549 current_seq = 4139 count = 183 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.293671 last_received_ts = 458.293549 last_seq = 4139 current_ts = 458.310333 current_received_ts = 458.310181 current_seq = 4140 count = 184 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 25us (kms_flip:2529) DEBUG: name = flip last_ts = 458.310333 last_received_ts = 458.310181 last_seq = 4140 current_ts = 458.327026 current_received_ts = 458.326538 current_seq = 4141 count = 185 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.327026 last_received_ts = 458.326538 last_seq = 4141 current_ts = 458.343689 current_received_ts = 458.343475 current_seq = 4142 count = 186 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.343689 last_received_ts = 458.343475 last_seq = 4142 current_ts = 458.360352 current_received_ts = 458.360168 current_seq = 4143 count = 187 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.360352 last_received_ts = 458.360168 last_seq = 4143 current_ts = 458.377014 current_received_ts = 458.376526 current_seq = 4144 count = 188 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.377014 last_received_ts = 458.376526 last_seq = 4144 current_ts = 458.393677 current_received_ts = 458.393341 current_seq = 4145 count = 189 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 458.393677 last_received_ts = 458.393341 last_seq = 4145 current_ts = 458.410339 current_received_ts = 458.410156 current_seq = 4146 count = 190 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 26us (kms_flip:2529) DEBUG: name = flip last_ts = 458.410339 last_received_ts = 458.410156 last_seq = 4146 current_ts = 458.427002 current_received_ts = 458.426575 current_seq = 4147 count = 191 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.427002 last_received_ts = 458.426575 last_seq = 4147 current_ts = 458.443665 current_received_ts = 458.443817 current_seq = 4148 count = 192 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.443665 last_received_ts = 458.443817 last_seq = 4148 current_ts = 458.460358 current_received_ts = 458.459869 current_seq = 4149 count = 193 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.460358 last_received_ts = 458.459869 last_seq = 4149 current_ts = 458.477020 current_received_ts = 458.477112 current_seq = 4150 count = 194 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 20us (kms_flip:2529) DEBUG: name = flip last_ts = 458.477020 last_received_ts = 458.477112 last_seq = 4150 current_ts = 458.493683 current_received_ts = 458.493530 current_seq = 4151 count = 195 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.493683 last_received_ts = 458.493530 last_seq = 4151 current_ts = 458.510345 current_received_ts = 458.510223 current_seq = 4152 count = 196 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.510345 last_received_ts = 458.510223 last_seq = 4152 current_ts = 458.527008 current_received_ts = 458.526550 current_seq = 4153 count = 197 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.527008 last_received_ts = 458.526550 last_seq = 4153 current_ts = 458.543671 current_received_ts = 458.543976 current_seq = 4154 count = 198 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 21us (kms_flip:2529) DEBUG: name = flip last_ts = 458.543671 last_received_ts = 458.543976 last_seq = 4154 current_ts = 458.560333 current_received_ts = 458.560181 current_seq = 4155 count = 199 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.560333 last_received_ts = 458.560181 last_seq = 4155 current_ts = 458.577026 current_received_ts = 458.576935 current_seq = 4156 count = 200 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 66us (kms_flip:2529) DEBUG: name = flip last_ts = 458.577026 last_received_ts = 458.576935 last_seq = 4156 current_ts = 458.593689 current_received_ts = 458.593842 current_seq = 4157 count = 201 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.593689 last_received_ts = 458.593842 last_seq = 4157 current_ts = 458.610352 current_received_ts = 458.609833 current_seq = 4158 count = 202 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 458.610352 last_received_ts = 458.609833 last_seq = 4158 current_ts = 458.627014 current_received_ts = 458.626556 current_seq = 4159 count = 203 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.627014 last_received_ts = 458.626556 last_seq = 4159 current_ts = 458.643677 current_received_ts = 458.643463 current_seq = 4160 count = 204 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.643677 last_received_ts = 458.643463 last_seq = 4160 current_ts = 458.660339 current_received_ts = 458.660156 current_seq = 4161 count = 205 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.660339 last_received_ts = 458.660156 last_seq = 4161 current_ts = 458.677032 current_received_ts = 458.676514 current_seq = 4162 count = 206 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.677032 last_received_ts = 458.676514 last_seq = 4162 current_ts = 458.693665 current_received_ts = 458.693756 current_seq = 4163 count = 207 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 21us (kms_flip:2529) DEBUG: name = flip last_ts = 458.693665 last_received_ts = 458.693756 last_seq = 4163 current_ts = 458.710358 current_received_ts = 458.710175 current_seq = 4164 count = 208 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 26us (kms_flip:2529) DEBUG: name = flip last_ts = 458.710358 last_received_ts = 458.710175 last_seq = 4164 current_ts = 458.727020 current_received_ts = 458.726532 current_seq = 4165 count = 209 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.727020 last_received_ts = 458.726532 last_seq = 4165 current_ts = 458.743683 current_received_ts = 458.743317 current_seq = 4166 count = 210 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.743683 last_received_ts = 458.743317 last_seq = 4166 current_ts = 458.760345 current_received_ts = 458.760162 current_seq = 4167 count = 211 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.760345 last_received_ts = 458.760162 last_seq = 4167 current_ts = 458.777008 current_received_ts = 458.776550 current_seq = 4168 count = 212 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 458.777008 last_received_ts = 458.776550 last_seq = 4168 current_ts = 458.793671 current_received_ts = 458.793457 current_seq = 4169 count = 213 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.793671 last_received_ts = 458.793457 last_seq = 4169 current_ts = 458.810333 current_received_ts = 458.809937 current_seq = 4170 count = 214 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 458.810333 last_received_ts = 458.809937 last_seq = 4170 current_ts = 458.827026 current_received_ts = 458.826569 current_seq = 4171 count = 215 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.827026 last_received_ts = 458.826569 last_seq = 4171 current_ts = 458.843689 current_received_ts = 458.843475 current_seq = 4172 count = 216 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 25us (kms_flip:2529) DEBUG: name = flip last_ts = 458.843689 last_received_ts = 458.843475 last_seq = 4172 current_ts = 458.860352 current_received_ts = 458.859802 current_seq = 4173 count = 217 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 21us (kms_flip:2529) DEBUG: name = flip last_ts = 458.860352 last_received_ts = 458.859802 last_seq = 4173 current_ts = 458.877014 current_received_ts = 458.876587 current_seq = 4174 count = 218 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 458.877014 last_received_ts = 458.876587 last_seq = 4174 current_ts = 458.893677 current_received_ts = 458.893494 current_seq = 4175 count = 219 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.893677 last_received_ts = 458.893494 last_seq = 4175 current_ts = 458.910339 current_received_ts = 458.910217 current_seq = 4176 count = 220 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 25us (kms_flip:2529) DEBUG: name = flip last_ts = 458.910339 last_received_ts = 458.910217 last_seq = 4176 current_ts = 458.927002 current_received_ts = 458.927002 current_seq = 4177 count = 221 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 21us (kms_flip:2529) DEBUG: name = flip last_ts = 458.927002 last_received_ts = 458.927002 last_seq = 4177 current_ts = 458.943665 current_received_ts = 458.943451 current_seq = 4178 count = 222 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.943665 last_received_ts = 458.943451 last_seq = 4178 current_ts = 458.960358 current_received_ts = 458.960175 current_seq = 4179 count = 223 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 21us (kms_flip:2529) DEBUG: name = flip last_ts = 458.960358 last_received_ts = 458.960175 last_seq = 4179 current_ts = 458.977020 current_received_ts = 458.976532 current_seq = 4180 count = 224 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 458.977020 last_received_ts = 458.976532 last_seq = 4180 current_ts = 458.993683 current_received_ts = 458.993469 current_seq = 4181 count = 225 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 458.993683 last_received_ts = 458.993469 last_seq = 4181 current_ts = 459.010345 current_received_ts = 459.010193 current_seq = 4182 count = 226 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.010345 last_received_ts = 459.010193 last_seq = 4182 current_ts = 459.027008 current_received_ts = 459.026581 current_seq = 4183 count = 227 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.027008 last_received_ts = 459.026581 last_seq = 4183 current_ts = 459.043671 current_received_ts = 459.043518 current_seq = 4184 count = 228 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.043671 last_received_ts = 459.043518 last_seq = 4184 current_ts = 459.060333 current_received_ts = 459.060150 current_seq = 4185 count = 229 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 459.060333 last_received_ts = 459.060150 last_seq = 4185 current_ts = 459.077026 current_received_ts = 459.076569 current_seq = 4186 count = 230 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.077026 last_received_ts = 459.076569 last_seq = 4186 current_ts = 459.093689 current_received_ts = 459.093964 current_seq = 4187 count = 231 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 21us (kms_flip:2529) DEBUG: name = flip last_ts = 459.093689 last_received_ts = 459.093964 last_seq = 4187 current_ts = 459.110352 current_received_ts = 459.110168 current_seq = 4188 count = 232 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.110352 last_received_ts = 459.110168 last_seq = 4188 current_ts = 459.127014 current_received_ts = 459.126923 current_seq = 4189 count = 233 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 65us (kms_flip:2529) DEBUG: name = flip last_ts = 459.127014 last_received_ts = 459.126923 last_seq = 4189 current_ts = 459.143677 current_received_ts = 459.143463 current_seq = 4190 count = 234 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 459.143677 last_received_ts = 459.143463 last_seq = 4190 current_ts = 459.160339 current_received_ts = 459.159851 current_seq = 4191 count = 235 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.160339 last_received_ts = 459.159851 last_seq = 4191 current_ts = 459.177002 current_received_ts = 459.176941 current_seq = 4192 count = 236 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 51us (kms_flip:2529) DEBUG: name = flip last_ts = 459.177002 last_received_ts = 459.176941 last_seq = 4192 current_ts = 459.193665 current_received_ts = 459.193481 current_seq = 4193 count = 237 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.193665 last_received_ts = 459.193481 last_seq = 4193 current_ts = 459.210358 current_received_ts = 459.210144 current_seq = 4194 count = 238 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.210358 last_received_ts = 459.210144 last_seq = 4194 current_ts = 459.227020 current_received_ts = 459.226562 current_seq = 4195 count = 239 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.227020 last_received_ts = 459.226562 last_seq = 4195 current_ts = 459.243683 current_received_ts = 459.243500 current_seq = 4196 count = 240 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 21us (kms_flip:2529) DEBUG: name = flip last_ts = 459.243683 last_received_ts = 459.243500 last_seq = 4196 current_ts = 459.260345 current_received_ts = 459.260468 current_seq = 4197 count = 241 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 20us (kms_flip:2529) DEBUG: name = flip last_ts = 459.260345 last_received_ts = 459.260468 last_seq = 4197 current_ts = 459.277008 current_received_ts = 459.276550 current_seq = 4198 count = 242 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 25us (kms_flip:2529) DEBUG: name = flip last_ts = 459.277008 last_received_ts = 459.276550 last_seq = 4198 current_ts = 459.293671 current_received_ts = 459.293518 current_seq = 4199 count = 243 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 40us (kms_flip:2529) DEBUG: name = flip last_ts = 459.293671 last_received_ts = 459.293518 last_seq = 4199 current_ts = 459.310333 current_received_ts = 459.310150 current_seq = 4200 count = 244 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.310333 last_received_ts = 459.310150 last_seq = 4200 current_ts = 459.327026 current_received_ts = 459.326935 current_seq = 4201 count = 245 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 59us (kms_flip:2529) DEBUG: name = flip last_ts = 459.327026 last_received_ts = 459.326935 last_seq = 4201 current_ts = 459.343689 current_received_ts = 459.343842 current_seq = 4202 count = 246 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.343689 last_received_ts = 459.343842 last_seq = 4202 current_ts = 459.360352 current_received_ts = 459.359863 current_seq = 4203 count = 247 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 21us (kms_flip:2529) DEBUG: name = flip last_ts = 459.360352 last_received_ts = 459.359863 last_seq = 4203 current_ts = 459.377014 current_received_ts = 459.377014 current_seq = 4204 count = 248 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 21us (kms_flip:2529) DEBUG: name = flip last_ts = 459.377014 last_received_ts = 459.377014 last_seq = 4204 current_ts = 459.393677 current_received_ts = 459.393463 current_seq = 4205 count = 249 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 26us (kms_flip:2529) DEBUG: name = flip last_ts = 459.393677 last_received_ts = 459.393463 last_seq = 4205 current_ts = 459.410339 current_received_ts = 459.410187 current_seq = 4206 count = 250 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.410339 last_received_ts = 459.410187 last_seq = 4206 current_ts = 459.427002 current_received_ts = 459.426819 current_seq = 4207 count = 251 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.427002 last_received_ts = 459.426819 last_seq = 4207 current_ts = 459.443695 current_received_ts = 459.443481 current_seq = 4208 count = 252 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.443695 last_received_ts = 459.443481 last_seq = 4208 current_ts = 459.460327 current_received_ts = 459.460419 current_seq = 4209 count = 253 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 20us (kms_flip:2529) DEBUG: name = flip last_ts = 459.460327 last_received_ts = 459.460419 last_seq = 4209 current_ts = 459.477020 current_received_ts = 459.476959 current_seq = 4210 count = 254 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.477020 last_received_ts = 459.476959 last_seq = 4210 current_ts = 459.493683 current_received_ts = 459.493530 current_seq = 4211 count = 255 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 25us (kms_flip:2529) DEBUG: name = flip last_ts = 459.493683 last_received_ts = 459.493530 last_seq = 4211 current_ts = 459.510345 current_received_ts = 459.510193 current_seq = 4212 count = 256 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 459.510345 last_received_ts = 459.510193 last_seq = 4212 current_ts = 459.527008 current_received_ts = 459.526550 current_seq = 4213 count = 257 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 459.527008 last_received_ts = 459.526550 last_seq = 4213 current_ts = 459.543671 current_received_ts = 459.543274 current_seq = 4214 count = 258 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 25us (kms_flip:2529) DEBUG: name = flip last_ts = 459.543671 last_received_ts = 459.543274 last_seq = 4214 current_ts = 459.560333 current_received_ts = 459.560242 current_seq = 4215 count = 259 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 21us (kms_flip:2529) DEBUG: name = flip last_ts = 459.560333 last_received_ts = 459.560242 last_seq = 4215 current_ts = 459.577026 current_received_ts = 459.576935 current_seq = 4216 count = 260 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 61us (kms_flip:2529) DEBUG: name = flip last_ts = 459.577026 last_received_ts = 459.576935 last_seq = 4216 current_ts = 459.593689 current_received_ts = 459.593811 current_seq = 4217 count = 261 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 459.593689 last_received_ts = 459.593811 last_seq = 4217 current_ts = 459.610352 current_received_ts = 459.609863 current_seq = 4218 count = 262 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 459.610352 last_received_ts = 459.609863 last_seq = 4218 current_ts = 459.627014 current_received_ts = 459.626587 current_seq = 4219 count = 263 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.627014 last_received_ts = 459.626587 last_seq = 4219 current_ts = 459.643677 current_received_ts = 459.643829 current_seq = 4220 count = 264 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.643677 last_received_ts = 459.643829 last_seq = 4220 current_ts = 459.660339 current_received_ts = 459.660217 current_seq = 4221 count = 265 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.660339 last_received_ts = 459.660217 last_seq = 4221 current_ts = 459.677002 current_received_ts = 459.676544 current_seq = 4222 count = 266 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.677002 last_received_ts = 459.676544 last_seq = 4222 current_ts = 459.693695 current_received_ts = 459.693909 current_seq = 4223 count = 267 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 20us (kms_flip:2529) DEBUG: name = flip last_ts = 459.693695 last_received_ts = 459.693909 last_seq = 4223 current_ts = 459.710358 current_received_ts = 459.710175 current_seq = 4224 count = 268 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 25us (kms_flip:2529) DEBUG: name = flip last_ts = 459.710358 last_received_ts = 459.710175 last_seq = 4224 current_ts = 459.727020 current_received_ts = 459.726532 current_seq = 4225 count = 269 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 459.727020 last_received_ts = 459.726532 last_seq = 4225 current_ts = 459.743683 current_received_ts = 459.743469 current_seq = 4226 count = 270 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.743683 last_received_ts = 459.743469 last_seq = 4226 current_ts = 459.760345 current_received_ts = 459.759888 current_seq = 4227 count = 271 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.760345 last_received_ts = 459.759888 last_seq = 4227 current_ts = 459.777008 current_received_ts = 459.776581 current_seq = 4228 count = 272 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 459.777008 last_received_ts = 459.776581 last_seq = 4228 current_ts = 459.793671 current_received_ts = 459.793854 current_seq = 4229 count = 273 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.793671 last_received_ts = 459.793854 last_seq = 4229 current_ts = 459.810333 current_received_ts = 459.809998 current_seq = 4230 count = 274 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.810333 last_received_ts = 459.809998 last_seq = 4230 current_ts = 459.827026 current_received_ts = 459.826538 current_seq = 4231 count = 275 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.827026 last_received_ts = 459.826538 last_seq = 4231 current_ts = 459.843689 current_received_ts = 459.843933 current_seq = 4232 count = 276 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 54us (kms_flip:2529) DEBUG: name = flip last_ts = 459.843689 last_received_ts = 459.843933 last_seq = 4232 current_ts = 459.860352 current_received_ts = 459.860260 current_seq = 4233 count = 277 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 24us (kms_flip:2529) DEBUG: name = flip last_ts = 459.860352 last_received_ts = 459.860260 last_seq = 4233 current_ts = 459.877014 current_received_ts = 459.876556 current_seq = 4234 count = 278 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.877014 last_received_ts = 459.876556 last_seq = 4234 current_ts = 459.893677 current_received_ts = 459.893799 current_seq = 4235 count = 279 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 22us (kms_flip:2529) DEBUG: name = flip last_ts = 459.893677 last_received_ts = 459.893799 last_seq = 4235 current_ts = 459.910339 current_received_ts = 459.909821 current_seq = 4236 count = 280 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.910339 last_received_ts = 459.909821 last_seq = 4236 current_ts = 459.927002 current_received_ts = 459.926575 current_seq = 4237 count = 281 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 23us (kms_flip:2529) DEBUG: name = flip last_ts = 459.927002 last_received_ts = 459.926575 last_seq = 4237 current_ts = 459.943665 current_received_ts = 459.943970 current_seq = 4238 count = 282 seq_step = 1 (kms_flip:2529) DEBUG: Vblank took 1250us (kms_flip:2529) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2529) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2529) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:2529) igt_core-INFO: Stack trace: (kms_flip:2529) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2529) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:2529) igt_core-INFO: #2 ../tests/kms_flip.c:1919 run_test() (kms_flip:2529) igt_core-INFO: #3 ../tests/kms_flip.c:2219 __igt_unique____real_main2104() (kms_flip:2529) igt_core-INFO: #4 ../tests/kms_flip.c:2104 main() (kms_flip:2529) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2529) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2529) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest C-HDMI-A1: FAIL (5.215s)
Dmesg	<6> [454.817287] [IGT] kms_flip: starting dynamic subtest C-HDMI-A1 <7> [454.818400] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:180] <7> [454.819885] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:182] <7> [454.859398] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A] <7> [454.860718] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [454.860897] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [454.861447] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [454.861971] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1) <7> [454.862376] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_count (expected 4, found 0) <7> [454.862828] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000) <7> [454.863240] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [454.863721] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [454.864104] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [454.864484] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [454.864937] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [454.865326] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [454.865770] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [454.866156] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [454.866587] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [454.866969] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [454.867349] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [454.867750] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [454.868130] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [454.868508] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [454.869031] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [454.869417] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [454.869822] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [454.870202] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [454.870703] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [454.871109] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [454.871488] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [454.871920] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [454.872323] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [454.872748] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [454.873160] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [454.873576] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [454.873959] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [454.874338] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [454.874769] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [454.875152] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [454.875558] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_infoframe (expected yes, found no) <7> [454.875942] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [454.876321] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [454.876741] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [454.877122] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in port_clock (expected 222750, found 0) <7> [454.877500] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [454.877918] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000) <7> [454.878369] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in avi infoframe <7> [454.878791] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [454.879169] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [454.879174] i915 0000:00:02.0: colorspace: RGB <7> [454.879177] i915 0000:00:02.0: scan mode: Underscan <7> [454.879181] i915 0000:00:02.0: colorimetry: No Data <7> [454.879185] i915 0000:00:02.0: picture aspect: No Data <7> [454.879188] i915 0000:00:02.0: active aspect: Same as Picture <7> [454.879191] i915 0000:00:02.0: itc: No Data <7> [454.879195] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [454.879198] i915 0000:00:02.0: quantization range: Full <7> [454.879201] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [454.879205] i915 0000:00:02.0: video code: 0 <7> [454.879208] i915 0000:00:02.0: ycc quantization range: Full <7> [454.879212] i915 0000:00:02.0: hdmi content type: Graphics <7> [454.879215] i915 0000:00:02.0: pixel repeat: 0 <7> [454.879218] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [454.879222] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [454.879615] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in spd infoframe <7> [454.879993] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [454.880431] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [454.880435] i915 0000:00:02.0: vendor: Intel <7> [454.880439] i915 0000:00:02.0: product: Integrated gfx <7> [454.880442] i915 0000:00:02.0: source device information: PC General (0x9) <7> [454.880446] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [454.880923] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hdmi infoframe <7> [454.881324] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [454.881754] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [454.881759] i915 0000:00:02.0: empty frame <7> [454.881762] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [454.882169] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] fastset requirement not met, forcing full modeset <7> [454.882586] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:121:pipe B] releasing PORT PLL B <7> [454.883032] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:121:pipe B] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x2 -> 0x0 <7> [454.883469] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:115:cursor B] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0 <7> [454.883969] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:121:pipe B] min cdclk: 192000 kHz -> 0 kHz <7> [454.884418] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [454.884864] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz <7> [454.885242] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4 <7> [454.885650] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:121:pipe B] enable: no [modeset] <7> [454.886032] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:79:plane 1B] fb: [NOFB], visible: no <7> [454.886411] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:88:plane 2B] fb: [NOFB], visible: no <7> [454.886820] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:97:plane 3B] fb: [NOFB], visible: no <7> [454.887196] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:106:plane 4B] fb: [NOFB], visible: no <7> [454.887602] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:115:cursor B] fb: [NOFB], visible: no <7> [454.888155] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:166:HDMI-A-1][ENCODER:165:DDI B/PHY B] Disable audio codec on [CRTC:121:pipe B] <7> [454.910928] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [454.911718] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B <7> [454.924138] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10 <7> [454.927570] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time <7> [455.032054] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [455.033184] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x2, on? 1) for [CRTC:121:pipe B] <7> [455.036969] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL B <7> [455.037587] 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> [455.038031] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [455.038443] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [455.039253] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:166:HDMI-A-1] <7> [455.041873] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-b <7> [455.042436] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:121:pipe B] <7> [455.043494] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [455.043983] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz <7> [455.044362] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13 <7> [455.044622] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C] <7> [455.044880] 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> [455.047735] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C] <7> [455.047815] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:166:HDMI-A-1] <7> [455.048037] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 12 bpc for HDMI output (pipe bpp: 36) <7> [455.048555] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:164:pipe C] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [455.048940] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:165:DDI B/PHY B] [CRTC:164:pipe C] <7> [455.049317] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [455.049761] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [455.050153] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [455.050757] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL <7> [455.050777] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled <7> [455.052590] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [455.053095] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d) <7> [455.053478] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [455.054552] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [455.055039] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [455.055430] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [455.056202] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [455.056867] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [455.057250] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [455.057816] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [455.058248] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [455.060583] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [455.061093] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [455.061475] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [455.062811] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [455.063283] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [455.064129] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [455.064958] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [455.065379] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [455.067359] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [455.068150] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [455.069597] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [455.069993] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [455.070375] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [455.071040] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [455.072097] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [455.072902] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [455.073326] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [455.073983] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [455.074367] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [455.076341] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [455.077179] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [455.078494] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in has_infoframe (expected no, found yes) <7> [455.079405] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [455.080167] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [455.080830] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [455.081224] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in port_clock (expected 0, found 222750) <7> [455.083101] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [455.084017] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006) <7> [455.084411] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in avi infoframe <7> [455.085763] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [455.086247] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [455.087226] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [455.087232] i915 0000:00:02.0: colorspace: RGB <7> [455.087236] i915 0000:00:02.0: scan mode: Underscan <7> [455.087240] i915 0000:00:02.0: colorimetry: No Data <7> [455.087243] i915 0000:00:02.0: picture aspect: No Data <7> [455.087246] i915 0000:00:02.0: active aspect: Same as Picture <7> [455.087250] i915 0000:00:02.0: itc: No Data <7> [455.087253] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [455.087257] i915 0000:00:02.0: quantization range: Full <7> [455.087260] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [455.087263] i915 0000:00:02.0: video code: 0 <7> [455.087266] i915 0000:00:02.0: ycc quantization range: Full <7> [455.087269] i915 0000:00:02.0: hdmi content type: Graphics <7> [455.087272] i915 0000:00:02.0: pixel repeat: 0 <7> [455.087275] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [455.087280] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in spd infoframe <7> [455.087919] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [455.088333] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [455.088779] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [455.088784] i915 0000:00:02.0: vendor: Intel <7> [455.088787] i915 0000:00:02.0: product: Integrated gfx <7> [455.088791] i915 0000:00:02.0: source device information: PC General (0x9) <7> [455.088795] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hdmi infoframe <7> [455.089204] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [455.089699] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [455.090081] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [455.090088] i915 0000:00:02.0: empty frame <7> [455.090093] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:164:pipe C] fastset requirement not met, forcing full modeset <7> [455.092040] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:164:pipe C] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x4 <7> [455.092630] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:122:plane 1C] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988 <7> [455.093010] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:158:cursor C] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32 <7> [455.093382] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,*twm, swm, stwm <7> [455.095613] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0 <7> [455.096097] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0 <7> [455.096494] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] 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> [455.097296] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] min_ddb_uv 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [455.097879] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:164:pipe C] min cdclk: 0 kHz -> 192000 kHz <7> [455.098311] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:164:pipe C] using pre-allocated PORT PLL B <7> [455.098859] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:164:pipe C] reserving PORT PLL B <7> [455.099285] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:164:pipe C] enable: yes [modeset] <7> [455.099819] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [455.100203] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: C, pipe bpp: 36, dithering: 0 <7> [455.100659] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [455.101072] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [455.101453] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [455.104069] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [455.104920] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [455.105376] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6 <7> [455.105904] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [455.105910] i915 0000:00:02.0: colorspace: RGB <7> [455.105914] i915 0000:00:02.0: scan mode: Underscan <7> [455.105935] i915 0000:00:02.0: colorimetry: No Data <7> [455.105938] i915 0000:00:02.0: picture aspect: No Data <7> [455.105942] i915 0000:00:02.0: active aspect: Same as Picture <7> [455.105945] i915 0000:00:02.0: itc: No Data <7> [455.105949] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [455.105952] i915 0000:00:02.0: quantization range: Full <7> [455.105955] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [455.105959] i915 0000:00:02.0: video code: 0 <7> [455.105962] i915 0000:00:02.0: ycc quantization range: Full <7> [455.105966] i915 0000:00:02.0: hdmi content type: Graphics <7> [455.105969] i915 0000:00:02.0: pixel repeat: 0 <7> [455.105972] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [455.105976] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [455.105980] i915 0000:00:02.0: vendor: Intel <7> [455.105983] i915 0000:00:02.0: product: Integrated gfx <7> [455.105987] i915 0000:00:02.0: source device information: PC General (0x9) <7> [455.105991] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [455.105995] i915 0000:00:02.0: empty frame <7> [455.105999] 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> [455.106383] 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> [455.106862] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [455.107263] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [455.107729] 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> [455.108136] 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> [455.108512] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [455.111456] 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> [455.112088] 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> [455.112471] 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> [455.113293] 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> [455.113788] 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> [455.114169] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pixel rate 148500, min cdclk 192000, min voltage level 0 <7> [455.114727] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [455.115132] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 1, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [455.115622] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [455.116032] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [455.116410] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [455.116841] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [455.117252] 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> [455.120618] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [455.121174] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [455.123737] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [455.124263] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [455.124673] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [455.125052] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [455.125429] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [455.125839] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:122:plane 1C] fb: [FB:180] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [455.126223] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [455.126654] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [455.127068] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:131:plane 2C] fb: [NOFB], visible: no <7> [455.127450] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:140:plane 3C] fb: [NOFB], visible: no <7> [455.127856] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:149:plane 4C] fb: [NOFB], visible: no <7> [455.128237] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:158:cursor C] fb: [NOFB], visible: no <7> [455.129338] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-b <7> [455.131413] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [455.131938] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [455.132488] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL B (active 0x4, on? 0) for [CRTC:164:pipe C] <7> [455.132913] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL B <7> [455.134452] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B <7> [455.135383] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe C <7> [455.153634] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:166:HDMI-A-1][ENCODER:165:DDI B/PHY B] Enable audio codec on [CRTC:164:pipe C], 32 bytes ELD <7> [455.170311] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000) <7> [455.170831] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <7> [455.171398] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:166:HDMI-A-1] <7> [455.173160] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:164:pipe C] <6> [460.033567] [IGT] kms_flip: finished subtest C-HDMI-A1, FAIL

Detail

Value

Duration

5.21 seconds

Hostname

shard-glk4

Igt-Version

IGT-Version: 2.4-g2a9f1c1ae (x86_64) (Linux: 7.0.0-rc7-CI_DRM_18290-g2dc939ed1bd6+ x86_64)

Out

Starting dynamic subtest: C-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:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1919 run_test()
  #3 ../tests/kms_flip.c:2219 __igt_unique____real_main2104()
  #4 ../tests/kms_flip.c:2104 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-HDMI-A1: FAIL (5.215s)

Err

Starting dynamic subtest: C-HDMI-A1
(kms_flip:2529) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2529) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2529) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 457.927002
last_received_ts = 457.926544
last_seq = 4117
current_ts = 457.943665
current_received_ts = 457.943451
current_seq = 4118
count = 162
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 457.943665
last_received_ts = 457.943451
last_seq = 4118
current_ts = 457.960358
current_received_ts = 457.959961
current_seq = 4119
count = 163
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 457.960358
last_received_ts = 457.959961
last_seq = 4119
current_ts = 457.977020
current_received_ts = 457.976654
current_seq = 4120
count = 164
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 457.977020
last_received_ts = 457.976654
last_seq = 4120
current_ts = 457.993683
current_received_ts = 457.993469
current_seq = 4121
count = 165
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 457.993683
last_received_ts = 457.993469
last_seq = 4121
current_ts = 458.010345
current_received_ts = 458.010162
current_seq = 4122
count = 166
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 26us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.010345
last_received_ts = 458.010162
last_seq = 4122
current_ts = 458.027008
current_received_ts = 458.026794
current_seq = 4123
count = 167
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.027008
last_received_ts = 458.026794
last_seq = 4123
current_ts = 458.043671
current_received_ts = 458.043396
current_seq = 4124
count = 168
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 25us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.043671
last_received_ts = 458.043396
last_seq = 4124
current_ts = 458.060364
current_received_ts = 458.060638
current_seq = 4125
count = 169
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 20us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.060364
last_received_ts = 458.060638
last_seq = 4125
current_ts = 458.077026
current_received_ts = 458.076935
current_seq = 4126
count = 170
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 70us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.077026
last_received_ts = 458.076935
last_seq = 4126
current_ts = 458.093689
current_received_ts = 458.093506
current_seq = 4127
count = 171
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.093689
last_received_ts = 458.093506
last_seq = 4127
current_ts = 458.110352
current_received_ts = 458.110168
current_seq = 4128
count = 172
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.110352
last_received_ts = 458.110168
last_seq = 4128
current_ts = 458.127014
current_received_ts = 458.126923
current_seq = 4129
count = 173
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 64us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.127014
last_received_ts = 458.126923
last_seq = 4129
current_ts = 458.143677
current_received_ts = 458.143494
current_seq = 4130
count = 174
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.143677
last_received_ts = 458.143494
last_seq = 4130
current_ts = 458.160339
current_received_ts = 458.159851
current_seq = 4131
count = 175
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.160339
last_received_ts = 458.159851
last_seq = 4131
current_ts = 458.177032
current_received_ts = 458.176666
current_seq = 4132
count = 176
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.177032
last_received_ts = 458.176666
last_seq = 4132
current_ts = 458.193695
current_received_ts = 458.193481
current_seq = 4133
count = 177
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.193695
last_received_ts = 458.193481
last_seq = 4133
current_ts = 458.210358
current_received_ts = 458.210175
current_seq = 4134
count = 178
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.210358
last_received_ts = 458.210175
last_seq = 4134
current_ts = 458.227020
current_received_ts = 458.226501
current_seq = 4135
count = 179
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.227020
last_received_ts = 458.226501
last_seq = 4135
current_ts = 458.243683
current_received_ts = 458.243927
current_seq = 4136
count = 180
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 21us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.243683
last_received_ts = 458.243927
last_seq = 4136
current_ts = 458.260345
current_received_ts = 458.260162
current_seq = 4137
count = 181
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 25us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.260345
last_received_ts = 458.260162
last_seq = 4137
current_ts = 458.277008
current_received_ts = 458.276550
current_seq = 4138
count = 182
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.277008
last_received_ts = 458.276550
last_seq = 4138
current_ts = 458.293671
current_received_ts = 458.293549
current_seq = 4139
count = 183
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.293671
last_received_ts = 458.293549
last_seq = 4139
current_ts = 458.310333
current_received_ts = 458.310181
current_seq = 4140
count = 184
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 25us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.310333
last_received_ts = 458.310181
last_seq = 4140
current_ts = 458.327026
current_received_ts = 458.326538
current_seq = 4141
count = 185
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.327026
last_received_ts = 458.326538
last_seq = 4141
current_ts = 458.343689
current_received_ts = 458.343475
current_seq = 4142
count = 186
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.343689
last_received_ts = 458.343475
last_seq = 4142
current_ts = 458.360352
current_received_ts = 458.360168
current_seq = 4143
count = 187
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.360352
last_received_ts = 458.360168
last_seq = 4143
current_ts = 458.377014
current_received_ts = 458.376526
current_seq = 4144
count = 188
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.377014
last_received_ts = 458.376526
last_seq = 4144
current_ts = 458.393677
current_received_ts = 458.393341
current_seq = 4145
count = 189
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.393677
last_received_ts = 458.393341
last_seq = 4145
current_ts = 458.410339
current_received_ts = 458.410156
current_seq = 4146
count = 190
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 26us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.410339
last_received_ts = 458.410156
last_seq = 4146
current_ts = 458.427002
current_received_ts = 458.426575
current_seq = 4147
count = 191
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.427002
last_received_ts = 458.426575
last_seq = 4147
current_ts = 458.443665
current_received_ts = 458.443817
current_seq = 4148
count = 192
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.443665
last_received_ts = 458.443817
last_seq = 4148
current_ts = 458.460358
current_received_ts = 458.459869
current_seq = 4149
count = 193
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.460358
last_received_ts = 458.459869
last_seq = 4149
current_ts = 458.477020
current_received_ts = 458.477112
current_seq = 4150
count = 194
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 20us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.477020
last_received_ts = 458.477112
last_seq = 4150
current_ts = 458.493683
current_received_ts = 458.493530
current_seq = 4151
count = 195
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.493683
last_received_ts = 458.493530
last_seq = 4151
current_ts = 458.510345
current_received_ts = 458.510223
current_seq = 4152
count = 196
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.510345
last_received_ts = 458.510223
last_seq = 4152
current_ts = 458.527008
current_received_ts = 458.526550
current_seq = 4153
count = 197
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.527008
last_received_ts = 458.526550
last_seq = 4153
current_ts = 458.543671
current_received_ts = 458.543976
current_seq = 4154
count = 198
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 21us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.543671
last_received_ts = 458.543976
last_seq = 4154
current_ts = 458.560333
current_received_ts = 458.560181
current_seq = 4155
count = 199
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.560333
last_received_ts = 458.560181
last_seq = 4155
current_ts = 458.577026
current_received_ts = 458.576935
current_seq = 4156
count = 200
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 66us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.577026
last_received_ts = 458.576935
last_seq = 4156
current_ts = 458.593689
current_received_ts = 458.593842
current_seq = 4157
count = 201
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.593689
last_received_ts = 458.593842
last_seq = 4157
current_ts = 458.610352
current_received_ts = 458.609833
current_seq = 4158
count = 202
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.610352
last_received_ts = 458.609833
last_seq = 4158
current_ts = 458.627014
current_received_ts = 458.626556
current_seq = 4159
count = 203
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.627014
last_received_ts = 458.626556
last_seq = 4159
current_ts = 458.643677
current_received_ts = 458.643463
current_seq = 4160
count = 204
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.643677
last_received_ts = 458.643463
last_seq = 4160
current_ts = 458.660339
current_received_ts = 458.660156
current_seq = 4161
count = 205
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.660339
last_received_ts = 458.660156
last_seq = 4161
current_ts = 458.677032
current_received_ts = 458.676514
current_seq = 4162
count = 206
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.677032
last_received_ts = 458.676514
last_seq = 4162
current_ts = 458.693665
current_received_ts = 458.693756
current_seq = 4163
count = 207
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 21us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.693665
last_received_ts = 458.693756
last_seq = 4163
current_ts = 458.710358
current_received_ts = 458.710175
current_seq = 4164
count = 208
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 26us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.710358
last_received_ts = 458.710175
last_seq = 4164
current_ts = 458.727020
current_received_ts = 458.726532
current_seq = 4165
count = 209
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.727020
last_received_ts = 458.726532
last_seq = 4165
current_ts = 458.743683
current_received_ts = 458.743317
current_seq = 4166
count = 210
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.743683
last_received_ts = 458.743317
last_seq = 4166
current_ts = 458.760345
current_received_ts = 458.760162
current_seq = 4167
count = 211
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.760345
last_received_ts = 458.760162
last_seq = 4167
current_ts = 458.777008
current_received_ts = 458.776550
current_seq = 4168
count = 212
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.777008
last_received_ts = 458.776550
last_seq = 4168
current_ts = 458.793671
current_received_ts = 458.793457
current_seq = 4169
count = 213
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.793671
last_received_ts = 458.793457
last_seq = 4169
current_ts = 458.810333
current_received_ts = 458.809937
current_seq = 4170
count = 214
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.810333
last_received_ts = 458.809937
last_seq = 4170
current_ts = 458.827026
current_received_ts = 458.826569
current_seq = 4171
count = 215
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.827026
last_received_ts = 458.826569
last_seq = 4171
current_ts = 458.843689
current_received_ts = 458.843475
current_seq = 4172
count = 216
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 25us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.843689
last_received_ts = 458.843475
last_seq = 4172
current_ts = 458.860352
current_received_ts = 458.859802
current_seq = 4173
count = 217
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 21us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.860352
last_received_ts = 458.859802
last_seq = 4173
current_ts = 458.877014
current_received_ts = 458.876587
current_seq = 4174
count = 218
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.877014
last_received_ts = 458.876587
last_seq = 4174
current_ts = 458.893677
current_received_ts = 458.893494
current_seq = 4175
count = 219
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.893677
last_received_ts = 458.893494
last_seq = 4175
current_ts = 458.910339
current_received_ts = 458.910217
current_seq = 4176
count = 220
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 25us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.910339
last_received_ts = 458.910217
last_seq = 4176
current_ts = 458.927002
current_received_ts = 458.927002
current_seq = 4177
count = 221
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 21us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.927002
last_received_ts = 458.927002
last_seq = 4177
current_ts = 458.943665
current_received_ts = 458.943451
current_seq = 4178
count = 222
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.943665
last_received_ts = 458.943451
last_seq = 4178
current_ts = 458.960358
current_received_ts = 458.960175
current_seq = 4179
count = 223
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 21us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.960358
last_received_ts = 458.960175
last_seq = 4179
current_ts = 458.977020
current_received_ts = 458.976532
current_seq = 4180
count = 224
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.977020
last_received_ts = 458.976532
last_seq = 4180
current_ts = 458.993683
current_received_ts = 458.993469
current_seq = 4181
count = 225
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 458.993683
last_received_ts = 458.993469
last_seq = 4181
current_ts = 459.010345
current_received_ts = 459.010193
current_seq = 4182
count = 226
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.010345
last_received_ts = 459.010193
last_seq = 4182
current_ts = 459.027008
current_received_ts = 459.026581
current_seq = 4183
count = 227
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.027008
last_received_ts = 459.026581
last_seq = 4183
current_ts = 459.043671
current_received_ts = 459.043518
current_seq = 4184
count = 228
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.043671
last_received_ts = 459.043518
last_seq = 4184
current_ts = 459.060333
current_received_ts = 459.060150
current_seq = 4185
count = 229
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.060333
last_received_ts = 459.060150
last_seq = 4185
current_ts = 459.077026
current_received_ts = 459.076569
current_seq = 4186
count = 230
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.077026
last_received_ts = 459.076569
last_seq = 4186
current_ts = 459.093689
current_received_ts = 459.093964
current_seq = 4187
count = 231
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 21us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.093689
last_received_ts = 459.093964
last_seq = 4187
current_ts = 459.110352
current_received_ts = 459.110168
current_seq = 4188
count = 232
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.110352
last_received_ts = 459.110168
last_seq = 4188
current_ts = 459.127014
current_received_ts = 459.126923
current_seq = 4189
count = 233
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 65us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.127014
last_received_ts = 459.126923
last_seq = 4189
current_ts = 459.143677
current_received_ts = 459.143463
current_seq = 4190
count = 234
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.143677
last_received_ts = 459.143463
last_seq = 4190
current_ts = 459.160339
current_received_ts = 459.159851
current_seq = 4191
count = 235
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.160339
last_received_ts = 459.159851
last_seq = 4191
current_ts = 459.177002
current_received_ts = 459.176941
current_seq = 4192
count = 236
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 51us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.177002
last_received_ts = 459.176941
last_seq = 4192
current_ts = 459.193665
current_received_ts = 459.193481
current_seq = 4193
count = 237
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.193665
last_received_ts = 459.193481
last_seq = 4193
current_ts = 459.210358
current_received_ts = 459.210144
current_seq = 4194
count = 238
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.210358
last_received_ts = 459.210144
last_seq = 4194
current_ts = 459.227020
current_received_ts = 459.226562
current_seq = 4195
count = 239
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.227020
last_received_ts = 459.226562
last_seq = 4195
current_ts = 459.243683
current_received_ts = 459.243500
current_seq = 4196
count = 240
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 21us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.243683
last_received_ts = 459.243500
last_seq = 4196
current_ts = 459.260345
current_received_ts = 459.260468
current_seq = 4197
count = 241
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 20us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.260345
last_received_ts = 459.260468
last_seq = 4197
current_ts = 459.277008
current_received_ts = 459.276550
current_seq = 4198
count = 242
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 25us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.277008
last_received_ts = 459.276550
last_seq = 4198
current_ts = 459.293671
current_received_ts = 459.293518
current_seq = 4199
count = 243
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 40us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.293671
last_received_ts = 459.293518
last_seq = 4199
current_ts = 459.310333
current_received_ts = 459.310150
current_seq = 4200
count = 244
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.310333
last_received_ts = 459.310150
last_seq = 4200
current_ts = 459.327026
current_received_ts = 459.326935
current_seq = 4201
count = 245
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 59us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.327026
last_received_ts = 459.326935
last_seq = 4201
current_ts = 459.343689
current_received_ts = 459.343842
current_seq = 4202
count = 246
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.343689
last_received_ts = 459.343842
last_seq = 4202
current_ts = 459.360352
current_received_ts = 459.359863
current_seq = 4203
count = 247
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 21us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.360352
last_received_ts = 459.359863
last_seq = 4203
current_ts = 459.377014
current_received_ts = 459.377014
current_seq = 4204
count = 248
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 21us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.377014
last_received_ts = 459.377014
last_seq = 4204
current_ts = 459.393677
current_received_ts = 459.393463
current_seq = 4205
count = 249
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 26us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.393677
last_received_ts = 459.393463
last_seq = 4205
current_ts = 459.410339
current_received_ts = 459.410187
current_seq = 4206
count = 250
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.410339
last_received_ts = 459.410187
last_seq = 4206
current_ts = 459.427002
current_received_ts = 459.426819
current_seq = 4207
count = 251
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.427002
last_received_ts = 459.426819
last_seq = 4207
current_ts = 459.443695
current_received_ts = 459.443481
current_seq = 4208
count = 252
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.443695
last_received_ts = 459.443481
last_seq = 4208
current_ts = 459.460327
current_received_ts = 459.460419
current_seq = 4209
count = 253
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 20us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.460327
last_received_ts = 459.460419
last_seq = 4209
current_ts = 459.477020
current_received_ts = 459.476959
current_seq = 4210
count = 254
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.477020
last_received_ts = 459.476959
last_seq = 4210
current_ts = 459.493683
current_received_ts = 459.493530
current_seq = 4211
count = 255
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 25us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.493683
last_received_ts = 459.493530
last_seq = 4211
current_ts = 459.510345
current_received_ts = 459.510193
current_seq = 4212
count = 256
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.510345
last_received_ts = 459.510193
last_seq = 4212
current_ts = 459.527008
current_received_ts = 459.526550
current_seq = 4213
count = 257
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.527008
last_received_ts = 459.526550
last_seq = 4213
current_ts = 459.543671
current_received_ts = 459.543274
current_seq = 4214
count = 258
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 25us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.543671
last_received_ts = 459.543274
last_seq = 4214
current_ts = 459.560333
current_received_ts = 459.560242
current_seq = 4215
count = 259
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 21us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.560333
last_received_ts = 459.560242
last_seq = 4215
current_ts = 459.577026
current_received_ts = 459.576935
current_seq = 4216
count = 260
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 61us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.577026
last_received_ts = 459.576935
last_seq = 4216
current_ts = 459.593689
current_received_ts = 459.593811
current_seq = 4217
count = 261
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.593689
last_received_ts = 459.593811
last_seq = 4217
current_ts = 459.610352
current_received_ts = 459.609863
current_seq = 4218
count = 262
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.610352
last_received_ts = 459.609863
last_seq = 4218
current_ts = 459.627014
current_received_ts = 459.626587
current_seq = 4219
count = 263
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.627014
last_received_ts = 459.626587
last_seq = 4219
current_ts = 459.643677
current_received_ts = 459.643829
current_seq = 4220
count = 264
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.643677
last_received_ts = 459.643829
last_seq = 4220
current_ts = 459.660339
current_received_ts = 459.660217
current_seq = 4221
count = 265
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.660339
last_received_ts = 459.660217
last_seq = 4221
current_ts = 459.677002
current_received_ts = 459.676544
current_seq = 4222
count = 266
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.677002
last_received_ts = 459.676544
last_seq = 4222
current_ts = 459.693695
current_received_ts = 459.693909
current_seq = 4223
count = 267
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 20us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.693695
last_received_ts = 459.693909
last_seq = 4223
current_ts = 459.710358
current_received_ts = 459.710175
current_seq = 4224
count = 268
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 25us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.710358
last_received_ts = 459.710175
last_seq = 4224
current_ts = 459.727020
current_received_ts = 459.726532
current_seq = 4225
count = 269
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.727020
last_received_ts = 459.726532
last_seq = 4225
current_ts = 459.743683
current_received_ts = 459.743469
current_seq = 4226
count = 270
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.743683
last_received_ts = 459.743469
last_seq = 4226
current_ts = 459.760345
current_received_ts = 459.759888
current_seq = 4227
count = 271
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.760345
last_received_ts = 459.759888
last_seq = 4227
current_ts = 459.777008
current_received_ts = 459.776581
current_seq = 4228
count = 272
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.777008
last_received_ts = 459.776581
last_seq = 4228
current_ts = 459.793671
current_received_ts = 459.793854
current_seq = 4229
count = 273
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.793671
last_received_ts = 459.793854
last_seq = 4229
current_ts = 459.810333
current_received_ts = 459.809998
current_seq = 4230
count = 274
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.810333
last_received_ts = 459.809998
last_seq = 4230
current_ts = 459.827026
current_received_ts = 459.826538
current_seq = 4231
count = 275
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.827026
last_received_ts = 459.826538
last_seq = 4231
current_ts = 459.843689
current_received_ts = 459.843933
current_seq = 4232
count = 276
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 54us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.843689
last_received_ts = 459.843933
last_seq = 4232
current_ts = 459.860352
current_received_ts = 459.860260
current_seq = 4233
count = 277
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 24us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.860352
last_received_ts = 459.860260
last_seq = 4233
current_ts = 459.877014
current_received_ts = 459.876556
current_seq = 4234
count = 278
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.877014
last_received_ts = 459.876556
last_seq = 4234
current_ts = 459.893677
current_received_ts = 459.893799
current_seq = 4235
count = 279
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 22us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.893677
last_received_ts = 459.893799
last_seq = 4235
current_ts = 459.910339
current_received_ts = 459.909821
current_seq = 4236
count = 280
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.910339
last_received_ts = 459.909821
last_seq = 4236
current_ts = 459.927002
current_received_ts = 459.926575
current_seq = 4237
count = 281
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 23us
(kms_flip:2529) DEBUG: name = flip
last_ts = 459.927002
last_received_ts = 459.926575
last_seq = 4237
current_ts = 459.943665
current_received_ts = 459.943970
current_seq = 4238
count = 282
seq_step = 1
(kms_flip:2529) DEBUG: Vblank took 1250us
(kms_flip:2529) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2529) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2529) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2529) igt_core-INFO: Stack trace:
(kms_flip:2529) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2529) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:2529) igt_core-INFO:   #2 ../tests/kms_flip.c:1919 run_test()
(kms_flip:2529) igt_core-INFO:   #3 ../tests/kms_flip.c:2219 __igt_unique____real_main2104()
(kms_flip:2529) igt_core-INFO:   #4 ../tests/kms_flip.c:2104 main()
(kms_flip:2529) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2529) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2529) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A1: FAIL (5.215s)

Dmesg

<6> [454.817287] [IGT] kms_flip: starting dynamic subtest C-HDMI-A1

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

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

<7> [454.859398] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A]

<7> [454.860718] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [454.882586] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:121:pipe B] releasing PORT PLL B

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

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

<7> [454.883969] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:121:pipe B] min cdclk: 192000 kHz -> 0 kHz

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

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

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

<7> [454.885650] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:121:pipe B] enable: no [modeset]

<7> [454.886032] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:79:plane 1B] fb: [NOFB], visible: no

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

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

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

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

<7> [454.888155] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:166:HDMI-A-1][ENCODER:165:DDI B/PHY B] Disable audio codec on [CRTC:121:pipe B]

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

<7> [454.911718] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B

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

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

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

<7> [455.033184] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x2, on? 1) for [CRTC:121:pipe B]

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

<7> [455.037587] 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> [455.038031] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B]

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

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

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

<7> [455.042436] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:121:pipe B]

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

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

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

<7> [455.044622] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C]

<7> [455.044880] 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> [455.047735] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C]

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

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

<7> [455.048555] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:164:pipe C] hw max bpp: 36, pipe bpp: 36, dithering: 0

<7> [455.048940] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:165:DDI B/PHY B] [CRTC:164:pipe C]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [455.092630] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:122:plane 1C] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988

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

<7> [455.093382] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5,*wm6,*wm7,*twm, swm, stwm

<7> [455.095613] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0

<7> [455.096097] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0

<7> [455.096494] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] 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> [455.097296] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] min_ddb_uv 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

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

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

<7> [455.098859] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:164:pipe C] reserving PORT PLL B

<7> [455.099285] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:164:pipe C] enable: yes [modeset]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [455.105999] 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> [455.106383] 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> [455.106862] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

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

<7> [455.107729] 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> [455.108136] 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> [455.108512] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

<7> [455.111456] 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> [455.112088] 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> [455.112471] 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> [455.113293] 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> [455.113788] 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> [455.114169] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pixel rate 148500, min cdclk 192000, min voltage level 0

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

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

<7> [455.115622] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [455.132488] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL B (active 0x4, on? 0) for [CRTC:164:pipe C]

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

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

<7> [455.135383] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe C

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

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

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

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

<7> [455.173160] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:164:pipe C]

<6> [460.033567] [IGT] kms_flip: finished subtest C-HDMI-A1, FAIL

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