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

Detail	Value
Duration	4.14 seconds
Hostname	shard-glk2
Igt-Version	IGT-Version: 2.3-g246d93c1d (x86_64) (Linux: 7.0.0-rc3-CI_DRM_18142-g4082c266f293+ 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:921 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1887 run_test() #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2043() #4 ../tests/kms_flip.c:2043 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-HDMI-A2: FAIL (4.136s)
Err	Starting dynamic subtest: A-HDMI-A2 (kms_flip:2500) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2500) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2500) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest A-HDMI-A2 failed. ** DEBUG (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 343.391693 last_received_ts = 343.391541 last_seq = 10644 current_ts = 343.408386 current_received_ts = 343.407837 current_seq = 10645 count = 100 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 343.408386 last_received_ts = 343.407837 last_seq = 10645 current_ts = 343.425049 current_received_ts = 343.424683 current_seq = 10646 count = 101 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 343.425049 last_received_ts = 343.424683 last_seq = 10646 current_ts = 343.441711 current_received_ts = 343.441528 current_seq = 10647 count = 102 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 343.441711 last_received_ts = 343.441528 last_seq = 10647 current_ts = 343.458374 current_received_ts = 343.458252 current_seq = 10648 count = 103 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 343.458374 last_received_ts = 343.458252 last_seq = 10648 current_ts = 343.475037 current_received_ts = 343.475067 current_seq = 10649 count = 104 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 50us (kms_flip:2500) DEBUG: name = flip last_ts = 343.475037 last_received_ts = 343.475067 last_seq = 10649 current_ts = 343.491699 current_received_ts = 343.491974 current_seq = 10650 count = 105 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 19us (kms_flip:2500) DEBUG: name = flip last_ts = 343.491699 last_received_ts = 343.491974 last_seq = 10650 current_ts = 343.508362 current_received_ts = 343.508209 current_seq = 10651 count = 106 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 343.508362 last_received_ts = 343.508209 last_seq = 10651 current_ts = 343.525055 current_received_ts = 343.524567 current_seq = 10652 count = 107 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 343.525055 last_received_ts = 343.524567 last_seq = 10652 current_ts = 343.541687 current_received_ts = 343.541534 current_seq = 10653 count = 108 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.541687 last_received_ts = 343.541534 last_seq = 10653 current_ts = 343.558380 current_received_ts = 343.557861 current_seq = 10654 count = 109 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 343.558380 last_received_ts = 343.557861 last_seq = 10654 current_ts = 343.575043 current_received_ts = 343.574677 current_seq = 10655 count = 110 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 343.575043 last_received_ts = 343.574677 last_seq = 10655 current_ts = 343.591705 current_received_ts = 343.591705 current_seq = 10656 count = 111 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 19us (kms_flip:2500) DEBUG: name = flip last_ts = 343.591705 last_received_ts = 343.591705 last_seq = 10656 current_ts = 343.608368 current_received_ts = 343.608154 current_seq = 10657 count = 112 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 343.608368 last_received_ts = 343.608154 last_seq = 10657 current_ts = 343.625031 current_received_ts = 343.624603 current_seq = 10658 count = 113 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 343.625031 last_received_ts = 343.624603 last_seq = 10658 current_ts = 343.641724 current_received_ts = 343.641296 current_seq = 10659 count = 114 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.641724 last_received_ts = 343.641296 last_seq = 10659 current_ts = 343.658356 current_received_ts = 343.658691 current_seq = 10660 count = 115 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 343.658356 last_received_ts = 343.658691 last_seq = 10660 current_ts = 343.675049 current_received_ts = 343.674988 current_seq = 10661 count = 116 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.675049 last_received_ts = 343.674988 last_seq = 10661 current_ts = 343.691711 current_received_ts = 343.691467 current_seq = 10662 count = 117 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.691711 last_received_ts = 343.691467 last_seq = 10662 current_ts = 343.708374 current_received_ts = 343.708252 current_seq = 10663 count = 118 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.708374 last_received_ts = 343.708252 last_seq = 10663 current_ts = 343.725037 current_received_ts = 343.724579 current_seq = 10664 count = 119 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.725037 last_received_ts = 343.724579 last_seq = 10664 current_ts = 343.741699 current_received_ts = 343.741608 current_seq = 10665 count = 120 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.741699 last_received_ts = 343.741608 last_seq = 10665 current_ts = 343.758392 current_received_ts = 343.757874 current_seq = 10666 count = 121 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 343.758392 last_received_ts = 343.757874 last_seq = 10666 current_ts = 343.775055 current_received_ts = 343.774628 current_seq = 10667 count = 122 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.775055 last_received_ts = 343.774628 last_seq = 10667 current_ts = 343.791718 current_received_ts = 343.791870 current_seq = 10668 count = 123 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 343.791718 last_received_ts = 343.791870 last_seq = 10668 current_ts = 343.808380 current_received_ts = 343.808228 current_seq = 10669 count = 124 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.808380 last_received_ts = 343.808228 last_seq = 10669 current_ts = 343.825043 current_received_ts = 343.824585 current_seq = 10670 count = 125 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.825043 last_received_ts = 343.824585 last_seq = 10670 current_ts = 343.841705 current_received_ts = 343.841980 current_seq = 10671 count = 126 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 343.841705 last_received_ts = 343.841980 last_seq = 10671 current_ts = 343.858368 current_received_ts = 343.858307 current_seq = 10672 count = 127 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.858368 last_received_ts = 343.858307 last_seq = 10672 current_ts = 343.875031 current_received_ts = 343.874603 current_seq = 10673 count = 128 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.875031 last_received_ts = 343.874603 last_seq = 10673 current_ts = 343.891724 current_received_ts = 343.891846 current_seq = 10674 count = 129 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 343.891724 last_received_ts = 343.891846 last_seq = 10674 current_ts = 343.908356 current_received_ts = 343.907867 current_seq = 10675 count = 130 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 343.908356 last_received_ts = 343.907867 last_seq = 10675 current_ts = 343.925049 current_received_ts = 343.925079 current_seq = 10676 count = 131 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 343.925049 last_received_ts = 343.925079 last_seq = 10676 current_ts = 343.941711 current_received_ts = 343.941498 current_seq = 10677 count = 132 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.941711 last_received_ts = 343.941498 last_seq = 10677 current_ts = 343.958374 current_received_ts = 343.958252 current_seq = 10678 count = 133 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 343.958374 last_received_ts = 343.958252 last_seq = 10678 current_ts = 343.975037 current_received_ts = 343.974579 current_seq = 10679 count = 134 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 343.975037 last_received_ts = 343.974579 last_seq = 10679 current_ts = 343.991699 current_received_ts = 343.992004 current_seq = 10680 count = 135 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 36us (kms_flip:2500) DEBUG: name = flip last_ts = 343.991699 last_received_ts = 343.992004 last_seq = 10680 current_ts = 344.008362 current_received_ts = 344.008209 current_seq = 10681 count = 136 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.008362 last_received_ts = 344.008209 last_seq = 10681 current_ts = 344.025055 current_received_ts = 344.024963 current_seq = 10682 count = 137 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 344.025055 last_received_ts = 344.024963 last_seq = 10682 current_ts = 344.041718 current_received_ts = 344.041534 current_seq = 10683 count = 138 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.041718 last_received_ts = 344.041534 last_seq = 10683 current_ts = 344.058380 current_received_ts = 344.057922 current_seq = 10684 count = 139 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.058380 last_received_ts = 344.057922 last_seq = 10684 current_ts = 344.075043 current_received_ts = 344.074615 current_seq = 10685 count = 140 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.075043 last_received_ts = 344.074615 last_seq = 10685 current_ts = 344.091705 current_received_ts = 344.091492 current_seq = 10686 count = 141 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.091705 last_received_ts = 344.091492 last_seq = 10686 current_ts = 344.108368 current_received_ts = 344.108276 current_seq = 10687 count = 142 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 344.108368 last_received_ts = 344.108276 last_seq = 10687 current_ts = 344.125061 current_received_ts = 344.124542 current_seq = 10688 count = 143 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 344.125061 last_received_ts = 344.124542 last_seq = 10688 current_ts = 344.141693 current_received_ts = 344.141968 current_seq = 10689 count = 144 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.141693 last_received_ts = 344.141968 last_seq = 10689 current_ts = 344.158386 current_received_ts = 344.158264 current_seq = 10690 count = 145 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 344.158386 last_received_ts = 344.158264 last_seq = 10690 current_ts = 344.175049 current_received_ts = 344.174591 current_seq = 10691 count = 146 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 344.175049 last_received_ts = 344.174591 last_seq = 10691 current_ts = 344.191711 current_received_ts = 344.191467 current_seq = 10692 count = 147 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 344.191711 last_received_ts = 344.191467 last_seq = 10692 current_ts = 344.208374 current_received_ts = 344.207886 current_seq = 10693 count = 148 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.208374 last_received_ts = 344.207886 last_seq = 10693 current_ts = 344.225037 current_received_ts = 344.224670 current_seq = 10694 count = 149 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 344.225037 last_received_ts = 344.224670 last_seq = 10694 current_ts = 344.241699 current_received_ts = 344.241882 current_seq = 10695 count = 150 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 344.241699 last_received_ts = 344.241882 last_seq = 10695 current_ts = 344.258392 current_received_ts = 344.258240 current_seq = 10696 count = 151 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.258392 last_received_ts = 344.258240 last_seq = 10696 current_ts = 344.275055 current_received_ts = 344.274597 current_seq = 10697 count = 152 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 344.275055 last_received_ts = 344.274597 last_seq = 10697 current_ts = 344.291718 current_received_ts = 344.291656 current_seq = 10698 count = 153 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 20us (kms_flip:2500) DEBUG: name = flip last_ts = 344.291718 last_received_ts = 344.291656 last_seq = 10698 current_ts = 344.308380 current_received_ts = 344.308228 current_seq = 10699 count = 154 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.308380 last_received_ts = 344.308228 last_seq = 10699 current_ts = 344.325043 current_received_ts = 344.324585 current_seq = 10700 count = 155 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 344.325043 last_received_ts = 344.324585 last_seq = 10700 current_ts = 344.341705 current_received_ts = 344.341522 current_seq = 10701 count = 156 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 344.341705 last_received_ts = 344.341522 last_seq = 10701 current_ts = 344.358368 current_received_ts = 344.357910 current_seq = 10702 count = 157 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.358368 last_received_ts = 344.357910 last_seq = 10702 current_ts = 344.375061 current_received_ts = 344.374603 current_seq = 10703 count = 158 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 344.375061 last_received_ts = 344.374603 last_seq = 10703 current_ts = 344.391724 current_received_ts = 344.391876 current_seq = 10704 count = 159 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 344.391724 last_received_ts = 344.391876 last_seq = 10704 current_ts = 344.408386 current_received_ts = 344.408295 current_seq = 10705 count = 160 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.408386 last_received_ts = 344.408295 last_seq = 10705 current_ts = 344.425049 current_received_ts = 344.424591 current_seq = 10706 count = 161 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.425049 last_received_ts = 344.424591 last_seq = 10706 current_ts = 344.441711 current_received_ts = 344.441284 current_seq = 10707 count = 162 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.441711 last_received_ts = 344.441284 last_seq = 10707 current_ts = 344.458374 current_received_ts = 344.458344 current_seq = 10708 count = 163 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 20us (kms_flip:2500) DEBUG: name = flip last_ts = 344.458374 last_received_ts = 344.458344 last_seq = 10708 current_ts = 344.475037 current_received_ts = 344.474579 current_seq = 10709 count = 164 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.475037 last_received_ts = 344.474579 last_seq = 10709 current_ts = 344.491699 current_received_ts = 344.491364 current_seq = 10710 count = 165 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.491699 last_received_ts = 344.491364 last_seq = 10710 current_ts = 344.508362 current_received_ts = 344.508575 current_seq = 10711 count = 166 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.508362 last_received_ts = 344.508575 last_seq = 10711 current_ts = 344.525055 current_received_ts = 344.524750 current_seq = 10712 count = 167 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.525055 last_received_ts = 344.524750 last_seq = 10712 current_ts = 344.541718 current_received_ts = 344.541443 current_seq = 10713 count = 168 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.541718 last_received_ts = 344.541443 last_seq = 10713 current_ts = 344.558380 current_received_ts = 344.558228 current_seq = 10714 count = 169 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.558380 last_received_ts = 344.558228 last_seq = 10714 current_ts = 344.575043 current_received_ts = 344.574615 current_seq = 10715 count = 170 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.575043 last_received_ts = 344.574615 last_seq = 10715 current_ts = 344.591705 current_received_ts = 344.591461 current_seq = 10716 count = 171 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 344.591705 last_received_ts = 344.591461 last_seq = 10716 current_ts = 344.608368 current_received_ts = 344.607849 current_seq = 10717 count = 172 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 20us (kms_flip:2500) DEBUG: name = flip last_ts = 344.608368 last_received_ts = 344.607849 last_seq = 10717 current_ts = 344.625061 current_received_ts = 344.624664 current_seq = 10718 count = 173 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 344.625061 last_received_ts = 344.624664 last_seq = 10718 current_ts = 344.641724 current_received_ts = 344.641632 current_seq = 10719 count = 174 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 20us (kms_flip:2500) DEBUG: name = flip last_ts = 344.641724 last_received_ts = 344.641632 last_seq = 10719 current_ts = 344.658386 current_received_ts = 344.658203 current_seq = 10720 count = 175 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.658386 last_received_ts = 344.658203 last_seq = 10720 current_ts = 344.675049 current_received_ts = 344.674591 current_seq = 10721 count = 176 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.675049 last_received_ts = 344.674591 last_seq = 10721 current_ts = 344.691711 current_received_ts = 344.691559 current_seq = 10722 count = 177 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 344.691711 last_received_ts = 344.691559 last_seq = 10722 current_ts = 344.708374 current_received_ts = 344.707916 current_seq = 10723 count = 178 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.708374 last_received_ts = 344.707916 last_seq = 10723 current_ts = 344.725037 current_received_ts = 344.724731 current_seq = 10724 count = 179 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.725037 last_received_ts = 344.724731 last_seq = 10724 current_ts = 344.741699 current_received_ts = 344.741486 current_seq = 10725 count = 180 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.741699 last_received_ts = 344.741486 last_seq = 10725 current_ts = 344.758362 current_received_ts = 344.758240 current_seq = 10726 count = 181 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.758362 last_received_ts = 344.758240 last_seq = 10726 current_ts = 344.775055 current_received_ts = 344.774536 current_seq = 10727 count = 182 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.775055 last_received_ts = 344.774536 last_seq = 10727 current_ts = 344.791718 current_received_ts = 344.791718 current_seq = 10728 count = 183 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.791718 last_received_ts = 344.791718 last_seq = 10728 current_ts = 344.808380 current_received_ts = 344.808228 current_seq = 10729 count = 184 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.808380 last_received_ts = 344.808228 last_seq = 10729 current_ts = 344.825043 current_received_ts = 344.824799 current_seq = 10730 count = 185 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 344.825043 last_received_ts = 344.824799 last_seq = 10730 current_ts = 344.841705 current_received_ts = 344.841370 current_seq = 10731 count = 186 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.841705 last_received_ts = 344.841370 last_seq = 10731 current_ts = 344.858398 current_received_ts = 344.858612 current_seq = 10732 count = 187 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.858398 last_received_ts = 344.858612 last_seq = 10732 current_ts = 344.875061 current_received_ts = 344.874573 current_seq = 10733 count = 188 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 344.875061 last_received_ts = 344.874573 last_seq = 10733 current_ts = 344.891693 current_received_ts = 344.891479 current_seq = 10734 count = 189 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 344.891693 last_received_ts = 344.891479 last_seq = 10734 current_ts = 344.908386 current_received_ts = 344.908234 current_seq = 10735 count = 190 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.908386 last_received_ts = 344.908234 last_seq = 10735 current_ts = 344.925049 current_received_ts = 344.924561 current_seq = 10736 count = 191 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 344.925049 last_received_ts = 344.924561 last_seq = 10736 current_ts = 344.941711 current_received_ts = 344.941895 current_seq = 10737 count = 192 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.941711 last_received_ts = 344.941895 last_seq = 10737 current_ts = 344.958374 current_received_ts = 344.958221 current_seq = 10738 count = 193 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 344.958374 last_received_ts = 344.958221 last_seq = 10738 current_ts = 344.975067 current_received_ts = 344.974548 current_seq = 10739 count = 194 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.975067 last_received_ts = 344.974548 last_seq = 10739 current_ts = 344.991699 current_received_ts = 344.991272 current_seq = 10740 count = 195 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 344.991699 last_received_ts = 344.991272 last_seq = 10740 current_ts = 345.008392 current_received_ts = 345.008301 current_seq = 10741 count = 196 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 24us (kms_flip:2500) DEBUG: name = flip last_ts = 345.008392 last_received_ts = 345.008301 last_seq = 10741 current_ts = 345.025055 current_received_ts = 345.024567 current_seq = 10742 count = 197 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 345.025055 last_received_ts = 345.024567 last_seq = 10742 current_ts = 345.041718 current_received_ts = 345.041901 current_seq = 10743 count = 198 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 345.041718 last_received_ts = 345.041901 last_seq = 10743 current_ts = 345.058380 current_received_ts = 345.058228 current_seq = 10744 count = 199 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 25us (kms_flip:2500) DEBUG: name = flip last_ts = 345.058380 last_received_ts = 345.058228 last_seq = 10744 current_ts = 345.075043 current_received_ts = 345.074585 current_seq = 10745 count = 200 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 345.075043 last_received_ts = 345.074585 last_seq = 10745 current_ts = 345.091705 current_received_ts = 345.091309 current_seq = 10746 count = 201 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 345.091705 last_received_ts = 345.091309 last_seq = 10746 current_ts = 345.108368 current_received_ts = 345.108398 current_seq = 10747 count = 202 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 345.108368 last_received_ts = 345.108398 last_seq = 10747 current_ts = 345.125061 current_received_ts = 345.124603 current_seq = 10748 count = 203 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 345.125061 last_received_ts = 345.124603 last_seq = 10748 current_ts = 345.141724 current_received_ts = 345.141266 current_seq = 10749 count = 204 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 345.141724 last_received_ts = 345.141266 last_seq = 10749 current_ts = 345.158386 current_received_ts = 345.158508 current_seq = 10750 count = 205 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 345.158386 last_received_ts = 345.158508 last_seq = 10750 current_ts = 345.175049 current_received_ts = 345.174561 current_seq = 10751 count = 206 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 345.175049 last_received_ts = 345.174561 last_seq = 10751 current_ts = 345.191711 current_received_ts = 345.191864 current_seq = 10752 count = 207 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 345.191711 last_received_ts = 345.191864 last_seq = 10752 current_ts = 345.208374 current_received_ts = 345.208221 current_seq = 10753 count = 208 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 345.208374 last_received_ts = 345.208221 last_seq = 10753 current_ts = 345.225037 current_received_ts = 345.224670 current_seq = 10754 count = 209 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 345.225037 last_received_ts = 345.224670 last_seq = 10754 current_ts = 345.241699 current_received_ts = 345.241974 current_seq = 10755 count = 210 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 345.241699 last_received_ts = 345.241974 last_seq = 10755 current_ts = 345.258392 current_received_ts = 345.258270 current_seq = 10756 count = 211 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 345.258392 last_received_ts = 345.258270 last_seq = 10756 current_ts = 345.275055 current_received_ts = 345.274597 current_seq = 10757 count = 212 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 345.275055 last_received_ts = 345.274597 last_seq = 10757 current_ts = 345.291718 current_received_ts = 345.291534 current_seq = 10758 count = 213 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 345.291718 last_received_ts = 345.291534 last_seq = 10758 current_ts = 345.308380 current_received_ts = 345.307892 current_seq = 10759 count = 214 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 345.308380 last_received_ts = 345.307892 last_seq = 10759 current_ts = 345.325043 current_received_ts = 345.325104 current_seq = 10760 count = 215 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 22us (kms_flip:2500) DEBUG: name = flip last_ts = 345.325043 last_received_ts = 345.325104 last_seq = 10760 current_ts = 345.341705 current_received_ts = 345.341492 current_seq = 10761 count = 216 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 21us (kms_flip:2500) DEBUG: name = flip last_ts = 345.341705 last_received_ts = 345.341492 last_seq = 10761 current_ts = 345.358368 current_received_ts = 345.358276 current_seq = 10762 count = 217 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 23us (kms_flip:2500) DEBUG: name = flip last_ts = 345.358368 last_received_ts = 345.358276 last_seq = 10762 current_ts = 345.375031 current_received_ts = 345.374481 current_seq = 10763 count = 218 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 13us (kms_flip:2500) DEBUG: name = flip last_ts = 345.375031 last_received_ts = 345.374481 last_seq = 10763 current_ts = 345.391724 current_received_ts = 345.391144 current_seq = 10764 count = 219 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 13us (kms_flip:2500) DEBUG: name = flip last_ts = 345.391724 last_received_ts = 345.391144 last_seq = 10764 current_ts = 345.408386 current_received_ts = 345.407959 current_seq = 10765 count = 220 seq_step = 1 (kms_flip:2500) DEBUG: Vblank took 931us (kms_flip:2500) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:2500) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2500) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:2500) igt_core-INFO: Stack trace: (kms_flip:2500) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2500) igt_core-INFO: #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0() (kms_flip:2500) igt_core-INFO: #2 ../tests/kms_flip.c:1887 run_test() (kms_flip:2500) igt_core-INFO: #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2043() (kms_flip:2500) igt_core-INFO: #4 ../tests/kms_flip.c:2043 main() (kms_flip:2500) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2500) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2500) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-HDMI-A2: FAIL (4.136s)
Dmesg	<6> [341.696911] [IGT] kms_flip: starting dynamic subtest A-HDMI-A2 <7> [341.698648] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:179] <7> [341.699268] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:181] <7> [341.736750] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:77:pipe A] <7> [341.739607] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:120:pipe B] <7> [341.740855] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:163:pipe C] <7> [341.741030] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.enable (expected yes, found no) <7> [341.741566] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.active (expected yes, found no) <7> [341.741972] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in cpu_transcoder (expected 2, found -1) <7> [341.742352] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in lane_count (expected 4, found 0) <7> [341.743045] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000) <7> [341.743428] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [341.743853] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [341.744233] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [341.744792] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [341.745209] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [341.745813] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [341.746196] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [341.746622] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [341.746999] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [341.747375] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [341.747951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [341.748412] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [341.749158] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [341.749658] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [341.750038] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [341.750413] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [341.750985] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [341.751387] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [341.751805] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [341.752181] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [341.752595] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [341.752982] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [341.753357] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [341.753960] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [341.754370] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [341.754981] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [341.755363] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [341.755782] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [341.756162] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [341.756758] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [341.757151] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in has_infoframe (expected yes, found no) <7> [341.757568] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [341.757947] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [341.758323] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [341.758850] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in port_clock (expected 222750, found 0) <7> [341.759231] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [341.759639] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000) <7> [341.760016] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in avi infoframe <7> [341.760471] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [341.761238] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [341.761244] i915 0000:00:02.0: colorspace: RGB <7> [341.761248] i915 0000:00:02.0: scan mode: Underscan <7> [341.761251] i915 0000:00:02.0: colorimetry: No Data <7> [341.761255] i915 0000:00:02.0: picture aspect: No Data <7> [341.761258] i915 0000:00:02.0: active aspect: Same as Picture <7> [341.761261] i915 0000:00:02.0: itc: No Data <7> [341.761264] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [341.761268] i915 0000:00:02.0: quantization range: Full <7> [341.761271] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [341.761274] i915 0000:00:02.0: video code: 0 <7> [341.761278] i915 0000:00:02.0: ycc quantization range: Full <7> [341.761281] i915 0000:00:02.0: hdmi content type: Graphics <7> [341.761284] i915 0000:00:02.0: pixel repeat: 0 <7> [341.761287] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [341.761291] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [341.761813] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in spd infoframe <7> [341.762192] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [341.762931] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [341.762936] i915 0000:00:02.0: vendor: Intel <7> [341.762958] i915 0000:00:02.0: product: Integrated gfx <7> [341.762962] i915 0000:00:02.0: source device information: PC General (0x9) <7> [341.762967] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [341.763358] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:163:pipe C] fastset requirement not met in hdmi infoframe <7> [341.763921] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [341.764334] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [341.764338] i915 0000:00:02.0: empty frame <7> [341.764341] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [341.764926] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:163:pipe C] fastset requirement not met, forcing full modeset <7> [341.765309] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:163:pipe C] releasing PORT PLL B <7> [341.765788] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:163:pipe C] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x4 -> 0x0 <7> [341.766242] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:157:cursor C] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0 <7> [341.766767] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:163:pipe C] min cdclk: 192000 kHz -> 0 kHz <7> [341.767220] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [341.767678] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz <7> [341.768054] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4 <7> [341.768443] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:163:pipe C] enable: no [modeset] <7> [341.768856] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:121:plane 1C] fb: [NOFB], visible: no <7> [341.769231] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:130:plane 2C] fb: [NOFB], visible: no <7> [341.769640] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:139:plane 3C] fb: [NOFB], visible: no <7> [341.770014] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:148:plane 4C] fb: [NOFB], visible: no <7> [341.770386] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:157:cursor C] fb: [NOFB], visible: no <7> [341.770966] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:165:HDMI-A-1][ENCODER:164:DDI B/PHY B] Disable audio codec on [CRTC:163:pipe C] <7> [341.789638] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [341.791360] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe C <7> [341.803088] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10 <7> [341.806610] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time <7> [341.910051] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [341.911092] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x4, on? 1) for [CRTC:163:pipe C] <7> [341.912246] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL B <7> [341.913542] 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> [341.914070] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:164:DDI B/PHY B] <7> [341.914565] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:174:DDI C/PHY C] <7> [341.914954] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:165:HDMI-A-1] <7> [341.915753] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-b <7> [341.916203] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:163:pipe C] <7> [341.917601] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [341.918054] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz <7> [341.918430] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13 <7> [341.918962] 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> [341.919866] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:77:pipe A] <7> [341.919942] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:175:HDMI-A-2] <7> [341.920148] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 12 bpc for HDMI output (pipe bpp: 36) <7> [341.920853] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:77:pipe A] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [341.921250] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:174:DDI C/PHY C] [CRTC:77:pipe A] <7> [341.921693] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [341.922077] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [341.922454] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [341.923197] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [341.923627] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d) <7> [341.924018] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [341.924394] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [341.924907] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL <7> [341.924924] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled <7> [341.924999] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [341.925386] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [341.925801] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [341.926177] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [341.926612] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [341.926998] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [341.927375] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [341.927867] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [341.928247] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [341.928656] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [341.929032] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [341.929407] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [341.929838] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [341.930215] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [341.930616] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [341.930993] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [341.931368] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [341.931790] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [341.932167] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [341.932567] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [341.932946] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [341.933330] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [341.933803] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [341.934183] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [341.934585] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [341.934963] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [341.935350] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [341.935914] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [341.936330] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in has_infoframe (expected no, found yes) <7> [341.936741] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [341.937120] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [341.937545] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [341.937923] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in port_clock (expected 0, found 222750) <7> [341.938298] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [341.938694] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006) <7> [341.939074] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in avi infoframe <7> [341.939451] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [341.939862] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [341.940237] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [341.940242] i915 0000:00:02.0: colorspace: RGB <7> [341.940246] i915 0000:00:02.0: scan mode: Underscan <7> [341.940249] i915 0000:00:02.0: colorimetry: No Data <7> [341.940253] i915 0000:00:02.0: picture aspect: No Data <7> [341.940256] i915 0000:00:02.0: active aspect: Same as Picture <7> [341.940259] i915 0000:00:02.0: itc: No Data <7> [341.940263] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [341.940266] i915 0000:00:02.0: quantization range: Full <7> [341.940269] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [341.940272] i915 0000:00:02.0: video code: 0 <7> [341.940275] i915 0000:00:02.0: ycc quantization range: Full <7> [341.940278] i915 0000:00:02.0: hdmi content type: Graphics <7> [341.940282] i915 0000:00:02.0: pixel repeat: 0 <7> [341.940285] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [341.940289] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in spd infoframe <7> [341.940695] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [341.941069] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [341.941440] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [341.941444] i915 0000:00:02.0: vendor: Intel <7> [341.941448] i915 0000:00:02.0: product: Integrated gfx <7> [341.941451] i915 0000:00:02.0: source device information: PC General (0x9) <7> [341.941455] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:77:pipe A] fastset requirement not met in hdmi infoframe <7> [341.941875] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [341.942251] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [341.942644] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [341.942649] i915 0000:00:02.0: empty frame <7> [341.942654] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:77:pipe A] fastset requirement not met, forcing full modeset <7> [341.943121] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:77:pipe A] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x1 <7> [341.943607] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988 <7> [341.943978] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:71:cursor A] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32 <7> [341.944350] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:35: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> [341.944769] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:35: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> [341.945143] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:35: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> [341.945540] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:35: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> [341.946001] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:77:pipe A] min cdclk: 0 kHz -> 192000 kHz <7> [341.946436] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:77:pipe A] using pre-allocated PORT PLL C <7> [341.946883] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:77:pipe A] reserving PORT PLL C <7> [341.947276] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:77:pipe A] enable: yes [modeset] <7> [341.947681] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [341.948058] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 36, dithering: 0 <7> [341.948431] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [341.948849] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [341.949226] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [341.949623] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [341.949997] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [341.950370] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6 <7> [341.950783] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [341.950788] i915 0000:00:02.0: colorspace: RGB <7> [341.950792] i915 0000:00:02.0: scan mode: Underscan <7> [341.950795] i915 0000:00:02.0: colorimetry: No Data <7> [341.950799] i915 0000:00:02.0: picture aspect: No Data <7> [341.950802] i915 0000:00:02.0: active aspect: Same as Picture <7> [341.950805] i915 0000:00:02.0: itc: No Data <7> [341.950809] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [341.950812] i915 0000:00:02.0: quantization range: Full <7> [341.950815] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [341.950819] i915 0000:00:02.0: video code: 0 <7> [341.950822] i915 0000:00:02.0: ycc quantization range: Full <7> [341.950825] i915 0000:00:02.0: hdmi content type: Graphics <7> [341.950828] i915 0000:00:02.0: pixel repeat: 0 <7> [341.950831] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [341.950835] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [341.950839] i915 0000:00:02.0: vendor: Intel <7> [341.950842] i915 0000:00:02.0: product: Integrated gfx <7> [341.950845] i915 0000:00:02.0: source device information: PC General (0x9) <7> [341.950849] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [341.950853] i915 0000:00:02.0: empty frame <7> [341.950857] 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> [341.951232] 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> [341.951626] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [341.952001] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [341.952374] 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> [341.952793] 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> [341.953169] 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> [341.953561] 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> [341.953939] 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> [341.954315] 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> [341.954724] 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> [341.955099] 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> [341.955476] 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> [341.955904] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [341.956286] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [341.956727] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [341.957104] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [341.957476] 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> [341.957869] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [341.958241] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [341.958646] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [341.959019] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [341.959390] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [341.959784] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [341.960156] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [341.960570] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [341.960947] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:plane 1A] fb: [FB:179] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [341.961325] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [341.961715] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [341.962094] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:44:plane 2A] fb: [NOFB], visible: no <7> [341.962470] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:53:plane 3A] fb: [NOFB], visible: no <7> [341.962891] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:62:plane 4A] fb: [NOFB], visible: no <7> [341.963270] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:71:cursor A] fb: [NOFB], visible: no <7> [341.964336] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-c <7> [341.966021] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:164:DDI B/PHY B] <7> [341.966479] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:174:DDI C/PHY C] <7> [341.967067] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL C (active 0x1, on? 0) for [CRTC:77:pipe A] <7> [341.967453] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL C <7> [341.968026] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_C <7> [341.968565] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A <7> [341.969950] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] reserved 16588800 bytes of contiguous stolen space for FBC, limit: 1 <7> [341.970347] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] Enabling FBC on [PLANE:35:plane 1A] <7> [341.986625] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:175:HDMI-A-2][ENCODER:174:DDI C/PHY C] Enable audio codec on [CRTC:77:pipe A], 32 bytes ELD <7> [342.003284] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000) <7> [342.003792] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <7> [342.004375] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:175:HDMI-A-2] <7> [342.006668] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:77:pipe A] <6> [345.836235] [IGT] kms_flip: finished subtest A-HDMI-A2, FAIL

