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

Detail	Value
Duration	2.57 seconds
Hostname	shard-tglu-7
Igt-Version	IGT-Version: 2.4-g4568b2c14 (x86_64) (Linux: 7.1.0-rc1-CI_DRM_18375-ge066eb26712b+ x86_64)
Out	Starting dynamic subtest: C-HDMI-A1 1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest C-HDMI-A1: FAIL (2.567s)
Err	Starting dynamic subtest: C-HDMI-A1 (kms_flip:2199) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2199) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2199) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest C-HDMI-A1 failed. ** DEBUG (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 200.489838 last_received_ts = 200.489517 last_seq = 164 current_ts = 200.498169 current_received_ts = 200.497818 current_seq = 165 count = 160 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 34us (kms_flip:2199) DEBUG: name = flip last_ts = 200.498169 last_received_ts = 200.497818 last_seq = 165 current_ts = 200.506500 current_received_ts = 200.506241 current_seq = 166 count = 161 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 200.506500 last_received_ts = 200.506241 last_seq = 166 current_ts = 200.514847 current_received_ts = 200.514465 current_seq = 167 count = 162 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 200.514847 last_received_ts = 200.514465 last_seq = 167 current_ts = 200.523178 current_received_ts = 200.522858 current_seq = 168 count = 163 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 200.523178 last_received_ts = 200.522858 last_seq = 168 current_ts = 200.531509 current_received_ts = 200.531174 current_seq = 169 count = 164 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 23us (kms_flip:2199) DEBUG: name = flip last_ts = 200.531509 last_received_ts = 200.531174 last_seq = 169 current_ts = 200.539841 current_received_ts = 200.539536 current_seq = 170 count = 165 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 26us (kms_flip:2199) DEBUG: name = flip last_ts = 200.539841 last_received_ts = 200.539536 last_seq = 170 current_ts = 200.548172 current_received_ts = 200.547928 current_seq = 171 count = 166 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 25us (kms_flip:2199) DEBUG: name = flip last_ts = 200.548172 last_received_ts = 200.547928 last_seq = 171 current_ts = 200.556519 current_received_ts = 200.556229 current_seq = 172 count = 167 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 23us (kms_flip:2199) DEBUG: name = flip last_ts = 200.556519 last_received_ts = 200.556229 last_seq = 172 current_ts = 200.564850 current_received_ts = 200.564575 current_seq = 173 count = 168 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 200.564850 last_received_ts = 200.564575 last_seq = 173 current_ts = 200.573181 current_received_ts = 200.572845 current_seq = 174 count = 169 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 25us (kms_flip:2199) DEBUG: name = flip last_ts = 200.573181 last_received_ts = 200.572845 last_seq = 174 current_ts = 200.581512 current_received_ts = 200.581238 current_seq = 175 count = 170 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 26us (kms_flip:2199) DEBUG: name = flip last_ts = 200.581512 last_received_ts = 200.581238 last_seq = 175 current_ts = 200.589844 current_received_ts = 200.589508 current_seq = 176 count = 171 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 25us (kms_flip:2199) DEBUG: name = flip last_ts = 200.589844 last_received_ts = 200.589508 last_seq = 176 current_ts = 200.598190 current_received_ts = 200.597961 current_seq = 177 count = 172 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 53us (kms_flip:2199) DEBUG: name = flip last_ts = 200.598190 last_received_ts = 200.597961 last_seq = 177 current_ts = 200.606522 current_received_ts = 200.606216 current_seq = 178 count = 173 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 200.606522 last_received_ts = 200.606216 last_seq = 178 current_ts = 200.614853 current_received_ts = 200.614532 current_seq = 179 count = 174 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 33us (kms_flip:2199) DEBUG: name = flip last_ts = 200.614853 last_received_ts = 200.614532 last_seq = 179 current_ts = 200.623184 current_received_ts = 200.622849 current_seq = 180 count = 175 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 25us (kms_flip:2199) DEBUG: name = flip last_ts = 200.623184 last_received_ts = 200.622849 last_seq = 180 current_ts = 200.631516 current_received_ts = 200.631165 current_seq = 181 count = 176 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 23us (kms_flip:2199) DEBUG: name = flip last_ts = 200.631516 last_received_ts = 200.631165 last_seq = 181 current_ts = 200.639862 current_received_ts = 200.639526 current_seq = 182 count = 177 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 200.639862 last_received_ts = 200.639526 last_seq = 182 current_ts = 200.648193 current_received_ts = 200.647797 current_seq = 183 count = 178 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 200.648193 last_received_ts = 200.647797 last_seq = 183 current_ts = 200.656525 current_received_ts = 200.656219 current_seq = 184 count = 179 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 31us (kms_flip:2199) DEBUG: name = flip last_ts = 200.656525 last_received_ts = 200.656219 last_seq = 184 current_ts = 200.664856 current_received_ts = 200.664474 current_seq = 185 count = 180 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 200.664856 last_received_ts = 200.664474 last_seq = 185 current_ts = 200.673203 current_received_ts = 200.672882 current_seq = 186 count = 181 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 200.673203 last_received_ts = 200.672882 last_seq = 186 current_ts = 200.681534 current_received_ts = 200.681183 current_seq = 187 count = 182 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 26us (kms_flip:2199) DEBUG: name = flip last_ts = 200.681534 last_received_ts = 200.681183 last_seq = 187 current_ts = 200.689865 current_received_ts = 200.689529 current_seq = 188 count = 183 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 200.689865 last_received_ts = 200.689529 last_seq = 188 current_ts = 200.698196 current_received_ts = 200.697983 current_seq = 189 count = 184 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 200.698196 last_received_ts = 200.697983 last_seq = 189 current_ts = 200.706528 current_received_ts = 200.706223 current_seq = 190 count = 185 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 200.706528 last_received_ts = 200.706223 last_seq = 190 current_ts = 200.714874 current_received_ts = 200.714539 current_seq = 191 count = 186 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 30us (kms_flip:2199) DEBUG: name = flip last_ts = 200.714874 last_received_ts = 200.714539 last_seq = 191 current_ts = 200.723206 current_received_ts = 200.722855 current_seq = 192 count = 187 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 25us (kms_flip:2199) DEBUG: name = flip last_ts = 200.723206 last_received_ts = 200.722855 last_seq = 192 current_ts = 200.731537 current_received_ts = 200.731232 current_seq = 193 count = 188 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 200.731537 last_received_ts = 200.731232 last_seq = 193 current_ts = 200.739868 current_received_ts = 200.739548 current_seq = 194 count = 189 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 26us (kms_flip:2199) DEBUG: name = flip last_ts = 200.739868 last_received_ts = 200.739548 last_seq = 194 current_ts = 200.748215 current_received_ts = 200.747849 current_seq = 195 count = 190 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 23us (kms_flip:2199) DEBUG: name = flip last_ts = 200.748215 last_received_ts = 200.747849 last_seq = 195 current_ts = 200.756546 current_received_ts = 200.756226 current_seq = 196 count = 191 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 200.756546 last_received_ts = 200.756226 last_seq = 196 current_ts = 200.764877 current_received_ts = 200.764526 current_seq = 197 count = 192 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 23us (kms_flip:2199) DEBUG: name = flip last_ts = 200.764877 last_received_ts = 200.764526 last_seq = 197 current_ts = 200.773209 current_received_ts = 200.773087 current_seq = 198 count = 193 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 26us (kms_flip:2199) DEBUG: name = flip last_ts = 200.773209 last_received_ts = 200.773087 last_seq = 198 current_ts = 200.781540 current_received_ts = 200.781189 current_seq = 199 count = 194 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 23us (kms_flip:2199) DEBUG: name = flip last_ts = 200.781540 last_received_ts = 200.781189 last_seq = 199 current_ts = 200.789886 current_received_ts = 200.789642 current_seq = 200 count = 195 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 35us (kms_flip:2199) DEBUG: name = flip last_ts = 200.789886 last_received_ts = 200.789642 last_seq = 200 current_ts = 200.798218 current_received_ts = 200.797852 current_seq = 201 count = 196 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 200.798218 last_received_ts = 200.797852 last_seq = 201 current_ts = 200.806549 current_received_ts = 200.806274 current_seq = 202 count = 197 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 200.806549 last_received_ts = 200.806274 last_seq = 202 current_ts = 200.814880 current_received_ts = 200.814499 current_seq = 203 count = 198 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 23us (kms_flip:2199) DEBUG: name = flip last_ts = 200.814880 last_received_ts = 200.814499 last_seq = 203 current_ts = 200.823212 current_received_ts = 200.822861 current_seq = 204 count = 199 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 26us (kms_flip:2199) DEBUG: name = flip last_ts = 200.823212 last_received_ts = 200.822861 last_seq = 204 current_ts = 200.831558 current_received_ts = 200.831284 current_seq = 205 count = 200 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 200.831558 last_received_ts = 200.831284 last_seq = 205 current_ts = 200.839890 current_received_ts = 200.839554 current_seq = 206 count = 201 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 200.839890 last_received_ts = 200.839554 last_seq = 206 current_ts = 200.848221 current_received_ts = 200.847900 current_seq = 207 count = 202 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 200.848221 last_received_ts = 200.847900 last_seq = 207 current_ts = 200.856567 current_received_ts = 200.856277 current_seq = 208 count = 203 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 37us (kms_flip:2199) DEBUG: name = flip last_ts = 200.856567 last_received_ts = 200.856277 last_seq = 208 current_ts = 200.864883 current_received_ts = 200.864563 current_seq = 209 count = 204 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 200.864883 last_received_ts = 200.864563 last_seq = 209 current_ts = 200.873230 current_received_ts = 200.872879 current_seq = 210 count = 205 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 200.873230 last_received_ts = 200.872879 last_seq = 210 current_ts = 200.881561 current_received_ts = 200.881241 current_seq = 211 count = 206 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 200.881561 last_received_ts = 200.881241 last_seq = 211 current_ts = 200.889893 current_received_ts = 200.889557 current_seq = 212 count = 207 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 200.889893 last_received_ts = 200.889557 last_seq = 212 current_ts = 200.898224 current_received_ts = 200.898087 current_seq = 213 count = 208 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 200.898224 last_received_ts = 200.898087 last_seq = 213 current_ts = 200.906570 current_received_ts = 200.906281 current_seq = 214 count = 209 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 200.906570 last_received_ts = 200.906281 last_seq = 214 current_ts = 200.914902 current_received_ts = 200.914658 current_seq = 215 count = 210 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 200.914902 last_received_ts = 200.914658 last_seq = 215 current_ts = 200.923233 current_received_ts = 200.922852 current_seq = 216 count = 211 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 25us (kms_flip:2199) DEBUG: name = flip last_ts = 200.923233 last_received_ts = 200.922852 last_seq = 216 current_ts = 200.931564 current_received_ts = 200.931305 current_seq = 217 count = 212 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 200.931564 last_received_ts = 200.931305 last_seq = 217 current_ts = 200.939896 current_received_ts = 200.939545 current_seq = 218 count = 213 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 37us (kms_flip:2199) DEBUG: name = flip last_ts = 200.939896 last_received_ts = 200.939545 last_seq = 218 current_ts = 200.948242 current_received_ts = 200.947861 current_seq = 219 count = 214 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 22us (kms_flip:2199) DEBUG: name = flip last_ts = 200.948242 last_received_ts = 200.947861 last_seq = 219 current_ts = 200.956573 current_received_ts = 200.956299 current_seq = 220 count = 215 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 32us (kms_flip:2199) DEBUG: name = flip last_ts = 200.956573 last_received_ts = 200.956299 last_seq = 220 current_ts = 200.964905 current_received_ts = 200.964554 current_seq = 221 count = 216 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 23us (kms_flip:2199) DEBUG: name = flip last_ts = 200.964905 last_received_ts = 200.964554 last_seq = 221 current_ts = 200.973251 current_received_ts = 200.973053 current_seq = 222 count = 217 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 200.973251 last_received_ts = 200.973053 last_seq = 222 current_ts = 200.981567 current_received_ts = 200.981247 current_seq = 223 count = 218 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 25us (kms_flip:2199) DEBUG: name = flip last_ts = 200.981567 last_received_ts = 200.981247 last_seq = 223 current_ts = 200.989914 current_received_ts = 200.989578 current_seq = 224 count = 219 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 200.989914 last_received_ts = 200.989578 last_seq = 224 current_ts = 200.998245 current_received_ts = 200.997910 current_seq = 225 count = 220 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 30us (kms_flip:2199) DEBUG: name = flip last_ts = 200.998245 last_received_ts = 200.997910 last_seq = 225 current_ts = 201.006577 current_received_ts = 201.006256 current_seq = 226 count = 221 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 201.006577 last_received_ts = 201.006256 last_seq = 226 current_ts = 201.014908 current_received_ts = 201.014572 current_seq = 227 count = 222 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 23us (kms_flip:2199) DEBUG: name = flip last_ts = 201.014908 last_received_ts = 201.014572 last_seq = 227 current_ts = 201.023239 current_received_ts = 201.022919 current_seq = 228 count = 223 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 25us (kms_flip:2199) DEBUG: name = flip last_ts = 201.023239 last_received_ts = 201.022919 last_seq = 228 current_ts = 201.031586 current_received_ts = 201.031342 current_seq = 229 count = 224 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 201.031586 last_received_ts = 201.031342 last_seq = 229 current_ts = 201.039917 current_received_ts = 201.039566 current_seq = 230 count = 225 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 201.039917 last_received_ts = 201.039566 last_seq = 230 current_ts = 201.048248 current_received_ts = 201.047913 current_seq = 231 count = 226 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 201.048248 last_received_ts = 201.047913 last_seq = 231 current_ts = 201.056580 current_received_ts = 201.056229 current_seq = 232 count = 227 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 25us (kms_flip:2199) DEBUG: name = flip last_ts = 201.056580 last_received_ts = 201.056229 last_seq = 232 current_ts = 201.064926 current_received_ts = 201.064590 current_seq = 233 count = 228 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 201.064926 last_received_ts = 201.064590 last_seq = 233 current_ts = 201.073257 current_received_ts = 201.072876 current_seq = 234 count = 229 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 201.073257 last_received_ts = 201.072876 last_seq = 234 current_ts = 201.081589 current_received_ts = 201.081329 current_seq = 235 count = 230 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 201.081589 last_received_ts = 201.081329 last_seq = 235 current_ts = 201.089920 current_received_ts = 201.089554 current_seq = 236 count = 231 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 201.089920 last_received_ts = 201.089554 last_seq = 236 current_ts = 201.098267 current_received_ts = 201.097946 current_seq = 237 count = 232 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 43us (kms_flip:2199) DEBUG: name = flip last_ts = 201.098267 last_received_ts = 201.097946 last_seq = 237 current_ts = 201.106598 current_received_ts = 201.106277 current_seq = 238 count = 233 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 52us (kms_flip:2199) DEBUG: name = flip last_ts = 201.106598 last_received_ts = 201.106277 last_seq = 238 current_ts = 201.114929 current_received_ts = 201.114655 current_seq = 239 count = 234 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 201.114929 last_received_ts = 201.114655 last_seq = 239 current_ts = 201.123260 current_received_ts = 201.122925 current_seq = 240 count = 235 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 25us (kms_flip:2199) DEBUG: name = flip last_ts = 201.123260 last_received_ts = 201.122925 last_seq = 240 current_ts = 201.131592 current_received_ts = 201.131271 current_seq = 241 count = 236 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 201.131592 last_received_ts = 201.131271 last_seq = 241 current_ts = 201.139938 current_received_ts = 201.139603 current_seq = 242 count = 237 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 32us (kms_flip:2199) DEBUG: name = flip last_ts = 201.139938 last_received_ts = 201.139603 last_seq = 242 current_ts = 201.148270 current_received_ts = 201.148056 current_seq = 243 count = 238 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 201.148270 last_received_ts = 201.148056 last_seq = 243 current_ts = 201.156601 current_received_ts = 201.156281 current_seq = 244 count = 239 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 32us (kms_flip:2199) DEBUG: name = flip last_ts = 201.156601 last_received_ts = 201.156281 last_seq = 244 current_ts = 201.164932 current_received_ts = 201.164597 current_seq = 245 count = 240 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 201.164932 last_received_ts = 201.164597 last_seq = 245 current_ts = 201.173279 current_received_ts = 201.172958 current_seq = 246 count = 241 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 43us (kms_flip:2199) DEBUG: name = flip last_ts = 201.173279 last_received_ts = 201.172958 last_seq = 246 current_ts = 201.181610 current_received_ts = 201.181274 current_seq = 247 count = 242 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 33us (kms_flip:2199) DEBUG: name = flip last_ts = 201.181610 last_received_ts = 201.181274 last_seq = 247 current_ts = 201.189941 current_received_ts = 201.189728 current_seq = 248 count = 243 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 26us (kms_flip:2199) DEBUG: name = flip last_ts = 201.189941 last_received_ts = 201.189728 last_seq = 248 current_ts = 201.198273 current_received_ts = 201.197891 current_seq = 249 count = 244 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 201.198273 last_received_ts = 201.197891 last_seq = 249 current_ts = 201.206604 current_received_ts = 201.206345 current_seq = 250 count = 245 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 201.206604 last_received_ts = 201.206345 last_seq = 250 current_ts = 201.214951 current_received_ts = 201.214554 current_seq = 251 count = 246 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 201.214951 last_received_ts = 201.214554 last_seq = 251 current_ts = 201.223282 current_received_ts = 201.222900 current_seq = 252 count = 247 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 201.223282 last_received_ts = 201.222900 last_seq = 252 current_ts = 201.231613 current_received_ts = 201.231308 current_seq = 253 count = 248 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 31us (kms_flip:2199) DEBUG: name = flip last_ts = 201.231613 last_received_ts = 201.231308 last_seq = 253 current_ts = 201.239944 current_received_ts = 201.239563 current_seq = 254 count = 249 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 201.239944 last_received_ts = 201.239563 last_seq = 254 current_ts = 201.248291 current_received_ts = 201.247955 current_seq = 255 count = 250 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 43us (kms_flip:2199) DEBUG: name = flip last_ts = 201.248291 last_received_ts = 201.247955 last_seq = 255 current_ts = 201.256622 current_received_ts = 201.256302 current_seq = 256 count = 251 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 201.256622 last_received_ts = 201.256302 last_seq = 256 current_ts = 201.264954 current_received_ts = 201.264664 current_seq = 257 count = 252 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 201.264954 last_received_ts = 201.264664 last_seq = 257 current_ts = 201.273285 current_received_ts = 201.272919 current_seq = 258 count = 253 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 30us (kms_flip:2199) DEBUG: name = flip last_ts = 201.273285 last_received_ts = 201.272919 last_seq = 258 current_ts = 201.281616 current_received_ts = 201.281281 current_seq = 259 count = 254 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 201.281616 last_received_ts = 201.281281 last_seq = 259 current_ts = 201.289948 current_received_ts = 201.289627 current_seq = 260 count = 255 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 30us (kms_flip:2199) DEBUG: name = flip last_ts = 201.289948 last_received_ts = 201.289627 last_seq = 260 current_ts = 201.298294 current_received_ts = 201.298065 current_seq = 261 count = 256 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 201.298294 last_received_ts = 201.298065 last_seq = 261 current_ts = 201.306625 current_received_ts = 201.306305 current_seq = 262 count = 257 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 201.306625 last_received_ts = 201.306305 last_seq = 262 current_ts = 201.314957 current_received_ts = 201.314667 current_seq = 263 count = 258 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 26us (kms_flip:2199) DEBUG: name = flip last_ts = 201.314957 last_received_ts = 201.314667 last_seq = 263 current_ts = 201.323303 current_received_ts = 201.322922 current_seq = 264 count = 259 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 201.323303 last_received_ts = 201.322922 last_seq = 264 current_ts = 201.331619 current_received_ts = 201.331314 current_seq = 265 count = 260 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 36us (kms_flip:2199) DEBUG: name = flip last_ts = 201.331619 last_received_ts = 201.331314 last_seq = 265 current_ts = 201.339966 current_received_ts = 201.339645 current_seq = 266 count = 261 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 201.339966 last_received_ts = 201.339645 last_seq = 266 current_ts = 201.348297 current_received_ts = 201.347916 current_seq = 267 count = 262 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 26us (kms_flip:2199) DEBUG: name = flip last_ts = 201.348297 last_received_ts = 201.347916 last_seq = 267 current_ts = 201.356628 current_received_ts = 201.356308 current_seq = 268 count = 263 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 201.356628 last_received_ts = 201.356308 last_seq = 268 current_ts = 201.364960 current_received_ts = 201.364578 current_seq = 269 count = 264 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 201.364960 last_received_ts = 201.364578 last_seq = 269 current_ts = 201.373306 current_received_ts = 201.372910 current_seq = 270 count = 265 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 31us (kms_flip:2199) DEBUG: name = flip last_ts = 201.373306 last_received_ts = 201.372910 last_seq = 270 current_ts = 201.381638 current_received_ts = 201.381317 current_seq = 271 count = 266 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 201.381638 last_received_ts = 201.381317 last_seq = 271 current_ts = 201.389969 current_received_ts = 201.389633 current_seq = 272 count = 267 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 23us (kms_flip:2199) DEBUG: name = flip last_ts = 201.389969 last_received_ts = 201.389633 last_seq = 272 current_ts = 201.398300 current_received_ts = 201.397980 current_seq = 273 count = 268 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 201.398300 last_received_ts = 201.397980 last_seq = 273 current_ts = 201.406631 current_received_ts = 201.406311 current_seq = 274 count = 269 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 201.406631 last_received_ts = 201.406311 last_seq = 274 current_ts = 201.414978 current_received_ts = 201.414734 current_seq = 275 count = 270 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 26us (kms_flip:2199) DEBUG: name = flip last_ts = 201.414978 last_received_ts = 201.414734 last_seq = 275 current_ts = 201.423309 current_received_ts = 201.422928 current_seq = 276 count = 271 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 201.423309 last_received_ts = 201.422928 last_seq = 276 current_ts = 201.431641 current_received_ts = 201.431320 current_seq = 277 count = 272 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 29us (kms_flip:2199) DEBUG: name = flip last_ts = 201.431641 last_received_ts = 201.431320 last_seq = 277 current_ts = 201.439972 current_received_ts = 201.439621 current_seq = 278 count = 273 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 22us (kms_flip:2199) DEBUG: name = flip last_ts = 201.439972 last_received_ts = 201.439621 last_seq = 278 current_ts = 201.448303 current_received_ts = 201.448105 current_seq = 279 count = 274 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 28us (kms_flip:2199) DEBUG: name = flip last_ts = 201.448303 last_received_ts = 201.448105 last_seq = 279 current_ts = 201.456650 current_received_ts = 201.456299 current_seq = 280 count = 275 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 27us (kms_flip:2199) DEBUG: name = flip last_ts = 201.456650 last_received_ts = 201.456299 last_seq = 280 current_ts = 201.464981 current_received_ts = 201.464661 current_seq = 281 count = 276 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 37us (kms_flip:2199) DEBUG: name = flip last_ts = 201.464981 last_received_ts = 201.464661 last_seq = 281 current_ts = 201.473312 current_received_ts = 201.472961 current_seq = 282 count = 277 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 67us (kms_flip:2199) DEBUG: name = flip last_ts = 201.473312 last_received_ts = 201.472961 last_seq = 282 current_ts = 201.481659 current_received_ts = 201.481354 current_seq = 283 count = 278 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 24us (kms_flip:2199) DEBUG: name = flip last_ts = 201.481659 last_received_ts = 201.481354 last_seq = 283 current_ts = 201.489990 current_received_ts = 201.489624 current_seq = 284 count = 279 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 30us (kms_flip:2199) DEBUG: name = flip last_ts = 201.489990 last_received_ts = 201.489624 last_seq = 284 current_ts = 201.498322 current_received_ts = 201.497971 current_seq = 285 count = 280 seq_step = 1 (kms_flip:2199) DEBUG: Vblank took 737us (kms_flip:2199) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2199) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2199) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:2199) igt_core-INFO: Stack trace: (kms_flip:2199) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2199) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:2199) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:2199) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() (kms_flip:2199) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:2199) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2199) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2199) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest C-HDMI-A1: FAIL (2.567s)
Dmesg	<6> [199.047543] [IGT] kms_flip: starting dynamic subtest C-HDMI-A1 <7> [199.048539] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:637] <7> [199.048988] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:638] <7> [199.071044] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:171:pipe A] <7> [199.071206] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe B] <7> [199.071329] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [199.071620] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [199.071861] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1) <7> [199.072099] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in lane_count (expected 4, found 0) <7> [199.072421] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [199.072659] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [199.072894] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [199.073126] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2080, found 0) <7> [199.073377] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [199.073620] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2080, found 0) <7> [199.073851] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1968, found 0) <7> [199.074228] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2000, found 0) <7> [199.074492] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [199.074722] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [199.074953] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [199.075181] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [199.075435] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1144, found 0) <7> [199.075665] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1144, found 0) <7> [199.075895] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [199.076124] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2080, found 0) <7> [199.076374] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [199.076604] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2080, found 0) <7> [199.076833] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1968, found 0) <7> [199.077080] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2000, found 0) <7> [199.077375] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [199.077612] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [199.077853] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [199.078091] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [199.078334] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1144, found 0) <7> [199.078566] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1144, found 0) <7> [199.078799] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [199.079031] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [199.079268] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [199.079502] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [199.079732] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in has_infoframe (expected yes, found no) <7> [199.079967] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [199.080196] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 285500, found 0) <7> [199.080452] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 285500, found 0) <7> [199.080683] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in port_clock (expected 285500, found 0) <7> [199.080915] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [199.081149] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in avi infoframe <7> [199.081433] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [199.081667] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [199.081671] i915 0000:00:02.0: colorspace: RGB <7> [199.081674] i915 0000:00:02.0: scan mode: Underscan <7> [199.081677] i915 0000:00:02.0: colorimetry: No Data <7> [199.081680] i915 0000:00:02.0: picture aspect: No Data <7> [199.081683] i915 0000:00:02.0: active aspect: Same as Picture <7> [199.081686] i915 0000:00:02.0: itc: No Data <7> [199.081689] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [199.081691] i915 0000:00:02.0: quantization range: Full <7> [199.081694] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [199.081697] i915 0000:00:02.0: video code: 0 <7> [199.081699] i915 0000:00:02.0: ycc quantization range: Full <7> [199.081702] i915 0000:00:02.0: hdmi content type: Graphics <7> [199.081705] i915 0000:00:02.0: pixel repeat: 0 <7> [199.081707] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [199.081711] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [199.081939] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in spd infoframe <7> [199.082169] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [199.082392] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [199.082395] i915 0000:00:02.0: vendor: Intel <7> [199.082398] i915 0000:00:02.0: product: Integrated gfx <7> [199.082401] i915 0000:00:02.0: source device information: PC General (0x9) <7> [199.082404] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [199.082632] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:309:pipe B] fastset requirement not met in hdmi infoframe <7> [199.082862] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [199.083091] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [199.083095] i915 0000:00:02.0: empty frame <7> [199.083097] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [199.083339] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:309:pipe B] fastset requirement not met, forcing full modeset <7> [199.083572] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:309:pipe B] releasing DPLL 0 <7> [199.083850] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no <7> [199.084081] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:309:pipe B] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x2 -> 0x0 <7> [199.084390] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:303:cursor B] ddb (1993 - 2048) -> ( 0 - 0), size 55 -> 0 <7> [199.084655] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:309:pipe B] min cdclk: 192000 kHz -> 0 kHz <7> [199.084936] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [199.085170] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz <7> [199.085423] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [199.085663] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:309:pipe B] enable: no [modeset] <7> [199.085904] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:173:plane 1B] fb: [NOFB], visible: no <7> [199.086138] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:203:plane 2B] fb: [NOFB], visible: no <7> [199.086389] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:233:plane 3B] fb: [NOFB], visible: no <7> [199.086625] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:263:plane 4B] fb: [NOFB], visible: no <7> [199.086855] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:273:plane 5B] fb: [NOFB], visible: no <7> [199.087085] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:283:plane 6B] fb: [NOFB], visible: no <7> [199.087319] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:293:plane 7B] fb: [NOFB], visible: no <7> [199.087551] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:303:cursor B] fb: [NOFB], visible: no <7> [199.087921] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:588:HDMI-A-1][ENCODER:587:DDI B/PHY B] Disable audio codec on [CRTC:309:pipe B] <7> [199.103924] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [199.106220] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:588:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10 <7> [199.106819] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [199.106971] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [199.107518] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [199.107806] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:588:HDMI-A-1] Failed to read TMDS config: -6 <7> [199.107823] i915 0000:00:02.0: [drm:intel_ddi_disable [i915]] [CONNECTOR:588:HDMI-A-1] Failed to reset sink scrambling/TMDS bit clock ratio <7> [199.108002] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B <7> [199.113352] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [199.113613] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x2, on? 1) for [CRTC:309:pipe B] <7> [199.113804] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0 <7> [199.113982] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 172800 kHz, VCO 345600 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [199.114241] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI B/PHY B] <7> [199.114445] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DDI TC1/PHY TC1] <7> [199.114632] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST A] <7> [199.114797] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST B] <7> [199.114958] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST C] <7> [199.115117] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:602:DP-MST D] <7> [199.115286] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DDI TC2/PHY TC2] <7> [199.115471] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST A] <7> [199.115628] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST B] <7> [199.115786] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST C] <7> [199.115942] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST D] <7> [199.116100] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DDI TC3/PHY TC3] <7> [199.116265] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST A] <7> [199.116442] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST B] <7> [199.116599] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST C] <7> [199.116757] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:621:DP-MST D] <7> [199.116919] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DDI TC4/PHY TC4] <7> [199.117083] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST A] <7> [199.117244] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST B] <7> [199.117478] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST C] <7> [199.117668] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:630:DP-MST D] <7> [199.117831] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:588:HDMI-A-1] <7> [199.118172] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [199.118407] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_3 <7> [199.118595] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2 <7> [199.118829] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:309:pipe B] <7> [199.119305] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe C] <7> [199.119467] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:585:pipe D] <7> [199.119581] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe C] <7> [199.119611] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:588:HDMI-A-1] <7> [199.119682] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:588:HDMI-A-1] Limiting target display pipe bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36) <7> [199.119865] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [199.120026] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:447:pipe C] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [199.120193] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:587:DDI B/PHY B] [CRTC:447:pipe C] <7> [199.120367] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [199.120533] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [199.120782] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [199.120951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [199.121116] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [199.121287] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [199.121450] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [199.121611] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2080) <7> [199.121772] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [199.121930] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2080) <7> [199.122090] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1968) <7> [199.122249] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2000) <7> [199.122434] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [199.122612] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [199.122770] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [199.122928] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [199.123086] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1144) <7> [199.123244] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1144) <7> [199.123424] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [199.123604] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2080) <7> [199.123762] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [199.123922] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2080) <7> [199.124080] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1968) <7> [199.124239] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2000) <7> [199.124420] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [199.124591] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [199.124750] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [199.124908] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [199.125066] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1144) <7> [199.125224] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1144) <7> [199.125400] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [199.125571] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [199.125736] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [199.125954] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [199.126115] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in has_infoframe (expected no, found yes) <7> [199.126295] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in dpll_hw_state <7> [199.126476] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [199.126634] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: cfgcr0: 0x0, cfgcr1: 0x0, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0 <7> [199.126795] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [199.126954] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: cfgcr0: 0x1801be, cfgcr1: 0x488, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0 <7> [199.127114] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [199.127282] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 285500) <7> [199.127455] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 285500) <7> [199.127661] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in port_clock (expected 0, found 285500) <7> [199.127819] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [199.127986] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in avi infoframe <7> [199.128153] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [199.128326] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [199.128497] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [199.128499] i915 0000:00:02.0: colorspace: RGB <7> [199.128501] i915 0000:00:02.0: scan mode: Underscan <7> [199.128503] i915 0000:00:02.0: colorimetry: No Data <7> [199.128504] i915 0000:00:02.0: picture aspect: No Data <7> [199.128506] i915 0000:00:02.0: active aspect: Same as Picture <7> [199.128507] i915 0000:00:02.0: itc: No Data <7> [199.128509] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [199.128510] i915 0000:00:02.0: quantization range: Full <7> [199.128512] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [199.128513] i915 0000:00:02.0: video code: 0 <7> [199.128515] i915 0000:00:02.0: ycc quantization range: Full <7> [199.128516] i915 0000:00:02.0: hdmi content type: Graphics <7> [199.128518] i915 0000:00:02.0: pixel repeat: 0 <7> [199.128519] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [199.128521] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in spd infoframe <7> [199.128682] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [199.128841] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [199.128999] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [199.129001] i915 0000:00:02.0: vendor: Intel <7> [199.129003] i915 0000:00:02.0: product: Integrated gfx <7> [199.129004] i915 0000:00:02.0: source device information: PC General (0x9) <7> [199.129006] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in hdmi infoframe <7> [199.129165] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [199.129375] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [199.129565] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [199.129567] i915 0000:00:02.0: empty frame <7> [199.129569] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:447:pipe C] fastset requirement not met, forcing full modeset <7> [199.129767] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no <7> [199.129928] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:447:pipe C] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4 <7> [199.130128] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:311:plane 1C] ddb ( 0 - 0) -> ( 0 - 1993), size 0 -> 1993 <7> [199.130300] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:441:cursor C] ddb ( 0 - 0) -> (1993 - 2048), size 0 -> 55 <7> [199.130472] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311: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> [199.130628] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 8, 8, 8, 8, 11, 16, 16, 0, 0, 0 <7> [199.130784] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 129, 129, 129, 129, 177, 257, 257, 30, 0, 0 <7> [199.130939] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 143, 143, 143, 143, 196, 284, 284, 31, 0, 0 <7> [199.131119] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:447:pipe C] data rate 1142000 num active planes 1 <7> [199.131356] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 14993 required 1142 <7> [199.131530] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [199.131722] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:447:pipe C] min cdclk: 0 kHz -> 192000 kHz <7> [199.131939] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [199.132106] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [199.132279] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [199.132452] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:447:pipe C] allocated DPLL 0 <7> [199.132621] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:447:pipe C] reserving DPLL 0 <7> [199.132787] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:447:pipe C] enable: yes [modeset] <7> [199.132997] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [199.133159] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: C, pipe bpp: 24, dithering: 0 <7> [199.133342] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [199.133521] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [199.133679] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [199.133838] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [199.134003] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [199.134165] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x0 <7> [199.134341] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [199.134345] i915 0000:00:02.0: colorspace: RGB <7> [199.134347] i915 0000:00:02.0: scan mode: Underscan <7> [199.134350] i915 0000:00:02.0: colorimetry: No Data <7> [199.134353] i915 0000:00:02.0: picture aspect: No Data <7> [199.134355] i915 0000:00:02.0: active aspect: Same as Picture <7> [199.134357] i915 0000:00:02.0: itc: No Data <7> [199.134360] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [199.134363] i915 0000:00:02.0: quantization range: Full <7> [199.134366] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [199.134368] i915 0000:00:02.0: video code: 0 <7> [199.134371] i915 0000:00:02.0: ycc quantization range: Full <7> [199.134373] i915 0000:00:02.0: hdmi content type: Graphics <7> [199.134376] i915 0000:00:02.0: pixel repeat: 0 <7> [199.134378] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [199.134381] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [199.134385] i915 0000:00:02.0: vendor: Intel <7> [199.134387] i915 0000:00:02.0: product: Integrated gfx <7> [199.134390] i915 0000:00:02.0: source device information: PC General (0x9) <7> [199.134393] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [199.134396] i915 0000:00:02.0: empty frame <7> [199.134399] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 0f 00 6d a2 00 7f 00 00 00 00 00 00 00 00 <7> [199.134588] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 0d 82 34 12 66 69 74 48 65 61 64 6c 65 73 73 47 <7> [199.134747] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 53 7f 7f 28 0f 7f 07 17 7f ff 3f 7f ff 47 7f ff <7> [199.134906] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 5f 7f 82 7f 7f 00 7f 7f 51 7f 7f 30 77 7f 03 00 <7> [199.135065] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [199.135224] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [199.135402] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1144, vmax: 1144, flipline: 1144, pipeline full: 61, guardband: 63 vsync start: 0, vsync end: 0 <7> [199.135573] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1081, vmax vblank: 1081, vmin vtotal: 1144, vmax vtotal: 1144 <7> [199.135732] 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> [199.135892] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 <7> [199.136053] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 <7> [199.136211] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5 <7> [199.136385] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x40 0x5 <7> [199.136555] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5 <7> [199.136732] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 285500, pixel rate 285500, min cdclk 192000, min voltage level 0 <7> [199.136892] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [199.137051] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [199.137208] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [199.137391] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [199.137422] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off <7> [199.137591] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [199.137752] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [199.137912] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1801be, cfgcr1: 0x488, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0 <7> [199.137950] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6 <7> [199.138076] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [199.138196] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02 <7> [199.138239] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [199.138425] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [199.138636] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [199.138795] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [199.138954] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [199.139123] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [199.139373] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [199.139609] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [199.139841] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [199.139979] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on <7> [199.140072] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [199.140295] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [199.140482] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:311:plane 1C] fb: [FB:637] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [199.140644] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [199.140801] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [199.140965] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:341:plane 2C] fb: [NOFB], visible: no <7> [199.141193] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:371:plane 3C] fb: [NOFB], visible: no <7> [199.141446] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:401:plane 4C] fb: [NOFB], visible: no <7> [199.141675] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:411:plane 5C] fb: [NOFB], visible: no <7> [199.141908] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:421:plane 6C] fb: [NOFB], visible: no <7> [199.142104] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:431:plane 7C] fb: [NOFB], visible: no <7> [199.142271] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:441:cursor C] fb: [NOFB], visible: no <7> [199.143022] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on <7> [199.143281] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off <7> [199.144038] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00 <7> [199.145253] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2 <7> [199.145532] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_3 <7> [199.145783] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_4 <7> [199.146071] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 192000 kHz, VCO 384000 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [199.146388] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:587:DDI B/PHY B] <7> [199.146556] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DDI TC1/PHY TC1] <7> [199.146722] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST A] <7> [199.146886] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST B] <7> [199.147093] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST C] <7> [199.147344] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:602:DP-MST D] <7> [199.147573] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DDI TC2/PHY TC2] <7> [199.147801] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST A] <7> [199.148016] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST B] <7> [199.148174] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST C] <7> [199.148353] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST D] <7> [199.148511] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DDI TC3/PHY TC3] <7> [199.148686] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST A] <7> [199.148916] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST B] <7> [199.149154] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST C] <7> [199.149405] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:621:DP-MST D] <7> [199.149630] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DDI TC4/PHY TC4] <7> [199.149792] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST A] <7> [199.149949] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST B] <7> [199.150106] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST C] <7> [199.150277] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:630:DP-MST D] <7> [199.150725] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [199.151010] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x4, on? 0) for [CRTC:447:pipe C] <7> [199.151113] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x810 <7> [199.151246] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0 <7> [199.151785] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B <7> [199.152143] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe C <7> [199.153108] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:588:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10 <7> [199.153696] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [199.153913] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry <7> [199.154510] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1) <7> [199.154745] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:588:HDMI-A-1] Failed to read TMDS config: -6 <7> [199.154771] i915 0000:00:02.0: [drm:intel_ddi_enable [i915]] [CONNECTOR:588:HDMI-A-1] Failed to configure sink scrambling/TMDS bit clock ratio <7> [199.155976] azx_init_pci: snd_hda_intel 0000:00:1f.3: Clearing TCSEL <7> [199.156009] azx_init_pci: snd_hda_intel 0000:00:1f.3: SCH snoop: Enabled <7> [199.163461] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:588:HDMI-A-1][ENCODER:587:DDI B/PHY B] Enable audio codec on [CRTC:447:pipe C], 64 bytes ELD <7> [199.171811] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] HDMI audio pixel clock setting for 285500 not found, falling back to defaults <7> [199.172016] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000) <7> [199.172178] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <6> [199.172369] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 5 not expected <6> [199.172373] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 0 not expected <6> [199.172376] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 10 not expected <6> [199.172379] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 6 not expected <7> [199.172561] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:588:HDMI-A-1] <7> [199.172963] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:447:pipe C] <7> [199.233416] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x810 <7> [199.237834] azx_init_pci: snd_hda_intel 0000:00:1f.3: Clearing TCSEL <7> [199.237867] azx_init_pci: snd_hda_intel 0000:00:1f.3: SCH snoop: Enabled <6> [201.615096] [IGT] kms_flip: finished subtest C-HDMI-A1, FAIL

