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

Detail	Value
Duration	5.05 seconds
Hostname	shard-glk6
Igt-Version	IGT-Version: 2.3-ga7015a99f (x86_64) (Linux: 7.0.0-rc4-CI_DRM_18186-g166a38809296+ x86_64)
Out	Starting dynamic subtest: A-HDMI-A2 1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1891 run_test() #3 ../tests/kms_flip.c:2126 __igt_unique____real_main2047() #4 ../tests/kms_flip.c:2047 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-HDMI-A2: FAIL (5.049s)
Err	Starting dynamic subtest: A-HDMI-A2 (kms_flip:2570) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:2570) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest A-HDMI-A2 failed. ** DEBUG (kms_flip:2570) DEBUG: name = flip last_ts = 458.467773 last_received_ts = 458.467529 last_seq = 17571 current_ts = 458.484406 current_received_ts = 458.484222 current_seq = 17572 count = 117 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 21us (kms_flip:2570) DEBUG: name = flip last_ts = 458.484406 last_received_ts = 458.484222 last_seq = 17572 current_ts = 458.501099 current_received_ts = 458.501373 current_seq = 17573 count = 118 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 21us (kms_flip:2570) DEBUG: name = flip last_ts = 458.501099 last_received_ts = 458.501373 last_seq = 17573 current_ts = 458.517731 current_received_ts = 458.517670 current_seq = 17574 count = 119 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 458.517731 last_received_ts = 458.517670 last_seq = 17574 current_ts = 458.534424 current_received_ts = 458.534241 current_seq = 17575 count = 120 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 458.534424 last_received_ts = 458.534241 last_seq = 17575 current_ts = 458.551056 current_received_ts = 458.550934 current_seq = 17576 count = 121 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 458.551056 last_received_ts = 458.550934 last_seq = 17576 current_ts = 458.567719 current_received_ts = 458.567566 current_seq = 17577 count = 122 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 22us (kms_flip:2570) DEBUG: name = flip last_ts = 458.567719 last_received_ts = 458.567566 last_seq = 17577 current_ts = 458.584412 current_received_ts = 458.584320 current_seq = 17578 count = 123 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 458.584412 last_received_ts = 458.584320 last_seq = 17578 current_ts = 458.601044 current_received_ts = 458.600983 current_seq = 17579 count = 124 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 458.601044 last_received_ts = 458.600983 last_seq = 17579 current_ts = 458.617706 current_received_ts = 458.617584 current_seq = 17580 count = 125 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 458.617706 last_received_ts = 458.617584 last_seq = 17580 current_ts = 458.634369 current_received_ts = 458.634308 current_seq = 17581 count = 126 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 458.634369 last_received_ts = 458.634308 last_seq = 17581 current_ts = 458.651031 current_received_ts = 458.650940 current_seq = 17582 count = 127 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 458.651031 last_received_ts = 458.650940 last_seq = 17582 current_ts = 458.667694 current_received_ts = 458.667633 current_seq = 17583 count = 128 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 458.667694 last_received_ts = 458.667633 last_seq = 17583 current_ts = 458.684357 current_received_ts = 458.684296 current_seq = 17584 count = 129 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 458.684357 last_received_ts = 458.684296 last_seq = 17584 current_ts = 458.701019 current_received_ts = 458.701355 current_seq = 17585 count = 130 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 21us (kms_flip:2570) DEBUG: name = flip last_ts = 458.701019 last_received_ts = 458.701355 last_seq = 17585 current_ts = 458.717682 current_received_ts = 458.717560 current_seq = 17586 count = 131 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 458.717682 last_received_ts = 458.717560 last_seq = 17586 current_ts = 458.734344 current_received_ts = 458.734253 current_seq = 17587 count = 132 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 458.734344 last_received_ts = 458.734253 last_seq = 17587 current_ts = 458.751007 current_received_ts = 458.750854 current_seq = 17588 count = 133 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 458.751007 last_received_ts = 458.750854 last_seq = 17588 current_ts = 458.767670 current_received_ts = 458.767578 current_seq = 17589 count = 134 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 458.767670 last_received_ts = 458.767578 last_seq = 17589 current_ts = 458.784332 current_received_ts = 458.784241 current_seq = 17590 count = 135 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 458.784332 last_received_ts = 458.784241 last_seq = 17590 current_ts = 458.800995 current_received_ts = 458.800934 current_seq = 17591 count = 136 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 96us (kms_flip:2570) DEBUG: name = flip last_ts = 458.800995 last_received_ts = 458.800934 last_seq = 17591 current_ts = 458.817657 current_received_ts = 458.817566 current_seq = 17592 count = 137 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 23us (kms_flip:2570) DEBUG: name = flip last_ts = 458.817657 last_received_ts = 458.817566 last_seq = 17592 current_ts = 458.834320 current_received_ts = 458.834259 current_seq = 17593 count = 138 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 458.834320 last_received_ts = 458.834259 last_seq = 17593 current_ts = 458.850983 current_received_ts = 458.850677 current_seq = 17594 count = 139 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 458.850983 last_received_ts = 458.850677 last_seq = 17594 current_ts = 458.867645 current_received_ts = 458.867554 current_seq = 17595 count = 140 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 458.867645 last_received_ts = 458.867554 last_seq = 17595 current_ts = 458.884308 current_received_ts = 458.884247 current_seq = 17596 count = 141 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 458.884308 last_received_ts = 458.884247 last_seq = 17596 current_ts = 458.900940 current_received_ts = 458.901215 current_seq = 17597 count = 142 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 21us (kms_flip:2570) DEBUG: name = flip last_ts = 458.900940 last_received_ts = 458.901215 last_seq = 17597 current_ts = 458.917633 current_received_ts = 458.917511 current_seq = 17598 count = 143 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 27us (kms_flip:2570) DEBUG: name = flip last_ts = 458.917633 last_received_ts = 458.917511 last_seq = 17598 current_ts = 458.934296 current_received_ts = 458.934174 current_seq = 17599 count = 144 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 458.934296 last_received_ts = 458.934174 last_seq = 17599 current_ts = 458.950958 current_received_ts = 458.950745 current_seq = 17600 count = 145 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 21us (kms_flip:2570) DEBUG: name = flip last_ts = 458.950958 last_received_ts = 458.950745 last_seq = 17600 current_ts = 458.967621 current_received_ts = 458.967499 current_seq = 17601 count = 146 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 27us (kms_flip:2570) DEBUG: name = flip last_ts = 458.967621 last_received_ts = 458.967499 last_seq = 17601 current_ts = 458.984253 current_received_ts = 458.984161 current_seq = 17602 count = 147 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 458.984253 last_received_ts = 458.984161 last_seq = 17602 current_ts = 459.000916 current_received_ts = 459.000702 current_seq = 17603 count = 148 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 20us (kms_flip:2570) DEBUG: name = flip last_ts = 459.000916 last_received_ts = 459.000702 last_seq = 17603 current_ts = 459.017609 current_received_ts = 459.017456 current_seq = 17604 count = 149 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 459.017609 last_received_ts = 459.017456 last_seq = 17604 current_ts = 459.034241 current_received_ts = 459.034149 current_seq = 17605 count = 150 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 459.034241 last_received_ts = 459.034149 last_seq = 17605 current_ts = 459.050903 current_received_ts = 459.050751 current_seq = 17606 count = 151 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.050903 last_received_ts = 459.050751 last_seq = 17606 current_ts = 459.067566 current_received_ts = 459.067413 current_seq = 17607 count = 152 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.067566 last_received_ts = 459.067413 last_seq = 17607 current_ts = 459.084229 current_received_ts = 459.084106 current_seq = 17608 count = 153 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.084229 last_received_ts = 459.084106 last_seq = 17608 current_ts = 459.100891 current_received_ts = 459.100494 current_seq = 17609 count = 154 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 459.100891 last_received_ts = 459.100494 last_seq = 17609 current_ts = 459.117554 current_received_ts = 459.117432 current_seq = 17610 count = 155 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 459.117554 last_received_ts = 459.117432 last_seq = 17610 current_ts = 459.134216 current_received_ts = 459.134125 current_seq = 17611 count = 156 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 459.134216 last_received_ts = 459.134125 last_seq = 17611 current_ts = 459.150879 current_received_ts = 459.150604 current_seq = 17612 count = 157 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 20us (kms_flip:2570) DEBUG: name = flip last_ts = 459.150879 last_received_ts = 459.150604 last_seq = 17612 current_ts = 459.167542 current_received_ts = 459.167419 current_seq = 17613 count = 158 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.167542 last_received_ts = 459.167419 last_seq = 17613 current_ts = 459.184204 current_received_ts = 459.184143 current_seq = 17614 count = 159 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.184204 last_received_ts = 459.184143 last_seq = 17614 current_ts = 459.200867 current_received_ts = 459.200745 current_seq = 17615 count = 160 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 20us (kms_flip:2570) DEBUG: name = flip last_ts = 459.200867 last_received_ts = 459.200745 last_seq = 17615 current_ts = 459.217529 current_received_ts = 459.217407 current_seq = 17616 count = 161 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.217529 last_received_ts = 459.217407 last_seq = 17616 current_ts = 459.234192 current_received_ts = 459.234039 current_seq = 17617 count = 162 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 17us (kms_flip:2570) DEBUG: name = flip last_ts = 459.234192 last_received_ts = 459.234039 last_seq = 17617 current_ts = 459.250854 current_received_ts = 459.250519 current_seq = 17618 count = 163 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.250854 last_received_ts = 459.250519 last_seq = 17618 current_ts = 459.267517 current_received_ts = 459.267395 current_seq = 17619 count = 164 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 459.267517 last_received_ts = 459.267395 last_seq = 17619 current_ts = 459.284180 current_received_ts = 459.283997 current_seq = 17620 count = 165 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 18us (kms_flip:2570) DEBUG: name = flip last_ts = 459.284180 last_received_ts = 459.283997 last_seq = 17620 current_ts = 459.300842 current_received_ts = 459.300537 current_seq = 17621 count = 166 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.300842 last_received_ts = 459.300537 last_seq = 17621 current_ts = 459.317505 current_received_ts = 459.317383 current_seq = 17622 count = 167 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.317505 last_received_ts = 459.317383 last_seq = 17622 current_ts = 459.334167 current_received_ts = 459.333984 current_seq = 17623 count = 168 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 18us (kms_flip:2570) DEBUG: name = flip last_ts = 459.334167 last_received_ts = 459.333984 last_seq = 17623 current_ts = 459.350800 current_received_ts = 459.350525 current_seq = 17624 count = 169 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.350800 last_received_ts = 459.350525 last_seq = 17624 current_ts = 459.367462 current_received_ts = 459.367371 current_seq = 17625 count = 170 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 459.367462 last_received_ts = 459.367371 last_seq = 17625 current_ts = 459.384155 current_received_ts = 459.383972 current_seq = 17626 count = 171 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 17us (kms_flip:2570) DEBUG: name = flip last_ts = 459.384155 last_received_ts = 459.383972 last_seq = 17626 current_ts = 459.400787 current_received_ts = 459.400696 current_seq = 17627 count = 172 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 459.400787 last_received_ts = 459.400696 last_seq = 17627 current_ts = 459.417450 current_received_ts = 459.417358 current_seq = 17628 count = 173 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.417450 last_received_ts = 459.417358 last_seq = 17628 current_ts = 459.434143 current_received_ts = 459.433960 current_seq = 17629 count = 174 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 94us (kms_flip:2570) DEBUG: name = flip last_ts = 459.434143 last_received_ts = 459.433960 last_seq = 17629 current_ts = 459.450775 current_received_ts = 459.450684 current_seq = 17630 count = 175 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.450775 last_received_ts = 459.450684 last_seq = 17630 current_ts = 459.467438 current_received_ts = 459.467346 current_seq = 17631 count = 176 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.467438 last_received_ts = 459.467346 last_seq = 17631 current_ts = 459.484100 current_received_ts = 459.483917 current_seq = 17632 count = 177 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 18us (kms_flip:2570) DEBUG: name = flip last_ts = 459.484100 last_received_ts = 459.483917 last_seq = 17632 current_ts = 459.500763 current_received_ts = 459.500427 current_seq = 17633 count = 178 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.500763 last_received_ts = 459.500427 last_seq = 17633 current_ts = 459.517426 current_received_ts = 459.517334 current_seq = 17634 count = 179 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.517426 last_received_ts = 459.517334 last_seq = 17634 current_ts = 459.534088 current_received_ts = 459.533936 current_seq = 17635 count = 180 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 81us (kms_flip:2570) DEBUG: name = flip last_ts = 459.534088 last_received_ts = 459.533936 last_seq = 17635 current_ts = 459.550751 current_received_ts = 459.550629 current_seq = 17636 count = 181 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.550751 last_received_ts = 459.550629 last_seq = 17636 current_ts = 459.567413 current_received_ts = 459.567291 current_seq = 17637 count = 182 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.567413 last_received_ts = 459.567291 last_seq = 17637 current_ts = 459.584076 current_received_ts = 459.583984 current_seq = 17638 count = 183 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 459.584076 last_received_ts = 459.583984 last_seq = 17638 current_ts = 459.600739 current_received_ts = 459.600403 current_seq = 17639 count = 184 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.600739 last_received_ts = 459.600403 last_seq = 17639 current_ts = 459.617401 current_received_ts = 459.617310 current_seq = 17640 count = 185 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.617401 last_received_ts = 459.617310 last_seq = 17640 current_ts = 459.634064 current_received_ts = 459.633942 current_seq = 17641 count = 186 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.634064 last_received_ts = 459.633942 last_seq = 17641 current_ts = 459.650726 current_received_ts = 459.650421 current_seq = 17642 count = 187 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.650726 last_received_ts = 459.650421 last_seq = 17642 current_ts = 459.667389 current_received_ts = 459.667267 current_seq = 17643 count = 188 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 459.667389 last_received_ts = 459.667267 last_seq = 17643 current_ts = 459.684052 current_received_ts = 459.683899 current_seq = 17644 count = 189 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 20us (kms_flip:2570) DEBUG: name = flip last_ts = 459.684052 last_received_ts = 459.683899 last_seq = 17644 current_ts = 459.700714 current_received_ts = 459.700562 current_seq = 17645 count = 190 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.700714 last_received_ts = 459.700562 last_seq = 17645 current_ts = 459.717377 current_received_ts = 459.717255 current_seq = 17646 count = 191 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 459.717377 last_received_ts = 459.717255 last_seq = 17646 current_ts = 459.734039 current_received_ts = 459.733887 current_seq = 17647 count = 192 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 20us (kms_flip:2570) DEBUG: name = flip last_ts = 459.734039 last_received_ts = 459.733887 last_seq = 17647 current_ts = 459.750702 current_received_ts = 459.750549 current_seq = 17648 count = 193 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 459.750702 last_received_ts = 459.750549 last_seq = 17648 current_ts = 459.767365 current_received_ts = 459.767242 current_seq = 17649 count = 194 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 459.767365 last_received_ts = 459.767242 last_seq = 17649 current_ts = 459.784027 current_received_ts = 459.783905 current_seq = 17650 count = 195 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 27us (kms_flip:2570) DEBUG: name = flip last_ts = 459.784027 last_received_ts = 459.783905 last_seq = 17650 current_ts = 459.800690 current_received_ts = 459.800568 current_seq = 17651 count = 196 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.800690 last_received_ts = 459.800568 last_seq = 17651 current_ts = 459.817322 current_received_ts = 459.817230 current_seq = 17652 count = 197 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 459.817322 last_received_ts = 459.817230 last_seq = 17652 current_ts = 459.834015 current_received_ts = 459.833832 current_seq = 17653 count = 198 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 20us (kms_flip:2570) DEBUG: name = flip last_ts = 459.834015 last_received_ts = 459.833832 last_seq = 17653 current_ts = 459.850677 current_received_ts = 459.850555 current_seq = 17654 count = 199 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.850677 last_received_ts = 459.850555 last_seq = 17654 current_ts = 459.867310 current_received_ts = 459.867126 current_seq = 17655 count = 200 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 459.867310 last_received_ts = 459.867126 last_seq = 17655 current_ts = 459.883972 current_received_ts = 459.883881 current_seq = 17656 count = 201 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.883972 last_received_ts = 459.883881 last_seq = 17656 current_ts = 459.900665 current_received_ts = 459.900391 current_seq = 17657 count = 202 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 459.900665 last_received_ts = 459.900391 last_seq = 17657 current_ts = 459.917297 current_received_ts = 459.917206 current_seq = 17658 count = 203 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 459.917297 last_received_ts = 459.917206 last_seq = 17658 current_ts = 459.933960 current_received_ts = 459.933807 current_seq = 17659 count = 204 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 18us (kms_flip:2570) DEBUG: name = flip last_ts = 459.933960 last_received_ts = 459.933807 last_seq = 17659 current_ts = 459.950623 current_received_ts = 459.950500 current_seq = 17660 count = 205 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 459.950623 last_received_ts = 459.950500 last_seq = 17660 current_ts = 459.967285 current_received_ts = 459.967194 current_seq = 17661 count = 206 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 459.967285 last_received_ts = 459.967194 last_seq = 17661 current_ts = 459.983948 current_received_ts = 459.983795 current_seq = 17662 count = 207 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 20us (kms_flip:2570) DEBUG: name = flip last_ts = 459.983948 last_received_ts = 459.983795 last_seq = 17662 current_ts = 460.000610 current_received_ts = 460.000366 current_seq = 17663 count = 208 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 460.000610 last_received_ts = 460.000366 last_seq = 17663 current_ts = 460.017273 current_received_ts = 460.017090 current_seq = 17664 count = 209 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 460.017273 last_received_ts = 460.017090 last_seq = 17664 current_ts = 460.033936 current_received_ts = 460.033813 current_seq = 17665 count = 210 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 460.033936 last_received_ts = 460.033813 last_seq = 17665 current_ts = 460.050598 current_received_ts = 460.050476 current_seq = 17666 count = 211 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 460.050598 last_received_ts = 460.050476 last_seq = 17666 current_ts = 460.067261 current_received_ts = 460.067200 current_seq = 17667 count = 212 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 460.067261 last_received_ts = 460.067200 last_seq = 17667 current_ts = 460.083923 current_received_ts = 460.083771 current_seq = 17668 count = 213 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 21us (kms_flip:2570) DEBUG: name = flip last_ts = 460.083923 last_received_ts = 460.083771 last_seq = 17668 current_ts = 460.100586 current_received_ts = 460.100311 current_seq = 17669 count = 214 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 460.100586 last_received_ts = 460.100311 last_seq = 17669 current_ts = 460.117249 current_received_ts = 460.117218 current_seq = 17670 count = 215 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 460.117249 last_received_ts = 460.117218 last_seq = 17670 current_ts = 460.133911 current_received_ts = 460.133820 current_seq = 17671 count = 216 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 460.133911 last_received_ts = 460.133820 last_seq = 17671 current_ts = 460.150574 current_received_ts = 460.150452 current_seq = 17672 count = 217 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 27us (kms_flip:2570) DEBUG: name = flip last_ts = 460.150574 last_received_ts = 460.150452 last_seq = 17672 current_ts = 460.167236 current_received_ts = 460.167145 current_seq = 17673 count = 218 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 460.167236 last_received_ts = 460.167145 last_seq = 17673 current_ts = 460.183899 current_received_ts = 460.183777 current_seq = 17674 count = 219 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 27us (kms_flip:2570) DEBUG: name = flip last_ts = 460.183899 last_received_ts = 460.183777 last_seq = 17674 current_ts = 460.200562 current_received_ts = 460.200439 current_seq = 17675 count = 220 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 460.200562 last_received_ts = 460.200439 last_seq = 17675 current_ts = 460.217224 current_received_ts = 460.217163 current_seq = 17676 count = 221 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 27us (kms_flip:2570) DEBUG: name = flip last_ts = 460.217224 last_received_ts = 460.217163 last_seq = 17676 current_ts = 460.233887 current_received_ts = 460.233734 current_seq = 17677 count = 222 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 18us (kms_flip:2570) DEBUG: name = flip last_ts = 460.233887 last_received_ts = 460.233734 last_seq = 17677 current_ts = 460.250549 current_received_ts = 460.250397 current_seq = 17678 count = 223 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 27us (kms_flip:2570) DEBUG: name = flip last_ts = 460.250549 last_received_ts = 460.250397 last_seq = 17678 current_ts = 460.267212 current_received_ts = 460.267120 current_seq = 17679 count = 224 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 460.267212 last_received_ts = 460.267120 last_seq = 17679 current_ts = 460.283844 current_received_ts = 460.283722 current_seq = 17680 count = 225 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 460.283844 last_received_ts = 460.283722 last_seq = 17680 current_ts = 460.300507 current_received_ts = 460.300293 current_seq = 17681 count = 226 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 460.300507 last_received_ts = 460.300293 last_seq = 17681 current_ts = 460.317200 current_received_ts = 460.317078 current_seq = 17682 count = 227 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 460.317200 last_received_ts = 460.317078 last_seq = 17682 current_ts = 460.333832 current_received_ts = 460.333710 current_seq = 17683 count = 228 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 24us (kms_flip:2570) DEBUG: name = flip last_ts = 460.333832 last_received_ts = 460.333710 last_seq = 17683 current_ts = 460.350494 current_received_ts = 460.350403 current_seq = 17684 count = 229 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 27us (kms_flip:2570) DEBUG: name = flip last_ts = 460.350494 last_received_ts = 460.350403 last_seq = 17684 current_ts = 460.367157 current_received_ts = 460.367096 current_seq = 17685 count = 230 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 460.367157 last_received_ts = 460.367096 last_seq = 17685 current_ts = 460.383820 current_received_ts = 460.383698 current_seq = 17686 count = 231 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 460.383820 last_received_ts = 460.383698 last_seq = 17686 current_ts = 460.400482 current_received_ts = 460.400360 current_seq = 17687 count = 232 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 460.400482 last_received_ts = 460.400360 last_seq = 17687 current_ts = 460.417145 current_received_ts = 460.417084 current_seq = 17688 count = 233 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 460.417145 last_received_ts = 460.417084 last_seq = 17688 current_ts = 460.433807 current_received_ts = 460.433685 current_seq = 17689 count = 234 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 27us (kms_flip:2570) DEBUG: name = flip last_ts = 460.433807 last_received_ts = 460.433685 last_seq = 17689 current_ts = 460.450470 current_received_ts = 460.450348 current_seq = 17690 count = 235 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 25us (kms_flip:2570) DEBUG: name = flip last_ts = 460.450470 last_received_ts = 460.450348 last_seq = 17690 current_ts = 460.467133 current_received_ts = 460.467102 current_seq = 17691 count = 236 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 26us (kms_flip:2570) DEBUG: name = flip last_ts = 460.467133 last_received_ts = 460.467102 last_seq = 17691 current_ts = 460.483795 current_received_ts = 460.483673 current_seq = 17692 count = 237 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 27us (kms_flip:2570) DEBUG: name = flip last_ts = 460.483795 last_received_ts = 460.483673 last_seq = 17692 current_ts = 460.500458 current_received_ts = 460.500244 current_seq = 17693 count = 238 seq_step = 1 (kms_flip:2570) DEBUG: Vblank took 854us (kms_flip:2570) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:2570) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2570) igt_core-INFO: Stack trace: (kms_flip:2570) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2570) igt_core-INFO: #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() (kms_flip:2570) igt_core-INFO: #2 ../tests/kms_flip.c:1891 run_test() (kms_flip:2570) igt_core-INFO: #3 ../tests/kms_flip.c:2126 __igt_unique____real_main2047() (kms_flip:2570) igt_core-INFO: #4 ../tests/kms_flip.c:2047 main() (kms_flip:2570) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2570) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2570) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-HDMI-A2: FAIL (5.049s)
Dmesg	<6> [456.726757] [IGT] kms_flip: starting dynamic subtest A-HDMI-A2 <7> [456.728122] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:180] <7> [456.729033] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:184] <7> [456.787943] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A] <7> [456.788993] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [456.789820] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C] <7> [456.790193] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.enable (expected yes, found no) <7> [456.791363] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.active (expected yes, found no) <7> [456.792573] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in cpu_transcoder (expected 2, found -1) <7> [456.793131] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in lane_count (expected 4, found 0) <7> [456.793548] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000) <7> [456.793929] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [456.794308] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [456.794733] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [456.795114] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [456.795534] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [456.795990] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [456.796369] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [456.796767] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [456.797143] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [456.797731] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [456.798198] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [456.798729] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [456.799120] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [456.799533] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [456.799931] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [456.800305] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [456.800744] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [456.801142] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [456.801567] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [456.801944] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [456.802317] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [456.802754] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [456.803129] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [456.803587] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [456.803968] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [456.804347] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [456.804790] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [456.805177] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [456.805624] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [456.806004] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [456.806382] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in has_infoframe (expected yes, found no) <7> [456.806808] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [456.807184] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [456.807617] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [456.807992] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in port_clock (expected 222750, found 0) <7> [456.808366] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [456.808768] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000) <7> [456.809144] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in avi infoframe <7> [456.809642] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [456.810023] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [456.810028] i915 0000:00:02.0: colorspace: RGB <7> [456.810032] i915 0000:00:02.0: scan mode: Underscan <7> [456.810035] i915 0000:00:02.0: colorimetry: No Data <7> [456.810039] i915 0000:00:02.0: picture aspect: No Data <7> [456.810042] i915 0000:00:02.0: active aspect: Same as Picture <7> [456.810046] i915 0000:00:02.0: itc: No Data <7> [456.810049] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [456.810053] i915 0000:00:02.0: quantization range: Full <7> [456.810056] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [456.810060] i915 0000:00:02.0: video code: 0 <7> [456.810063] i915 0000:00:02.0: ycc quantization range: Full <7> [456.810066] i915 0000:00:02.0: hdmi content type: Graphics <7> [456.810069] i915 0000:00:02.0: pixel repeat: 0 <7> [456.810073] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [456.810076] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [456.810477] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in spd infoframe <7> [456.810852] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [456.811227] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [456.811231] i915 0000:00:02.0: vendor: Intel <7> [456.811235] i915 0000:00:02.0: product: Integrated gfx <7> [456.811238] i915 0000:00:02.0: source device information: PC General (0x9) <7> [456.811241] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [456.811916] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hdmi infoframe <7> [456.812379] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [456.812876] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [456.812881] i915 0000:00:02.0: empty frame <7> [456.812884] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [456.813265] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:164:pipe C] fastset requirement not met, forcing full modeset <7> [456.813687] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:164:pipe C] releasing PORT PLL B <7> [456.814146] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:164:pipe C] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x4 -> 0x0 <7> [456.814645] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:158:cursor C] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0 <7> [456.815122] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:164:pipe C] min cdclk: 192000 kHz -> 0 kHz <7> [456.815612] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [456.815986] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz <7> [456.816360] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4 <7> [456.816815] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:164:pipe C] enable: no [modeset] <7> [456.817198] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:122:plane 1C] fb: [NOFB], visible: no <7> [456.817674] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:131:plane 2C] fb: [NOFB], visible: no <7> [456.818055] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:140:plane 3C] fb: [NOFB], visible: no <7> [456.818433] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:149:plane 4C] fb: [NOFB], visible: no <7> [456.818879] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:158:cursor C] fb: [NOFB], visible: no <7> [456.819443] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:166:HDMI-A-1][ENCODER:165:DDI B/PHY B] Disable audio codec on [CRTC:164:pipe C] <7> [456.838324] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [456.839248] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe C <7> [456.851061] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10 <7> [456.856556] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time <7> [456.957987] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [456.959336] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x4, on? 1) for [CRTC:164:pipe C] <7> [456.963294] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL B <7> [456.963877] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 79200 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 4 <7> [456.964305] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [456.964780] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [456.965159] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:166:HDMI-A-1] <7> [456.965775] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-b <7> [456.966233] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:164:pipe C] <7> [456.968382] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A] <7> [456.968161] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [456.968612] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz <7> [456.969019] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13 <7> [456.969489] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 316800 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 13 <7> [456.970618] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:176:HDMI-A-2] <7> [456.970900] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 12 bpc for HDMI output (pipe bpp: 36) <7> [456.971327] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:78:pipe A] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [456.972582] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:175:DDI C/PHY C] [CRTC:78:pipe A] <7> [456.972972] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [456.973375] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [456.973822] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [456.974203] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [456.974598] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d) <7> [456.974975] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [456.975353] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [456.976122] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [456.976893] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [456.977278] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [456.977936] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL <7> [456.977953] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled <7> [456.977994] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [456.978378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [456.978951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [456.979330] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [456.979899] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [456.980278] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [456.980876] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [456.981259] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [456.982109] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [456.982799] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [456.983185] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [456.983756] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [456.984135] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [456.984703] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [456.985091] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [456.985466] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [456.986528] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [456.986917] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [456.987293] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [456.988040] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [456.988437] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [456.989002] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [456.989383] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [456.989951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [456.990332] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [456.990954] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_infoframe (expected no, found yes) <7> [456.991338] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [456.992074] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [456.992764] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [456.993147] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in port_clock (expected 0, found 222750) <7> [456.993709] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [456.994092] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006) <7> [456.994467] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in avi infoframe <7> [456.995188] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [456.995739] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [456.996122] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [456.996127] i915 0000:00:02.0: colorspace: RGB <7> [456.996131] i915 0000:00:02.0: scan mode: Underscan <7> [456.996134] i915 0000:00:02.0: colorimetry: No Data <7> [456.996138] i915 0000:00:02.0: picture aspect: No Data <7> [456.996141] i915 0000:00:02.0: active aspect: Same as Picture <7> [456.996145] i915 0000:00:02.0: itc: No Data <7> [456.996148] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [456.996151] i915 0000:00:02.0: quantization range: Full <7> [456.996154] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [456.996158] i915 0000:00:02.0: video code: 0 <7> [456.996161] i915 0000:00:02.0: ycc quantization range: Full <7> [456.996164] i915 0000:00:02.0: hdmi content type: Graphics <7> [456.996168] i915 0000:00:02.0: pixel repeat: 0 <7> [456.996171] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [456.996175] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in spd infoframe <7> [456.997048] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [456.997432] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [456.998090] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [456.998095] i915 0000:00:02.0: vendor: Intel <7> [456.998099] i915 0000:00:02.0: product: Integrated gfx <7> [456.998103] i915 0000:00:02.0: source device information: PC General (0x9) <7> [456.998107] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hdmi infoframe <7> [456.998487] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [456.999168] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [456.999721] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [456.999726] i915 0000:00:02.0: empty frame <7> [456.999732] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:78:pipe A] fastset requirement not met, forcing full modeset <7> [457.000195] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:78:pipe A] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x1 <7> [457.000863] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:36:plane 1A] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988 <7> [457.001243] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:72:cursor A] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32 <7> [457.001884] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:36:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,*twm, swm, stwm <7> [457.002308] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:36:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0 <7> [457.002930] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:36:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0 <7> [457.003310] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:36:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 17, 17, 17, 34, 34, 34, 34, 34, 31, 0, 0 <7> [457.003877] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:36:plane 1A] min_ddb_uv 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [457.004353] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:78:pipe A] min cdclk: 0 kHz -> 192000 kHz <7> [457.004973] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:78:pipe A] using pre-allocated PORT PLL C <7> [457.005359] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:78:pipe A] reserving PORT PLL C <7> [457.006351] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:78:pipe A] enable: yes [modeset] <7> [457.007034] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [457.007426] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 36, dithering: 0 <7> [457.007964] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [457.008340] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [457.008892] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [457.009272] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [457.009935] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [457.010318] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6 <7> [457.010936] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [457.010942] i915 0000:00:02.0: colorspace: RGB <7> [457.010947] i915 0000:00:02.0: scan mode: Underscan <7> [457.010950] i915 0000:00:02.0: colorimetry: No Data <7> [457.010954] i915 0000:00:02.0: picture aspect: No Data <7> [457.010957] i915 0000:00:02.0: active aspect: Same as Picture <7> [457.010961] i915 0000:00:02.0: itc: No Data <7> [457.010964] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [457.010968] i915 0000:00:02.0: quantization range: Full <7> [457.010971] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [457.010974] i915 0000:00:02.0: video code: 0 <7> [457.010978] i915 0000:00:02.0: ycc quantization range: Full <7> [457.010981] i915 0000:00:02.0: hdmi content type: Graphics <7> [457.010985] i915 0000:00:02.0: pixel repeat: 0 <7> [457.010988] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [457.010992] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [457.010996] i915 0000:00:02.0: vendor: Intel <7> [457.010999] i915 0000:00:02.0: product: Integrated gfx <7> [457.011003] i915 0000:00:02.0: source device information: PC General (0x9) <7> [457.011007] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [457.011011] i915 0000:00:02.0: empty frame <7> [457.011015] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 07 00 66 10 00 01 00 00 00 00 00 00 00 00 <7> [457.011450] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 05 e3 cd 0c 32 38 45 38 35 30 09 07 07 00 00 00 <7> [457.012162] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [457.012720] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [457.013103] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0 <7> [457.013481] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0 <7> [457.014059] 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> [457.014439] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [457.015420] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [457.016138] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9 <7> [457.016819] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x40 0x9 <7> [457.017208] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9 <7> [457.017759] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pipe src: 1920x1080+0+0, pixel rate 148500, min cdclk 192000 <7> [457.018139] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [457.018723] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [457.019103] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [457.019479] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [457.020229] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: ebb0: 0x6200, ebb4: 0x2000,pll0: 0x21, pll1: 0x100, pll2: 0x1a6666, pll3: 0x10000, pll6: 0x30904, pll8: 0x8, pll9: 0xa, pll10: 0x8003c00, pcsdw12: 0x4d <7> [457.020874] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [457.021258] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [457.021815] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [457.022195] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [457.022772] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [457.023151] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [457.024025] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [457.024408] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [457.025084] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:36:plane 1A] fb: [FB:180] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [457.025481] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [457.026019] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [457.026400] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:45:plane 2A] fb: [NOFB], visible: no <7> [457.026955] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:plane 3A] fb: [NOFB], visible: no <7> [457.027346] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 4A] fb: [NOFB], visible: no <7> [457.028006] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:72:cursor A] fb: [NOFB], visible: no <7> [457.029245] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-c <7> [457.030411] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [457.030843] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [457.031380] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL C (active 0x1, on? 0) for [CRTC:78:pipe A] <7> [457.032113] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL C <7> [457.032837] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_C <7> [457.033328] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A <7> [457.035329] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] reserved 16588800 bytes of contiguous stolen space for FBC, limit: 1 <7> [457.035778] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] Enabling FBC on [PLANE:36:plane 1A] <7> [457.052010] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:176:HDMI-A-2][ENCODER:175:DDI C/PHY C] Enable audio codec on [CRTC:78:pipe A], 32 bytes ELD <7> [457.068804] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000) <7> [457.069297] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <7> [457.071420] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:176:HDMI-A-2] <7> [457.072733] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:78:pipe A] <6> [461.776762] [IGT] kms_flip: finished subtest A-HDMI-A2, FAIL