Detail

Value

Duration

4.14 seconds

Hostname

shard-glk2

Igt-Version

IGT-Version: 2.3-g246d93c1d (x86_64) (Linux: 7.0.0-rc3-CI_DRM_18142-g4082c266f293+ 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:921 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1887 run_test()
  #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2043()
  #4 ../tests/kms_flip.c:2043 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A2: FAIL (4.136s)

Err

Starting dynamic subtest: A-HDMI-A2
(kms_flip:2500) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2500) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2500) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest A-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.391693
last_received_ts = 343.391541
last_seq = 10644
current_ts = 343.408386
current_received_ts = 343.407837
current_seq = 10645
count = 100
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.408386
last_received_ts = 343.407837
last_seq = 10645
current_ts = 343.425049
current_received_ts = 343.424683
current_seq = 10646
count = 101
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.425049
last_received_ts = 343.424683
last_seq = 10646
current_ts = 343.441711
current_received_ts = 343.441528
current_seq = 10647
count = 102
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.441711
last_received_ts = 343.441528
last_seq = 10647
current_ts = 343.458374
current_received_ts = 343.458252
current_seq = 10648
count = 103
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.458374
last_received_ts = 343.458252
last_seq = 10648
current_ts = 343.475037
current_received_ts = 343.475067
current_seq = 10649
count = 104
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 50us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.475037
last_received_ts = 343.475067
last_seq = 10649
current_ts = 343.491699
current_received_ts = 343.491974
current_seq = 10650
count = 105
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 19us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.491699
last_received_ts = 343.491974
last_seq = 10650
current_ts = 343.508362
current_received_ts = 343.508209
current_seq = 10651
count = 106
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.508362
last_received_ts = 343.508209
last_seq = 10651
current_ts = 343.525055
current_received_ts = 343.524567
current_seq = 10652
count = 107
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.525055
last_received_ts = 343.524567
last_seq = 10652
current_ts = 343.541687
current_received_ts = 343.541534
current_seq = 10653
count = 108
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.541687
last_received_ts = 343.541534
last_seq = 10653
current_ts = 343.558380
current_received_ts = 343.557861
current_seq = 10654
count = 109
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.558380
last_received_ts = 343.557861
last_seq = 10654
current_ts = 343.575043
current_received_ts = 343.574677
current_seq = 10655
count = 110
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.575043
last_received_ts = 343.574677
last_seq = 10655
current_ts = 343.591705
current_received_ts = 343.591705
current_seq = 10656
count = 111
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 19us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.591705
last_received_ts = 343.591705
last_seq = 10656
current_ts = 343.608368
current_received_ts = 343.608154
current_seq = 10657
count = 112
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.608368
last_received_ts = 343.608154
last_seq = 10657
current_ts = 343.625031
current_received_ts = 343.624603
current_seq = 10658
count = 113
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.625031
last_received_ts = 343.624603
last_seq = 10658
current_ts = 343.641724
current_received_ts = 343.641296
current_seq = 10659
count = 114
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.641724
last_received_ts = 343.641296
last_seq = 10659
current_ts = 343.658356
current_received_ts = 343.658691
current_seq = 10660
count = 115
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.658356
last_received_ts = 343.658691
last_seq = 10660
current_ts = 343.675049
current_received_ts = 343.674988
current_seq = 10661
count = 116
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.675049
last_received_ts = 343.674988
last_seq = 10661
current_ts = 343.691711
current_received_ts = 343.691467
current_seq = 10662
count = 117
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.691711
last_received_ts = 343.691467
last_seq = 10662
current_ts = 343.708374
current_received_ts = 343.708252
current_seq = 10663
count = 118
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.708374
last_received_ts = 343.708252
last_seq = 10663
current_ts = 343.725037
current_received_ts = 343.724579
current_seq = 10664
count = 119
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.725037
last_received_ts = 343.724579
last_seq = 10664
current_ts = 343.741699
current_received_ts = 343.741608
current_seq = 10665
count = 120
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.741699
last_received_ts = 343.741608
last_seq = 10665
current_ts = 343.758392
current_received_ts = 343.757874
current_seq = 10666
count = 121
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.758392
last_received_ts = 343.757874
last_seq = 10666
current_ts = 343.775055
current_received_ts = 343.774628
current_seq = 10667
count = 122
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.775055
last_received_ts = 343.774628
last_seq = 10667
current_ts = 343.791718
current_received_ts = 343.791870
current_seq = 10668
count = 123
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.791718
last_received_ts = 343.791870
last_seq = 10668
current_ts = 343.808380
current_received_ts = 343.808228
current_seq = 10669
count = 124
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.808380
last_received_ts = 343.808228
last_seq = 10669
current_ts = 343.825043
current_received_ts = 343.824585
current_seq = 10670
count = 125
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.825043
last_received_ts = 343.824585
last_seq = 10670
current_ts = 343.841705
current_received_ts = 343.841980
current_seq = 10671
count = 126
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.841705
last_received_ts = 343.841980
last_seq = 10671
current_ts = 343.858368
current_received_ts = 343.858307
current_seq = 10672
count = 127
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.858368
last_received_ts = 343.858307
last_seq = 10672
current_ts = 343.875031
current_received_ts = 343.874603
current_seq = 10673
count = 128
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.875031
last_received_ts = 343.874603
last_seq = 10673
current_ts = 343.891724
current_received_ts = 343.891846
current_seq = 10674
count = 129
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.891724
last_received_ts = 343.891846
last_seq = 10674
current_ts = 343.908356
current_received_ts = 343.907867
current_seq = 10675
count = 130
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.908356
last_received_ts = 343.907867
last_seq = 10675
current_ts = 343.925049
current_received_ts = 343.925079
current_seq = 10676
count = 131
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.925049
last_received_ts = 343.925079
last_seq = 10676
current_ts = 343.941711
current_received_ts = 343.941498
current_seq = 10677
count = 132
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.941711
last_received_ts = 343.941498
last_seq = 10677
current_ts = 343.958374
current_received_ts = 343.958252
current_seq = 10678
count = 133
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.958374
last_received_ts = 343.958252
last_seq = 10678
current_ts = 343.975037
current_received_ts = 343.974579
current_seq = 10679
count = 134
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.975037
last_received_ts = 343.974579
last_seq = 10679
current_ts = 343.991699
current_received_ts = 343.992004
current_seq = 10680
count = 135
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 36us
(kms_flip:2500) DEBUG: name = flip
last_ts = 343.991699
last_received_ts = 343.992004
last_seq = 10680
current_ts = 344.008362
current_received_ts = 344.008209
current_seq = 10681
count = 136
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.008362
last_received_ts = 344.008209
last_seq = 10681
current_ts = 344.025055
current_received_ts = 344.024963
current_seq = 10682
count = 137
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.025055
last_received_ts = 344.024963
last_seq = 10682
current_ts = 344.041718
current_received_ts = 344.041534
current_seq = 10683
count = 138
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.041718
last_received_ts = 344.041534
last_seq = 10683
current_ts = 344.058380
current_received_ts = 344.057922
current_seq = 10684
count = 139
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.058380
last_received_ts = 344.057922
last_seq = 10684
current_ts = 344.075043
current_received_ts = 344.074615
current_seq = 10685
count = 140
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.075043
last_received_ts = 344.074615
last_seq = 10685
current_ts = 344.091705
current_received_ts = 344.091492
current_seq = 10686
count = 141
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.091705
last_received_ts = 344.091492
last_seq = 10686
current_ts = 344.108368
current_received_ts = 344.108276
current_seq = 10687
count = 142
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.108368
last_received_ts = 344.108276
last_seq = 10687
current_ts = 344.125061
current_received_ts = 344.124542
current_seq = 10688
count = 143
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.125061
last_received_ts = 344.124542
last_seq = 10688
current_ts = 344.141693
current_received_ts = 344.141968
current_seq = 10689
count = 144
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.141693
last_received_ts = 344.141968
last_seq = 10689
current_ts = 344.158386
current_received_ts = 344.158264
current_seq = 10690
count = 145
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.158386
last_received_ts = 344.158264
last_seq = 10690
current_ts = 344.175049
current_received_ts = 344.174591
current_seq = 10691
count = 146
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.175049
last_received_ts = 344.174591
last_seq = 10691
current_ts = 344.191711
current_received_ts = 344.191467
current_seq = 10692
count = 147
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.191711
last_received_ts = 344.191467
last_seq = 10692
current_ts = 344.208374
current_received_ts = 344.207886
current_seq = 10693
count = 148
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.208374
last_received_ts = 344.207886
last_seq = 10693
current_ts = 344.225037
current_received_ts = 344.224670
current_seq = 10694
count = 149
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.225037
last_received_ts = 344.224670
last_seq = 10694
current_ts = 344.241699
current_received_ts = 344.241882
current_seq = 10695
count = 150
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.241699
last_received_ts = 344.241882
last_seq = 10695
current_ts = 344.258392
current_received_ts = 344.258240
current_seq = 10696
count = 151
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.258392
last_received_ts = 344.258240
last_seq = 10696
current_ts = 344.275055
current_received_ts = 344.274597
current_seq = 10697
count = 152
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.275055
last_received_ts = 344.274597
last_seq = 10697
current_ts = 344.291718
current_received_ts = 344.291656
current_seq = 10698
count = 153
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 20us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.291718
last_received_ts = 344.291656
last_seq = 10698
current_ts = 344.308380
current_received_ts = 344.308228
current_seq = 10699
count = 154
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.308380
last_received_ts = 344.308228
last_seq = 10699
current_ts = 344.325043
current_received_ts = 344.324585
current_seq = 10700
count = 155
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.325043
last_received_ts = 344.324585
last_seq = 10700
current_ts = 344.341705
current_received_ts = 344.341522
current_seq = 10701
count = 156
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.341705
last_received_ts = 344.341522
last_seq = 10701
current_ts = 344.358368
current_received_ts = 344.357910
current_seq = 10702
count = 157
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.358368
last_received_ts = 344.357910
last_seq = 10702
current_ts = 344.375061
current_received_ts = 344.374603
current_seq = 10703
count = 158
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.375061
last_received_ts = 344.374603
last_seq = 10703
current_ts = 344.391724
current_received_ts = 344.391876
current_seq = 10704
count = 159
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.391724
last_received_ts = 344.391876
last_seq = 10704
current_ts = 344.408386
current_received_ts = 344.408295
current_seq = 10705
count = 160
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.408386
last_received_ts = 344.408295
last_seq = 10705
current_ts = 344.425049
current_received_ts = 344.424591
current_seq = 10706
count = 161
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.425049
last_received_ts = 344.424591
last_seq = 10706
current_ts = 344.441711
current_received_ts = 344.441284
current_seq = 10707
count = 162
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.441711
last_received_ts = 344.441284
last_seq = 10707
current_ts = 344.458374
current_received_ts = 344.458344
current_seq = 10708
count = 163
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 20us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.458374
last_received_ts = 344.458344
last_seq = 10708
current_ts = 344.475037
current_received_ts = 344.474579
current_seq = 10709
count = 164
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.475037
last_received_ts = 344.474579
last_seq = 10709
current_ts = 344.491699
current_received_ts = 344.491364
current_seq = 10710
count = 165
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.491699
last_received_ts = 344.491364
last_seq = 10710
current_ts = 344.508362
current_received_ts = 344.508575
current_seq = 10711
count = 166
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.508362
last_received_ts = 344.508575
last_seq = 10711
current_ts = 344.525055
current_received_ts = 344.524750
current_seq = 10712
count = 167
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.525055
last_received_ts = 344.524750
last_seq = 10712
current_ts = 344.541718
current_received_ts = 344.541443
current_seq = 10713
count = 168
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.541718
last_received_ts = 344.541443
last_seq = 10713
current_ts = 344.558380
current_received_ts = 344.558228
current_seq = 10714
count = 169
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.558380
last_received_ts = 344.558228
last_seq = 10714
current_ts = 344.575043
current_received_ts = 344.574615
current_seq = 10715
count = 170
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.575043
last_received_ts = 344.574615
last_seq = 10715
current_ts = 344.591705
current_received_ts = 344.591461
current_seq = 10716
count = 171
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.591705
last_received_ts = 344.591461
last_seq = 10716
current_ts = 344.608368
current_received_ts = 344.607849
current_seq = 10717
count = 172
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 20us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.608368
last_received_ts = 344.607849
last_seq = 10717
current_ts = 344.625061
current_received_ts = 344.624664
current_seq = 10718
count = 173
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.625061
last_received_ts = 344.624664
last_seq = 10718
current_ts = 344.641724
current_received_ts = 344.641632
current_seq = 10719
count = 174
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 20us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.641724
last_received_ts = 344.641632
last_seq = 10719
current_ts = 344.658386
current_received_ts = 344.658203
current_seq = 10720
count = 175
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.658386
last_received_ts = 344.658203
last_seq = 10720
current_ts = 344.675049
current_received_ts = 344.674591
current_seq = 10721
count = 176
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.675049
last_received_ts = 344.674591
last_seq = 10721
current_ts = 344.691711
current_received_ts = 344.691559
current_seq = 10722
count = 177
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.691711
last_received_ts = 344.691559
last_seq = 10722
current_ts = 344.708374
current_received_ts = 344.707916
current_seq = 10723
count = 178
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.708374
last_received_ts = 344.707916
last_seq = 10723
current_ts = 344.725037
current_received_ts = 344.724731
current_seq = 10724
count = 179
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.725037
last_received_ts = 344.724731
last_seq = 10724
current_ts = 344.741699
current_received_ts = 344.741486
current_seq = 10725
count = 180
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.741699
last_received_ts = 344.741486
last_seq = 10725
current_ts = 344.758362
current_received_ts = 344.758240
current_seq = 10726
count = 181
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.758362
last_received_ts = 344.758240
last_seq = 10726
current_ts = 344.775055
current_received_ts = 344.774536
current_seq = 10727
count = 182
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.775055
last_received_ts = 344.774536
last_seq = 10727
current_ts = 344.791718
current_received_ts = 344.791718
current_seq = 10728
count = 183
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.791718
last_received_ts = 344.791718
last_seq = 10728
current_ts = 344.808380
current_received_ts = 344.808228
current_seq = 10729
count = 184
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.808380
last_received_ts = 344.808228
last_seq = 10729
current_ts = 344.825043
current_received_ts = 344.824799
current_seq = 10730
count = 185
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.825043
last_received_ts = 344.824799
last_seq = 10730
current_ts = 344.841705
current_received_ts = 344.841370
current_seq = 10731
count = 186
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.841705
last_received_ts = 344.841370
last_seq = 10731
current_ts = 344.858398
current_received_ts = 344.858612
current_seq = 10732
count = 187
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.858398
last_received_ts = 344.858612
last_seq = 10732
current_ts = 344.875061
current_received_ts = 344.874573
current_seq = 10733
count = 188
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.875061
last_received_ts = 344.874573
last_seq = 10733
current_ts = 344.891693
current_received_ts = 344.891479
current_seq = 10734
count = 189
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.891693
last_received_ts = 344.891479
last_seq = 10734
current_ts = 344.908386
current_received_ts = 344.908234
current_seq = 10735
count = 190
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.908386
last_received_ts = 344.908234
last_seq = 10735
current_ts = 344.925049
current_received_ts = 344.924561
current_seq = 10736
count = 191
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.925049
last_received_ts = 344.924561
last_seq = 10736
current_ts = 344.941711
current_received_ts = 344.941895
current_seq = 10737
count = 192
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.941711
last_received_ts = 344.941895
last_seq = 10737
current_ts = 344.958374
current_received_ts = 344.958221
current_seq = 10738
count = 193
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.958374
last_received_ts = 344.958221
last_seq = 10738
current_ts = 344.975067
current_received_ts = 344.974548
current_seq = 10739
count = 194
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.975067
last_received_ts = 344.974548
last_seq = 10739
current_ts = 344.991699
current_received_ts = 344.991272
current_seq = 10740
count = 195
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 344.991699
last_received_ts = 344.991272
last_seq = 10740
current_ts = 345.008392
current_received_ts = 345.008301
current_seq = 10741
count = 196
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 24us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.008392
last_received_ts = 345.008301
last_seq = 10741
current_ts = 345.025055
current_received_ts = 345.024567
current_seq = 10742
count = 197
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.025055
last_received_ts = 345.024567
last_seq = 10742
current_ts = 345.041718
current_received_ts = 345.041901
current_seq = 10743
count = 198
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.041718
last_received_ts = 345.041901
last_seq = 10743
current_ts = 345.058380
current_received_ts = 345.058228
current_seq = 10744
count = 199
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 25us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.058380
last_received_ts = 345.058228
last_seq = 10744
current_ts = 345.075043
current_received_ts = 345.074585
current_seq = 10745
count = 200
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.075043
last_received_ts = 345.074585
last_seq = 10745
current_ts = 345.091705
current_received_ts = 345.091309
current_seq = 10746
count = 201
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.091705
last_received_ts = 345.091309
last_seq = 10746
current_ts = 345.108368
current_received_ts = 345.108398
current_seq = 10747
count = 202
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.108368
last_received_ts = 345.108398
last_seq = 10747
current_ts = 345.125061
current_received_ts = 345.124603
current_seq = 10748
count = 203
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.125061
last_received_ts = 345.124603
last_seq = 10748
current_ts = 345.141724
current_received_ts = 345.141266
current_seq = 10749
count = 204
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.141724
last_received_ts = 345.141266
last_seq = 10749
current_ts = 345.158386
current_received_ts = 345.158508
current_seq = 10750
count = 205
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.158386
last_received_ts = 345.158508
last_seq = 10750
current_ts = 345.175049
current_received_ts = 345.174561
current_seq = 10751
count = 206
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.175049
last_received_ts = 345.174561
last_seq = 10751
current_ts = 345.191711
current_received_ts = 345.191864
current_seq = 10752
count = 207
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.191711
last_received_ts = 345.191864
last_seq = 10752
current_ts = 345.208374
current_received_ts = 345.208221
current_seq = 10753
count = 208
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.208374
last_received_ts = 345.208221
last_seq = 10753
current_ts = 345.225037
current_received_ts = 345.224670
current_seq = 10754
count = 209
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.225037
last_received_ts = 345.224670
last_seq = 10754
current_ts = 345.241699
current_received_ts = 345.241974
current_seq = 10755
count = 210
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.241699
last_received_ts = 345.241974
last_seq = 10755
current_ts = 345.258392
current_received_ts = 345.258270
current_seq = 10756
count = 211
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.258392
last_received_ts = 345.258270
last_seq = 10756
current_ts = 345.275055
current_received_ts = 345.274597
current_seq = 10757
count = 212
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.275055
last_received_ts = 345.274597
last_seq = 10757
current_ts = 345.291718
current_received_ts = 345.291534
current_seq = 10758
count = 213
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.291718
last_received_ts = 345.291534
last_seq = 10758
current_ts = 345.308380
current_received_ts = 345.307892
current_seq = 10759
count = 214
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.308380
last_received_ts = 345.307892
last_seq = 10759
current_ts = 345.325043
current_received_ts = 345.325104
current_seq = 10760
count = 215
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 22us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.325043
last_received_ts = 345.325104
last_seq = 10760
current_ts = 345.341705
current_received_ts = 345.341492
current_seq = 10761
count = 216
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 21us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.341705
last_received_ts = 345.341492
last_seq = 10761
current_ts = 345.358368
current_received_ts = 345.358276
current_seq = 10762
count = 217
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 23us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.358368
last_received_ts = 345.358276
last_seq = 10762
current_ts = 345.375031
current_received_ts = 345.374481
current_seq = 10763
count = 218
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 13us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.375031
last_received_ts = 345.374481
last_seq = 10763
current_ts = 345.391724
current_received_ts = 345.391144
current_seq = 10764
count = 219
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 13us
(kms_flip:2500) DEBUG: name = flip
last_ts = 345.391724
last_received_ts = 345.391144
last_seq = 10764
current_ts = 345.408386
current_received_ts = 345.407959
current_seq = 10765
count = 220
seq_step = 1
(kms_flip:2500) DEBUG: Vblank took 931us
(kms_flip:2500) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:2500) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2500) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2500) igt_core-INFO: Stack trace:
(kms_flip:2500) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2500) igt_core-INFO:   #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0()
(kms_flip:2500) igt_core-INFO:   #2 ../tests/kms_flip.c:1887 run_test()
(kms_flip:2500) igt_core-INFO:   #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2043()
(kms_flip:2500) igt_core-INFO:   #4 ../tests/kms_flip.c:2043 main()
(kms_flip:2500) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2500) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2500) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A2: FAIL (4.136s)

Dmesg

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

<7> [341.698648] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:179]

<7> [341.699268] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:181]

<7> [341.736750] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:77:pipe A]

<7> [341.739607] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:120:pipe B]

<7> [341.740855] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:163:pipe C]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [341.913542] 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> [341.914070] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:164:DDI B/PHY B]

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

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

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

<7> [341.916203] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:163:pipe C]

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

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

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

<7> [341.918962] 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> [341.919866] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:77:pipe A]

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

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

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

<7> [341.921250] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:174:DDI C/PHY C] [CRTC:77:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [341.944350] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:35: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> [341.944769] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:35: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> [341.945143] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:35: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> [341.945540] i915 0000:00:02.0: [drm:skl_print_plane_changes [i915]] [PLANE:35: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> [341.946001] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:77:pipe A] min cdclk: 0 kHz -> 192000 kHz

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [341.950857] 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> [341.951232] 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> [341.951626] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

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

<7> [341.952374] 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> [341.952793] 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> [341.953169] 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> [341.953561] 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> [341.953939] 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> [341.954315] 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> [341.954724] 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> [341.955099] 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> [341.955476] 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> [341.955904] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [342.006668] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:77:pipe A]

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

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