Detail

Value

Duration

2.57 seconds

Hostname

shard-tglu-7

Igt-Version

IGT-Version: 2.4-g4568b2c14 (x86_64) (Linux: 7.1.0-rc1-CI_DRM_18375-ge066eb26712b+ x86_64)

Out

Starting dynamic subtest: C-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-HDMI-A1: FAIL (2.567s)

Err

Starting dynamic subtest: C-HDMI-A1
(kms_flip:2199) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2199) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2199) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.489838
last_received_ts = 200.489517
last_seq = 164
current_ts = 200.498169
current_received_ts = 200.497818
current_seq = 165
count = 160
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 34us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.498169
last_received_ts = 200.497818
last_seq = 165
current_ts = 200.506500
current_received_ts = 200.506241
current_seq = 166
count = 161
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.506500
last_received_ts = 200.506241
last_seq = 166
current_ts = 200.514847
current_received_ts = 200.514465
current_seq = 167
count = 162
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.514847
last_received_ts = 200.514465
last_seq = 167
current_ts = 200.523178
current_received_ts = 200.522858
current_seq = 168
count = 163
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.523178
last_received_ts = 200.522858
last_seq = 168
current_ts = 200.531509
current_received_ts = 200.531174
current_seq = 169
count = 164
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 23us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.531509
last_received_ts = 200.531174
last_seq = 169
current_ts = 200.539841
current_received_ts = 200.539536
current_seq = 170
count = 165
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 26us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.539841
last_received_ts = 200.539536
last_seq = 170
current_ts = 200.548172
current_received_ts = 200.547928
current_seq = 171
count = 166
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 25us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.548172
last_received_ts = 200.547928
last_seq = 171
current_ts = 200.556519
current_received_ts = 200.556229
current_seq = 172
count = 167
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 23us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.556519
last_received_ts = 200.556229
last_seq = 172
current_ts = 200.564850
current_received_ts = 200.564575
current_seq = 173
count = 168
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.564850
last_received_ts = 200.564575
last_seq = 173
current_ts = 200.573181
current_received_ts = 200.572845
current_seq = 174
count = 169
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 25us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.573181
last_received_ts = 200.572845
last_seq = 174
current_ts = 200.581512
current_received_ts = 200.581238
current_seq = 175
count = 170
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 26us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.581512
last_received_ts = 200.581238
last_seq = 175
current_ts = 200.589844
current_received_ts = 200.589508
current_seq = 176
count = 171
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 25us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.589844
last_received_ts = 200.589508
last_seq = 176
current_ts = 200.598190
current_received_ts = 200.597961
current_seq = 177
count = 172
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 53us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.598190
last_received_ts = 200.597961
last_seq = 177
current_ts = 200.606522
current_received_ts = 200.606216
current_seq = 178
count = 173
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.606522
last_received_ts = 200.606216
last_seq = 178
current_ts = 200.614853
current_received_ts = 200.614532
current_seq = 179
count = 174
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 33us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.614853
last_received_ts = 200.614532
last_seq = 179
current_ts = 200.623184
current_received_ts = 200.622849
current_seq = 180
count = 175
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 25us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.623184
last_received_ts = 200.622849
last_seq = 180
current_ts = 200.631516
current_received_ts = 200.631165
current_seq = 181
count = 176
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 23us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.631516
last_received_ts = 200.631165
last_seq = 181
current_ts = 200.639862
current_received_ts = 200.639526
current_seq = 182
count = 177
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.639862
last_received_ts = 200.639526
last_seq = 182
current_ts = 200.648193
current_received_ts = 200.647797
current_seq = 183
count = 178
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.648193
last_received_ts = 200.647797
last_seq = 183
current_ts = 200.656525
current_received_ts = 200.656219
current_seq = 184
count = 179
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 31us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.656525
last_received_ts = 200.656219
last_seq = 184
current_ts = 200.664856
current_received_ts = 200.664474
current_seq = 185
count = 180
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.664856
last_received_ts = 200.664474
last_seq = 185
current_ts = 200.673203
current_received_ts = 200.672882
current_seq = 186
count = 181
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.673203
last_received_ts = 200.672882
last_seq = 186
current_ts = 200.681534
current_received_ts = 200.681183
current_seq = 187
count = 182
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 26us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.681534
last_received_ts = 200.681183
last_seq = 187
current_ts = 200.689865
current_received_ts = 200.689529
current_seq = 188
count = 183
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.689865
last_received_ts = 200.689529
last_seq = 188
current_ts = 200.698196
current_received_ts = 200.697983
current_seq = 189
count = 184
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.698196
last_received_ts = 200.697983
last_seq = 189
current_ts = 200.706528
current_received_ts = 200.706223
current_seq = 190
count = 185
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.706528
last_received_ts = 200.706223
last_seq = 190
current_ts = 200.714874
current_received_ts = 200.714539
current_seq = 191
count = 186
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 30us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.714874
last_received_ts = 200.714539
last_seq = 191
current_ts = 200.723206
current_received_ts = 200.722855
current_seq = 192
count = 187
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 25us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.723206
last_received_ts = 200.722855
last_seq = 192
current_ts = 200.731537
current_received_ts = 200.731232
current_seq = 193
count = 188
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.731537
last_received_ts = 200.731232
last_seq = 193
current_ts = 200.739868
current_received_ts = 200.739548
current_seq = 194
count = 189
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 26us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.739868
last_received_ts = 200.739548
last_seq = 194
current_ts = 200.748215
current_received_ts = 200.747849
current_seq = 195
count = 190
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 23us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.748215
last_received_ts = 200.747849
last_seq = 195
current_ts = 200.756546
current_received_ts = 200.756226
current_seq = 196
count = 191
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.756546
last_received_ts = 200.756226
last_seq = 196
current_ts = 200.764877
current_received_ts = 200.764526
current_seq = 197
count = 192
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 23us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.764877
last_received_ts = 200.764526
last_seq = 197
current_ts = 200.773209
current_received_ts = 200.773087
current_seq = 198
count = 193
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 26us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.773209
last_received_ts = 200.773087
last_seq = 198
current_ts = 200.781540
current_received_ts = 200.781189
current_seq = 199
count = 194
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 23us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.781540
last_received_ts = 200.781189
last_seq = 199
current_ts = 200.789886
current_received_ts = 200.789642
current_seq = 200
count = 195
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 35us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.789886
last_received_ts = 200.789642
last_seq = 200
current_ts = 200.798218
current_received_ts = 200.797852
current_seq = 201
count = 196
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.798218
last_received_ts = 200.797852
last_seq = 201
current_ts = 200.806549
current_received_ts = 200.806274
current_seq = 202
count = 197
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.806549
last_received_ts = 200.806274
last_seq = 202
current_ts = 200.814880
current_received_ts = 200.814499
current_seq = 203
count = 198
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 23us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.814880
last_received_ts = 200.814499
last_seq = 203
current_ts = 200.823212
current_received_ts = 200.822861
current_seq = 204
count = 199
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 26us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.823212
last_received_ts = 200.822861
last_seq = 204
current_ts = 200.831558
current_received_ts = 200.831284
current_seq = 205
count = 200
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.831558
last_received_ts = 200.831284
last_seq = 205
current_ts = 200.839890
current_received_ts = 200.839554
current_seq = 206
count = 201
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.839890
last_received_ts = 200.839554
last_seq = 206
current_ts = 200.848221
current_received_ts = 200.847900
current_seq = 207
count = 202
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.848221
last_received_ts = 200.847900
last_seq = 207
current_ts = 200.856567
current_received_ts = 200.856277
current_seq = 208
count = 203
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 37us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.856567
last_received_ts = 200.856277
last_seq = 208
current_ts = 200.864883
current_received_ts = 200.864563
current_seq = 209
count = 204
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.864883
last_received_ts = 200.864563
last_seq = 209
current_ts = 200.873230
current_received_ts = 200.872879
current_seq = 210
count = 205
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.873230
last_received_ts = 200.872879
last_seq = 210
current_ts = 200.881561
current_received_ts = 200.881241
current_seq = 211
count = 206
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.881561
last_received_ts = 200.881241
last_seq = 211
current_ts = 200.889893
current_received_ts = 200.889557
current_seq = 212
count = 207
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.889893
last_received_ts = 200.889557
last_seq = 212
current_ts = 200.898224
current_received_ts = 200.898087
current_seq = 213
count = 208
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.898224
last_received_ts = 200.898087
last_seq = 213
current_ts = 200.906570
current_received_ts = 200.906281
current_seq = 214
count = 209
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.906570
last_received_ts = 200.906281
last_seq = 214
current_ts = 200.914902
current_received_ts = 200.914658
current_seq = 215
count = 210
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.914902
last_received_ts = 200.914658
last_seq = 215
current_ts = 200.923233
current_received_ts = 200.922852
current_seq = 216
count = 211
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 25us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.923233
last_received_ts = 200.922852
last_seq = 216
current_ts = 200.931564
current_received_ts = 200.931305
current_seq = 217
count = 212
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.931564
last_received_ts = 200.931305
last_seq = 217
current_ts = 200.939896
current_received_ts = 200.939545
current_seq = 218
count = 213
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 37us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.939896
last_received_ts = 200.939545
last_seq = 218
current_ts = 200.948242
current_received_ts = 200.947861
current_seq = 219
count = 214
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 22us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.948242
last_received_ts = 200.947861
last_seq = 219
current_ts = 200.956573
current_received_ts = 200.956299
current_seq = 220
count = 215
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 32us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.956573
last_received_ts = 200.956299
last_seq = 220
current_ts = 200.964905
current_received_ts = 200.964554
current_seq = 221
count = 216
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 23us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.964905
last_received_ts = 200.964554
last_seq = 221
current_ts = 200.973251
current_received_ts = 200.973053
current_seq = 222
count = 217
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.973251
last_received_ts = 200.973053
last_seq = 222
current_ts = 200.981567
current_received_ts = 200.981247
current_seq = 223
count = 218
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 25us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.981567
last_received_ts = 200.981247
last_seq = 223
current_ts = 200.989914
current_received_ts = 200.989578
current_seq = 224
count = 219
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.989914
last_received_ts = 200.989578
last_seq = 224
current_ts = 200.998245
current_received_ts = 200.997910
current_seq = 225
count = 220
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 30us
(kms_flip:2199) DEBUG: name = flip
last_ts = 200.998245
last_received_ts = 200.997910
last_seq = 225
current_ts = 201.006577
current_received_ts = 201.006256
current_seq = 226
count = 221
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.006577
last_received_ts = 201.006256
last_seq = 226
current_ts = 201.014908
current_received_ts = 201.014572
current_seq = 227
count = 222
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 23us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.014908
last_received_ts = 201.014572
last_seq = 227
current_ts = 201.023239
current_received_ts = 201.022919
current_seq = 228
count = 223
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 25us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.023239
last_received_ts = 201.022919
last_seq = 228
current_ts = 201.031586
current_received_ts = 201.031342
current_seq = 229
count = 224
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.031586
last_received_ts = 201.031342
last_seq = 229
current_ts = 201.039917
current_received_ts = 201.039566
current_seq = 230
count = 225
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.039917
last_received_ts = 201.039566
last_seq = 230
current_ts = 201.048248
current_received_ts = 201.047913
current_seq = 231
count = 226
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.048248
last_received_ts = 201.047913
last_seq = 231
current_ts = 201.056580
current_received_ts = 201.056229
current_seq = 232
count = 227
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 25us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.056580
last_received_ts = 201.056229
last_seq = 232
current_ts = 201.064926
current_received_ts = 201.064590
current_seq = 233
count = 228
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.064926
last_received_ts = 201.064590
last_seq = 233
current_ts = 201.073257
current_received_ts = 201.072876
current_seq = 234
count = 229
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.073257
last_received_ts = 201.072876
last_seq = 234
current_ts = 201.081589
current_received_ts = 201.081329
current_seq = 235
count = 230
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.081589
last_received_ts = 201.081329
last_seq = 235
current_ts = 201.089920
current_received_ts = 201.089554
current_seq = 236
count = 231
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.089920
last_received_ts = 201.089554
last_seq = 236
current_ts = 201.098267
current_received_ts = 201.097946
current_seq = 237
count = 232
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 43us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.098267
last_received_ts = 201.097946
last_seq = 237
current_ts = 201.106598
current_received_ts = 201.106277
current_seq = 238
count = 233
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 52us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.106598
last_received_ts = 201.106277
last_seq = 238
current_ts = 201.114929
current_received_ts = 201.114655
current_seq = 239
count = 234
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.114929
last_received_ts = 201.114655
last_seq = 239
current_ts = 201.123260
current_received_ts = 201.122925
current_seq = 240
count = 235
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 25us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.123260
last_received_ts = 201.122925
last_seq = 240
current_ts = 201.131592
current_received_ts = 201.131271
current_seq = 241
count = 236
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.131592
last_received_ts = 201.131271
last_seq = 241
current_ts = 201.139938
current_received_ts = 201.139603
current_seq = 242
count = 237
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 32us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.139938
last_received_ts = 201.139603
last_seq = 242
current_ts = 201.148270
current_received_ts = 201.148056
current_seq = 243
count = 238
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.148270
last_received_ts = 201.148056
last_seq = 243
current_ts = 201.156601
current_received_ts = 201.156281
current_seq = 244
count = 239
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 32us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.156601
last_received_ts = 201.156281
last_seq = 244
current_ts = 201.164932
current_received_ts = 201.164597
current_seq = 245
count = 240
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.164932
last_received_ts = 201.164597
last_seq = 245
current_ts = 201.173279
current_received_ts = 201.172958
current_seq = 246
count = 241
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 43us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.173279
last_received_ts = 201.172958
last_seq = 246
current_ts = 201.181610
current_received_ts = 201.181274
current_seq = 247
count = 242
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 33us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.181610
last_received_ts = 201.181274
last_seq = 247
current_ts = 201.189941
current_received_ts = 201.189728
current_seq = 248
count = 243
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 26us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.189941
last_received_ts = 201.189728
last_seq = 248
current_ts = 201.198273
current_received_ts = 201.197891
current_seq = 249
count = 244
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.198273
last_received_ts = 201.197891
last_seq = 249
current_ts = 201.206604
current_received_ts = 201.206345
current_seq = 250
count = 245
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.206604
last_received_ts = 201.206345
last_seq = 250
current_ts = 201.214951
current_received_ts = 201.214554
current_seq = 251
count = 246
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.214951
last_received_ts = 201.214554
last_seq = 251
current_ts = 201.223282
current_received_ts = 201.222900
current_seq = 252
count = 247
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.223282
last_received_ts = 201.222900
last_seq = 252
current_ts = 201.231613
current_received_ts = 201.231308
current_seq = 253
count = 248
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 31us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.231613
last_received_ts = 201.231308
last_seq = 253
current_ts = 201.239944
current_received_ts = 201.239563
current_seq = 254
count = 249
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.239944
last_received_ts = 201.239563
last_seq = 254
current_ts = 201.248291
current_received_ts = 201.247955
current_seq = 255
count = 250
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 43us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.248291
last_received_ts = 201.247955
last_seq = 255
current_ts = 201.256622
current_received_ts = 201.256302
current_seq = 256
count = 251
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.256622
last_received_ts = 201.256302
last_seq = 256
current_ts = 201.264954
current_received_ts = 201.264664
current_seq = 257
count = 252
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.264954
last_received_ts = 201.264664
last_seq = 257
current_ts = 201.273285
current_received_ts = 201.272919
current_seq = 258
count = 253
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 30us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.273285
last_received_ts = 201.272919
last_seq = 258
current_ts = 201.281616
current_received_ts = 201.281281
current_seq = 259
count = 254
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.281616
last_received_ts = 201.281281
last_seq = 259
current_ts = 201.289948
current_received_ts = 201.289627
current_seq = 260
count = 255
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 30us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.289948
last_received_ts = 201.289627
last_seq = 260
current_ts = 201.298294
current_received_ts = 201.298065
current_seq = 261
count = 256
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.298294
last_received_ts = 201.298065
last_seq = 261
current_ts = 201.306625
current_received_ts = 201.306305
current_seq = 262
count = 257
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.306625
last_received_ts = 201.306305
last_seq = 262
current_ts = 201.314957
current_received_ts = 201.314667
current_seq = 263
count = 258
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 26us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.314957
last_received_ts = 201.314667
last_seq = 263
current_ts = 201.323303
current_received_ts = 201.322922
current_seq = 264
count = 259
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.323303
last_received_ts = 201.322922
last_seq = 264
current_ts = 201.331619
current_received_ts = 201.331314
current_seq = 265
count = 260
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 36us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.331619
last_received_ts = 201.331314
last_seq = 265
current_ts = 201.339966
current_received_ts = 201.339645
current_seq = 266
count = 261
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.339966
last_received_ts = 201.339645
last_seq = 266
current_ts = 201.348297
current_received_ts = 201.347916
current_seq = 267
count = 262
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 26us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.348297
last_received_ts = 201.347916
last_seq = 267
current_ts = 201.356628
current_received_ts = 201.356308
current_seq = 268
count = 263
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.356628
last_received_ts = 201.356308
last_seq = 268
current_ts = 201.364960
current_received_ts = 201.364578
current_seq = 269
count = 264
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.364960
last_received_ts = 201.364578
last_seq = 269
current_ts = 201.373306
current_received_ts = 201.372910
current_seq = 270
count = 265
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 31us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.373306
last_received_ts = 201.372910
last_seq = 270
current_ts = 201.381638
current_received_ts = 201.381317
current_seq = 271
count = 266
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.381638
last_received_ts = 201.381317
last_seq = 271
current_ts = 201.389969
current_received_ts = 201.389633
current_seq = 272
count = 267
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 23us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.389969
last_received_ts = 201.389633
last_seq = 272
current_ts = 201.398300
current_received_ts = 201.397980
current_seq = 273
count = 268
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.398300
last_received_ts = 201.397980
last_seq = 273
current_ts = 201.406631
current_received_ts = 201.406311
current_seq = 274
count = 269
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.406631
last_received_ts = 201.406311
last_seq = 274
current_ts = 201.414978
current_received_ts = 201.414734
current_seq = 275
count = 270
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 26us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.414978
last_received_ts = 201.414734
last_seq = 275
current_ts = 201.423309
current_received_ts = 201.422928
current_seq = 276
count = 271
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.423309
last_received_ts = 201.422928
last_seq = 276
current_ts = 201.431641
current_received_ts = 201.431320
current_seq = 277
count = 272
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 29us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.431641
last_received_ts = 201.431320
last_seq = 277
current_ts = 201.439972
current_received_ts = 201.439621
current_seq = 278
count = 273
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 22us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.439972
last_received_ts = 201.439621
last_seq = 278
current_ts = 201.448303
current_received_ts = 201.448105
current_seq = 279
count = 274
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 28us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.448303
last_received_ts = 201.448105
last_seq = 279
current_ts = 201.456650
current_received_ts = 201.456299
current_seq = 280
count = 275
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 27us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.456650
last_received_ts = 201.456299
last_seq = 280
current_ts = 201.464981
current_received_ts = 201.464661
current_seq = 281
count = 276
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 37us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.464981
last_received_ts = 201.464661
last_seq = 281
current_ts = 201.473312
current_received_ts = 201.472961
current_seq = 282
count = 277
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 67us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.473312
last_received_ts = 201.472961
last_seq = 282
current_ts = 201.481659
current_received_ts = 201.481354
current_seq = 283
count = 278
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 24us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.481659
last_received_ts = 201.481354
last_seq = 283
current_ts = 201.489990
current_received_ts = 201.489624
current_seq = 284
count = 279
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 30us
(kms_flip:2199) DEBUG: name = flip
last_ts = 201.489990
last_received_ts = 201.489624
last_seq = 284
current_ts = 201.498322
current_received_ts = 201.497971
current_seq = 285
count = 280
seq_step = 1
(kms_flip:2199) DEBUG: Vblank took 737us
(kms_flip:2199) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2199) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2199) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2199) igt_core-INFO: Stack trace:
(kms_flip:2199) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2199) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:2199) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:2199) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:2199) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:2199) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2199) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2199) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A1: FAIL (2.567s)