Detail

Value

Duration

5.05 seconds

Hostname

shard-glk6

Igt-Version

IGT-Version: 2.3-ga7015a99f (x86_64) (Linux: 7.0.0-rc4-CI_DRM_18186-g166a38809296+ x86_64)

Out

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

Err

Starting dynamic subtest: A-HDMI-A2
(kms_flip:2570) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:2570) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.467773
last_received_ts = 458.467529
last_seq = 17571
current_ts = 458.484406
current_received_ts = 458.484222
current_seq = 17572
count = 117
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 21us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.484406
last_received_ts = 458.484222
last_seq = 17572
current_ts = 458.501099
current_received_ts = 458.501373
current_seq = 17573
count = 118
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 21us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.501099
last_received_ts = 458.501373
last_seq = 17573
current_ts = 458.517731
current_received_ts = 458.517670
current_seq = 17574
count = 119
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.517731
last_received_ts = 458.517670
last_seq = 17574
current_ts = 458.534424
current_received_ts = 458.534241
current_seq = 17575
count = 120
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.534424
last_received_ts = 458.534241
last_seq = 17575
current_ts = 458.551056
current_received_ts = 458.550934
current_seq = 17576
count = 121
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.551056
last_received_ts = 458.550934
last_seq = 17576
current_ts = 458.567719
current_received_ts = 458.567566
current_seq = 17577
count = 122
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 22us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.567719
last_received_ts = 458.567566
last_seq = 17577
current_ts = 458.584412
current_received_ts = 458.584320
current_seq = 17578
count = 123
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.584412
last_received_ts = 458.584320
last_seq = 17578
current_ts = 458.601044
current_received_ts = 458.600983
current_seq = 17579
count = 124
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.601044
last_received_ts = 458.600983
last_seq = 17579
current_ts = 458.617706
current_received_ts = 458.617584
current_seq = 17580
count = 125
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.617706
last_received_ts = 458.617584
last_seq = 17580
current_ts = 458.634369
current_received_ts = 458.634308
current_seq = 17581
count = 126
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.634369
last_received_ts = 458.634308
last_seq = 17581
current_ts = 458.651031
current_received_ts = 458.650940
current_seq = 17582
count = 127
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.651031
last_received_ts = 458.650940
last_seq = 17582
current_ts = 458.667694
current_received_ts = 458.667633
current_seq = 17583
count = 128
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.667694
last_received_ts = 458.667633
last_seq = 17583
current_ts = 458.684357
current_received_ts = 458.684296
current_seq = 17584
count = 129
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.684357
last_received_ts = 458.684296
last_seq = 17584
current_ts = 458.701019
current_received_ts = 458.701355
current_seq = 17585
count = 130
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 21us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.701019
last_received_ts = 458.701355
last_seq = 17585
current_ts = 458.717682
current_received_ts = 458.717560
current_seq = 17586
count = 131
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.717682
last_received_ts = 458.717560
last_seq = 17586
current_ts = 458.734344
current_received_ts = 458.734253
current_seq = 17587
count = 132
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.734344
last_received_ts = 458.734253
last_seq = 17587
current_ts = 458.751007
current_received_ts = 458.750854
current_seq = 17588
count = 133
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.751007
last_received_ts = 458.750854
last_seq = 17588
current_ts = 458.767670
current_received_ts = 458.767578
current_seq = 17589
count = 134
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.767670
last_received_ts = 458.767578
last_seq = 17589
current_ts = 458.784332
current_received_ts = 458.784241
current_seq = 17590
count = 135
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.784332
last_received_ts = 458.784241
last_seq = 17590
current_ts = 458.800995
current_received_ts = 458.800934
current_seq = 17591
count = 136
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 96us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.800995
last_received_ts = 458.800934
last_seq = 17591
current_ts = 458.817657
current_received_ts = 458.817566
current_seq = 17592
count = 137
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 23us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.817657
last_received_ts = 458.817566
last_seq = 17592
current_ts = 458.834320
current_received_ts = 458.834259
current_seq = 17593
count = 138
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.834320
last_received_ts = 458.834259
last_seq = 17593
current_ts = 458.850983
current_received_ts = 458.850677
current_seq = 17594
count = 139
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.850983
last_received_ts = 458.850677
last_seq = 17594
current_ts = 458.867645
current_received_ts = 458.867554
current_seq = 17595
count = 140
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.867645
last_received_ts = 458.867554
last_seq = 17595
current_ts = 458.884308
current_received_ts = 458.884247
current_seq = 17596
count = 141
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.884308
last_received_ts = 458.884247
last_seq = 17596
current_ts = 458.900940
current_received_ts = 458.901215
current_seq = 17597
count = 142
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 21us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.900940
last_received_ts = 458.901215
last_seq = 17597
current_ts = 458.917633
current_received_ts = 458.917511
current_seq = 17598
count = 143
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 27us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.917633
last_received_ts = 458.917511
last_seq = 17598
current_ts = 458.934296
current_received_ts = 458.934174
current_seq = 17599
count = 144
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.934296
last_received_ts = 458.934174
last_seq = 17599
current_ts = 458.950958
current_received_ts = 458.950745
current_seq = 17600
count = 145
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 21us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.950958
last_received_ts = 458.950745
last_seq = 17600
current_ts = 458.967621
current_received_ts = 458.967499
current_seq = 17601
count = 146
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 27us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.967621
last_received_ts = 458.967499
last_seq = 17601
current_ts = 458.984253
current_received_ts = 458.984161
current_seq = 17602
count = 147
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 458.984253
last_received_ts = 458.984161
last_seq = 17602
current_ts = 459.000916
current_received_ts = 459.000702
current_seq = 17603
count = 148
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 20us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.000916
last_received_ts = 459.000702
last_seq = 17603
current_ts = 459.017609
current_received_ts = 459.017456
current_seq = 17604
count = 149
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.017609
last_received_ts = 459.017456
last_seq = 17604
current_ts = 459.034241
current_received_ts = 459.034149
current_seq = 17605
count = 150
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.034241
last_received_ts = 459.034149
last_seq = 17605
current_ts = 459.050903
current_received_ts = 459.050751
current_seq = 17606
count = 151
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.050903
last_received_ts = 459.050751
last_seq = 17606
current_ts = 459.067566
current_received_ts = 459.067413
current_seq = 17607
count = 152
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.067566
last_received_ts = 459.067413
last_seq = 17607
current_ts = 459.084229
current_received_ts = 459.084106
current_seq = 17608
count = 153
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.084229
last_received_ts = 459.084106
last_seq = 17608
current_ts = 459.100891
current_received_ts = 459.100494
current_seq = 17609
count = 154
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.100891
last_received_ts = 459.100494
last_seq = 17609
current_ts = 459.117554
current_received_ts = 459.117432
current_seq = 17610
count = 155
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.117554
last_received_ts = 459.117432
last_seq = 17610
current_ts = 459.134216
current_received_ts = 459.134125
current_seq = 17611
count = 156
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.134216
last_received_ts = 459.134125
last_seq = 17611
current_ts = 459.150879
current_received_ts = 459.150604
current_seq = 17612
count = 157
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 20us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.150879
last_received_ts = 459.150604
last_seq = 17612
current_ts = 459.167542
current_received_ts = 459.167419
current_seq = 17613
count = 158
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.167542
last_received_ts = 459.167419
last_seq = 17613
current_ts = 459.184204
current_received_ts = 459.184143
current_seq = 17614
count = 159
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.184204
last_received_ts = 459.184143
last_seq = 17614
current_ts = 459.200867
current_received_ts = 459.200745
current_seq = 17615
count = 160
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 20us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.200867
last_received_ts = 459.200745
last_seq = 17615
current_ts = 459.217529
current_received_ts = 459.217407
current_seq = 17616
count = 161
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.217529
last_received_ts = 459.217407
last_seq = 17616
current_ts = 459.234192
current_received_ts = 459.234039
current_seq = 17617
count = 162
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 17us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.234192
last_received_ts = 459.234039
last_seq = 17617
current_ts = 459.250854
current_received_ts = 459.250519
current_seq = 17618
count = 163
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.250854
last_received_ts = 459.250519
last_seq = 17618
current_ts = 459.267517
current_received_ts = 459.267395
current_seq = 17619
count = 164
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.267517
last_received_ts = 459.267395
last_seq = 17619
current_ts = 459.284180
current_received_ts = 459.283997
current_seq = 17620
count = 165
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 18us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.284180
last_received_ts = 459.283997
last_seq = 17620
current_ts = 459.300842
current_received_ts = 459.300537
current_seq = 17621
count = 166
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.300842
last_received_ts = 459.300537
last_seq = 17621
current_ts = 459.317505
current_received_ts = 459.317383
current_seq = 17622
count = 167
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.317505
last_received_ts = 459.317383
last_seq = 17622
current_ts = 459.334167
current_received_ts = 459.333984
current_seq = 17623
count = 168
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 18us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.334167
last_received_ts = 459.333984
last_seq = 17623
current_ts = 459.350800
current_received_ts = 459.350525
current_seq = 17624
count = 169
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.350800
last_received_ts = 459.350525
last_seq = 17624
current_ts = 459.367462
current_received_ts = 459.367371
current_seq = 17625
count = 170
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.367462
last_received_ts = 459.367371
last_seq = 17625
current_ts = 459.384155
current_received_ts = 459.383972
current_seq = 17626
count = 171
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 17us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.384155
last_received_ts = 459.383972
last_seq = 17626
current_ts = 459.400787
current_received_ts = 459.400696
current_seq = 17627
count = 172
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.400787
last_received_ts = 459.400696
last_seq = 17627
current_ts = 459.417450
current_received_ts = 459.417358
current_seq = 17628
count = 173
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.417450
last_received_ts = 459.417358
last_seq = 17628
current_ts = 459.434143
current_received_ts = 459.433960
current_seq = 17629
count = 174
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 94us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.434143
last_received_ts = 459.433960
last_seq = 17629
current_ts = 459.450775
current_received_ts = 459.450684
current_seq = 17630
count = 175
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.450775
last_received_ts = 459.450684
last_seq = 17630
current_ts = 459.467438
current_received_ts = 459.467346
current_seq = 17631
count = 176
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.467438
last_received_ts = 459.467346
last_seq = 17631
current_ts = 459.484100
current_received_ts = 459.483917
current_seq = 17632
count = 177
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 18us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.484100
last_received_ts = 459.483917
last_seq = 17632
current_ts = 459.500763
current_received_ts = 459.500427
current_seq = 17633
count = 178
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.500763
last_received_ts = 459.500427
last_seq = 17633
current_ts = 459.517426
current_received_ts = 459.517334
current_seq = 17634
count = 179
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.517426
last_received_ts = 459.517334
last_seq = 17634
current_ts = 459.534088
current_received_ts = 459.533936
current_seq = 17635
count = 180
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 81us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.534088
last_received_ts = 459.533936
last_seq = 17635
current_ts = 459.550751
current_received_ts = 459.550629
current_seq = 17636
count = 181
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.550751
last_received_ts = 459.550629
last_seq = 17636
current_ts = 459.567413
current_received_ts = 459.567291
current_seq = 17637
count = 182
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.567413
last_received_ts = 459.567291
last_seq = 17637
current_ts = 459.584076
current_received_ts = 459.583984
current_seq = 17638
count = 183
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.584076
last_received_ts = 459.583984
last_seq = 17638
current_ts = 459.600739
current_received_ts = 459.600403
current_seq = 17639
count = 184
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.600739
last_received_ts = 459.600403
last_seq = 17639
current_ts = 459.617401
current_received_ts = 459.617310
current_seq = 17640
count = 185
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.617401
last_received_ts = 459.617310
last_seq = 17640
current_ts = 459.634064
current_received_ts = 459.633942
current_seq = 17641
count = 186
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.634064
last_received_ts = 459.633942
last_seq = 17641
current_ts = 459.650726
current_received_ts = 459.650421
current_seq = 17642
count = 187
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.650726
last_received_ts = 459.650421
last_seq = 17642
current_ts = 459.667389
current_received_ts = 459.667267
current_seq = 17643
count = 188
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.667389
last_received_ts = 459.667267
last_seq = 17643
current_ts = 459.684052
current_received_ts = 459.683899
current_seq = 17644
count = 189
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 20us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.684052
last_received_ts = 459.683899
last_seq = 17644
current_ts = 459.700714
current_received_ts = 459.700562
current_seq = 17645
count = 190
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.700714
last_received_ts = 459.700562
last_seq = 17645
current_ts = 459.717377
current_received_ts = 459.717255
current_seq = 17646
count = 191
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.717377
last_received_ts = 459.717255
last_seq = 17646
current_ts = 459.734039
current_received_ts = 459.733887
current_seq = 17647
count = 192
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 20us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.734039
last_received_ts = 459.733887
last_seq = 17647
current_ts = 459.750702
current_received_ts = 459.750549
current_seq = 17648
count = 193
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.750702
last_received_ts = 459.750549
last_seq = 17648
current_ts = 459.767365
current_received_ts = 459.767242
current_seq = 17649
count = 194
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.767365
last_received_ts = 459.767242
last_seq = 17649
current_ts = 459.784027
current_received_ts = 459.783905
current_seq = 17650
count = 195
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 27us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.784027
last_received_ts = 459.783905
last_seq = 17650
current_ts = 459.800690
current_received_ts = 459.800568
current_seq = 17651
count = 196
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.800690
last_received_ts = 459.800568
last_seq = 17651
current_ts = 459.817322
current_received_ts = 459.817230
current_seq = 17652
count = 197
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.817322
last_received_ts = 459.817230
last_seq = 17652
current_ts = 459.834015
current_received_ts = 459.833832
current_seq = 17653
count = 198
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 20us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.834015
last_received_ts = 459.833832
last_seq = 17653
current_ts = 459.850677
current_received_ts = 459.850555
current_seq = 17654
count = 199
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.850677
last_received_ts = 459.850555
last_seq = 17654
current_ts = 459.867310
current_received_ts = 459.867126
current_seq = 17655
count = 200
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.867310
last_received_ts = 459.867126
last_seq = 17655
current_ts = 459.883972
current_received_ts = 459.883881
current_seq = 17656
count = 201
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.883972
last_received_ts = 459.883881
last_seq = 17656
current_ts = 459.900665
current_received_ts = 459.900391
current_seq = 17657
count = 202
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.900665
last_received_ts = 459.900391
last_seq = 17657
current_ts = 459.917297
current_received_ts = 459.917206
current_seq = 17658
count = 203
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.917297
last_received_ts = 459.917206
last_seq = 17658
current_ts = 459.933960
current_received_ts = 459.933807
current_seq = 17659
count = 204
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 18us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.933960
last_received_ts = 459.933807
last_seq = 17659
current_ts = 459.950623
current_received_ts = 459.950500
current_seq = 17660
count = 205
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.950623
last_received_ts = 459.950500
last_seq = 17660
current_ts = 459.967285
current_received_ts = 459.967194
current_seq = 17661
count = 206
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.967285
last_received_ts = 459.967194
last_seq = 17661
current_ts = 459.983948
current_received_ts = 459.983795
current_seq = 17662
count = 207
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 20us
(kms_flip:2570) DEBUG: name = flip
last_ts = 459.983948
last_received_ts = 459.983795
last_seq = 17662
current_ts = 460.000610
current_received_ts = 460.000366
current_seq = 17663
count = 208
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.000610
last_received_ts = 460.000366
last_seq = 17663
current_ts = 460.017273
current_received_ts = 460.017090
current_seq = 17664
count = 209
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.017273
last_received_ts = 460.017090
last_seq = 17664
current_ts = 460.033936
current_received_ts = 460.033813
current_seq = 17665
count = 210
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.033936
last_received_ts = 460.033813
last_seq = 17665
current_ts = 460.050598
current_received_ts = 460.050476
current_seq = 17666
count = 211
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.050598
last_received_ts = 460.050476
last_seq = 17666
current_ts = 460.067261
current_received_ts = 460.067200
current_seq = 17667
count = 212
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.067261
last_received_ts = 460.067200
last_seq = 17667
current_ts = 460.083923
current_received_ts = 460.083771
current_seq = 17668
count = 213
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 21us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.083923
last_received_ts = 460.083771
last_seq = 17668
current_ts = 460.100586
current_received_ts = 460.100311
current_seq = 17669
count = 214
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.100586
last_received_ts = 460.100311
last_seq = 17669
current_ts = 460.117249
current_received_ts = 460.117218
current_seq = 17670
count = 215
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.117249
last_received_ts = 460.117218
last_seq = 17670
current_ts = 460.133911
current_received_ts = 460.133820
current_seq = 17671
count = 216
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.133911
last_received_ts = 460.133820
last_seq = 17671
current_ts = 460.150574
current_received_ts = 460.150452
current_seq = 17672
count = 217
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 27us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.150574
last_received_ts = 460.150452
last_seq = 17672
current_ts = 460.167236
current_received_ts = 460.167145
current_seq = 17673
count = 218
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.167236
last_received_ts = 460.167145
last_seq = 17673
current_ts = 460.183899
current_received_ts = 460.183777
current_seq = 17674
count = 219
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 27us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.183899
last_received_ts = 460.183777
last_seq = 17674
current_ts = 460.200562
current_received_ts = 460.200439
current_seq = 17675
count = 220
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.200562
last_received_ts = 460.200439
last_seq = 17675
current_ts = 460.217224
current_received_ts = 460.217163
current_seq = 17676
count = 221
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 27us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.217224
last_received_ts = 460.217163
last_seq = 17676
current_ts = 460.233887
current_received_ts = 460.233734
current_seq = 17677
count = 222
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 18us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.233887
last_received_ts = 460.233734
last_seq = 17677
current_ts = 460.250549
current_received_ts = 460.250397
current_seq = 17678
count = 223
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 27us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.250549
last_received_ts = 460.250397
last_seq = 17678
current_ts = 460.267212
current_received_ts = 460.267120
current_seq = 17679
count = 224
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.267212
last_received_ts = 460.267120
last_seq = 17679
current_ts = 460.283844
current_received_ts = 460.283722
current_seq = 17680
count = 225
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.283844
last_received_ts = 460.283722
last_seq = 17680
current_ts = 460.300507
current_received_ts = 460.300293
current_seq = 17681
count = 226
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.300507
last_received_ts = 460.300293
last_seq = 17681
current_ts = 460.317200
current_received_ts = 460.317078
current_seq = 17682
count = 227
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.317200
last_received_ts = 460.317078
last_seq = 17682
current_ts = 460.333832
current_received_ts = 460.333710
current_seq = 17683
count = 228
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 24us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.333832
last_received_ts = 460.333710
last_seq = 17683
current_ts = 460.350494
current_received_ts = 460.350403
current_seq = 17684
count = 229
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 27us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.350494
last_received_ts = 460.350403
last_seq = 17684
current_ts = 460.367157
current_received_ts = 460.367096
current_seq = 17685
count = 230
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.367157
last_received_ts = 460.367096
last_seq = 17685
current_ts = 460.383820
current_received_ts = 460.383698
current_seq = 17686
count = 231
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.383820
last_received_ts = 460.383698
last_seq = 17686
current_ts = 460.400482
current_received_ts = 460.400360
current_seq = 17687
count = 232
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.400482
last_received_ts = 460.400360
last_seq = 17687
current_ts = 460.417145
current_received_ts = 460.417084
current_seq = 17688
count = 233
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.417145
last_received_ts = 460.417084
last_seq = 17688
current_ts = 460.433807
current_received_ts = 460.433685
current_seq = 17689
count = 234
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 27us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.433807
last_received_ts = 460.433685
last_seq = 17689
current_ts = 460.450470
current_received_ts = 460.450348
current_seq = 17690
count = 235
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 25us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.450470
last_received_ts = 460.450348
last_seq = 17690
current_ts = 460.467133
current_received_ts = 460.467102
current_seq = 17691
count = 236
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 26us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.467133
last_received_ts = 460.467102
last_seq = 17691
current_ts = 460.483795
current_received_ts = 460.483673
current_seq = 17692
count = 237
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 27us
(kms_flip:2570) DEBUG: name = flip
last_ts = 460.483795
last_received_ts = 460.483673
last_seq = 17692
current_ts = 460.500458
current_received_ts = 460.500244
current_seq = 17693
count = 238
seq_step = 1
(kms_flip:2570) DEBUG: Vblank took 854us
(kms_flip:2570) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:2570) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2570) igt_core-INFO: Stack trace:
(kms_flip:2570) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2570) igt_core-INFO:   #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0()
(kms_flip:2570) igt_core-INFO:   #2 ../tests/kms_flip.c:1891 run_test()
(kms_flip:2570) igt_core-INFO:   #3 ../tests/kms_flip.c:2126 __igt_unique____real_main2047()
(kms_flip:2570) igt_core-INFO:   #4 ../tests/kms_flip.c:2047 main()
(kms_flip:2570) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2570) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2570) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A2: FAIL (5.049s)

Dmesg

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

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

<7> [456.729033] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:184]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [456.972582] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:175:DDI C/PHY C] [CRTC:78:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [457.000863] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:36:plane 1A] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988

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

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

<7> [457.002308] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:36:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0

<7> [457.002930] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:36:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0

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

<7> [457.003877] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:36:plane 1A] min_ddb_uv 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [457.014059] 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> [457.014439] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9

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

<7> [457.016138] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9

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

<7> [457.017208] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [457.072733] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:78:pipe A]

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

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