Dmesg

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

<7> [199.048539] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:637]

<7> [199.048988] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:638]

<7> [199.071044] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:171:pipe A]

<7> [199.071206] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:309:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [199.083572] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:309:pipe B] releasing DPLL 0

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

<7> [199.084081] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:309:pipe B] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x2 -> 0x0

<7> [199.084390] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:303:cursor B] ddb (1993 - 2048) -> ( 0 - 0), size 55 -> 0

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

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

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

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

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

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

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

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

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

<7> [199.086855] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:273:plane 5B] fb: [NOFB], visible: no

<7> [199.087085] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:283:plane 6B] fb: [NOFB], visible: no

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

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

<7> [199.087921] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:588:HDMI-A-1][ENCODER:587:DDI B/PHY B] Disable audio codec on [CRTC:309:pipe B]

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

<7> [199.106220] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:588:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10

<7> [199.106819] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1)

<7> [199.106971] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry

<7> [199.107518] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1)

<7> [199.107806] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:588:HDMI-A-1] Failed to read TMDS config: -6

<7> [199.107823] i915 0000:00:02.0: [drm:intel_ddi_disable [i915]] [CONNECTOR:588:HDMI-A-1] Failed to reset sink scrambling/TMDS bit clock ratio

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

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

<7> [199.113613] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x2, on? 1) for [CRTC:309:pipe B]

<7> [199.113804] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0

<7> [199.113982] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 172800 kHz, VCO 345600 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

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

<7> [199.114445] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DDI TC1/PHY TC1]

<7> [199.114632] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST A]

<7> [199.114797] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST B]

<7> [199.114958] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST C]

<7> [199.115117] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:602:DP-MST D]

<7> [199.115286] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DDI TC2/PHY TC2]

<7> [199.115471] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST A]

<7> [199.115628] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST B]

<7> [199.115786] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST C]

<7> [199.115942] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST D]

<7> [199.116100] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DDI TC3/PHY TC3]

<7> [199.116265] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST A]

<7> [199.116442] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST B]

<7> [199.116599] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST C]

<7> [199.116757] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:621:DP-MST D]

<7> [199.116919] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DDI TC4/PHY TC4]

<7> [199.117083] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST A]

<7> [199.117244] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST B]

<7> [199.117478] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST C]

<7> [199.117668] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:630:DP-MST D]

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

<7> [199.118172] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1

<7> [199.118407] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_3

<7> [199.118595] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2

<7> [199.118829] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:309:pipe B]

<7> [199.119305] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe C]

<7> [199.119467] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:585:pipe D]

<7> [199.119581] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:447:pipe C]

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

<7> [199.119682] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:588:HDMI-A-1] Limiting target display pipe bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36)

<7> [199.119865] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24)

<7> [199.120026] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:447:pipe C] hw max bpp: 24, pipe bpp: 24, dithering: 0

<7> [199.120193] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:587:DDI B/PHY B] [CRTC:447:pipe C]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [199.126295] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:447:pipe C] fastset requirement not met in dpll_hw_state

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

<7> [199.126634] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: cfgcr0: 0x0, cfgcr1: 0x0, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0

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

<7> [199.126954] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: cfgcr0: 0x1801be, cfgcr1: 0x488, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [199.129928] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:447:pipe C] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4

<7> [199.130128] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:311:plane 1C] ddb ( 0 - 0) -> ( 0 - 1993), size 0 -> 1993

<7> [199.130300] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:441:cursor C] ddb ( 0 - 0) -> (1993 - 2048), size 0 -> 55

<7> [199.130472] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311: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> [199.130628] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 8, 8, 8, 8, 11, 16, 16, 0, 0, 0

<7> [199.130784] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 129, 129, 129, 129, 177, 257, 257, 30, 0, 0

<7> [199.130939] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:311:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 143, 143, 143, 143, 196, 284, 284, 31, 0, 0

<7> [199.131119] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:447:pipe C] data rate 1142000 num active planes 1

<7> [199.131356] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 14993 required 1142

<7> [199.131530] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1

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

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

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

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

<7> [199.132452] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:447:pipe C] allocated DPLL 0

<7> [199.132621] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:447:pipe C] reserving DPLL 0

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

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

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

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

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

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

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

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

<7> [199.134165] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [199.134399] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 0f 00 6d a2 00 7f 00 00 00 00 00 00 00 00

<7> [199.134588] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 0d 82 34 12 66 69 74 48 65 61 64 6c 65 73 73 47

<7> [199.134747] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 53 7f 7f 28 0f 7f 07 17 7f ff 3f 7f ff 47 7f ff

<7> [199.134906] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 5f 7f 82 7f 7f 00 7f 7f 51 7f 7f 30 77 7f 03 00

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

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

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

<7> [199.135573] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1081, vmax vblank: 1081, vmin vtotal: 1144, vmax vtotal: 1144

<7> [199.135732] 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> [199.135892] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5

<7> [199.136053] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5

<7> [199.136211] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5

<7> [199.136385] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x40 0x5

<7> [199.136555] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=285500, hd=1920 hb=1920-2080 hs=1968-2000 ht=2080, vd=1080 vb=1080-1144 vs=1083-1088 vt=1144, flags=0x5

<7> [199.136732] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 285500, pixel rate 285500, min cdclk 192000, min voltage level 0

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

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

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

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

<7> [199.137422] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off

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

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

<7> [199.137912] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1801be, cfgcr1: 0x488, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0

<7> [199.137950] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6

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

<7> [199.138196] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02

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

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

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

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

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

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

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

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

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

<7> [199.139979] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on

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

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

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

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

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

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

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

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

<7> [199.141675] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:411:plane 5C] fb: [NOFB], visible: no

<7> [199.141908] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:421:plane 6C] fb: [NOFB], visible: no

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

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

<7> [199.143022] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on

<7> [199.143281] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off

<7> [199.144038] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00

<7> [199.145253] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2

<7> [199.145532] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_3

<7> [199.145783] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_4

<7> [199.146071] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 192000 kHz, VCO 384000 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

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

<7> [199.146556] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:597:DDI TC1/PHY TC1]

<7> [199.146722] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:599:DP-MST A]

<7> [199.146886] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:600:DP-MST B]

<7> [199.147093] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:601:DP-MST C]

<7> [199.147344] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:602:DP-MST D]

<7> [199.147573] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:607:DDI TC2/PHY TC2]

<7> [199.147801] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:609:DP-MST A]

<7> [199.148016] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:610:DP-MST B]

<7> [199.148174] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:611:DP-MST C]

<7> [199.148353] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:612:DP-MST D]

<7> [199.148511] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:616:DDI TC3/PHY TC3]

<7> [199.148686] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:618:DP-MST A]

<7> [199.148916] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:619:DP-MST B]

<7> [199.149154] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:620:DP-MST C]

<7> [199.149405] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:621:DP-MST D]

<7> [199.149630] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:625:DDI TC4/PHY TC4]

<7> [199.149792] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:627:DP-MST A]

<7> [199.149949] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:628:DP-MST B]

<7> [199.150106] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:629:DP-MST C]

<7> [199.150277] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:630:DP-MST D]

<7> [199.150725] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3

<7> [199.151010] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x4, on? 0) for [CRTC:447:pipe C]

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

<7> [199.151246] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0

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

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

<7> [199.153108] i915 0000:00:02.0: [drm:intel_hdmi_handle_sink_scrambling [i915]] [CONNECTOR:588:HDMI-A-1] scrambling=no, TMDS bit clock ratio=1/10

<7> [199.153696] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1)

<7> [199.153913] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK on first message, retry

<7> [199.154510] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus dpb] NAK for addr: 0054 w(1)

<7> [199.154745] i915 0000:00:02.0: [drm:drm_scdc_set_high_tmds_clock_ratio [drm_display_helper]] [CONNECTOR:588:HDMI-A-1] Failed to read TMDS config: -6

<7> [199.154771] i915 0000:00:02.0: [drm:intel_ddi_enable [i915]] [CONNECTOR:588:HDMI-A-1] Failed to configure sink scrambling/TMDS bit clock ratio

<7> [199.155976] azx_init_pci: snd_hda_intel 0000:00:1f.3: Clearing TCSEL

<7> [199.156009] azx_init_pci: snd_hda_intel 0000:00:1f.3: SCH snoop: Enabled

<7> [199.163461] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:588:HDMI-A-1][ENCODER:587:DDI B/PHY B] Enable audio codec on [CRTC:447:pipe C], 64 bytes ELD

<7> [199.171811] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] HDMI audio pixel clock setting for 285500 not found, falling back to defaults

<7> [199.172016] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000)

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

<6> [199.172369] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 5 not expected

<6> [199.172373] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 0 not expected

<6> [199.172376] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 10 not expected

<6> [199.172379] snd_hda_codec_intelhdmi hdaudioC0D2: HDMI: audio coding xtype 6 not expected

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

<7> [199.172963] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:447:pipe C]

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

<7> [199.237834] azx_init_pci: snd_hda_intel 0000:00:1f.3: Clearing TCSEL

<7> [199.237867] azx_init_pci: snd_hda_intel 0000:00:1f.3: SCH snoop: Enabled

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

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