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

Detail	Value
Duration	3.81 seconds
Hostname	shard-glk1
Igt-Version	IGT-Version: 2.4-g8966d7c15 (x86_64) (Linux: 7.1.0-rc3-CI_DRM_18470-g767b83aa80c6+ x86_64)
Out	Starting dynamic subtest: C-HDMI-A1 1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest C-HDMI-A1: FAIL (3.810s)
Err	Starting dynamic subtest: C-HDMI-A1 (kms_flip:2294) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2294) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2294) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest C-HDMI-A1 failed. ** DEBUG (kms_flip:2294) DEBUG: Vblank took 26us (kms_flip:2294) DEBUG: name = flip last_ts = 123.097038 last_received_ts = 123.096611 last_seq = 87 current_ts = 123.113693 current_received_ts = 123.113869 current_seq = 88 count = 82 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 123.113693 last_received_ts = 123.113869 last_seq = 88 current_ts = 123.130371 current_received_ts = 123.130211 current_seq = 89 count = 83 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.130371 last_received_ts = 123.130211 last_seq = 89 current_ts = 123.147041 current_received_ts = 123.146576 current_seq = 90 count = 84 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 123.147041 last_received_ts = 123.146576 last_seq = 90 current_ts = 123.163696 current_received_ts = 123.163666 current_seq = 91 count = 85 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 123.163696 last_received_ts = 123.163666 last_seq = 91 current_ts = 123.180367 current_received_ts = 123.180382 current_seq = 92 count = 86 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 38us (kms_flip:2294) DEBUG: name = flip last_ts = 123.180367 last_received_ts = 123.180382 last_seq = 92 current_ts = 123.197037 current_received_ts = 123.196564 current_seq = 93 count = 87 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.197037 last_received_ts = 123.196564 last_seq = 93 current_ts = 123.213699 current_received_ts = 123.213448 current_seq = 94 count = 88 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.213699 last_received_ts = 123.213448 last_seq = 94 current_ts = 123.230377 current_received_ts = 123.230194 current_seq = 95 count = 89 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.230377 last_received_ts = 123.230194 last_seq = 95 current_ts = 123.247032 current_received_ts = 123.246552 current_seq = 96 count = 90 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 123.247032 last_received_ts = 123.246552 last_seq = 96 current_ts = 123.263695 current_received_ts = 123.263458 current_seq = 97 count = 91 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 123.263695 last_received_ts = 123.263458 last_seq = 97 current_ts = 123.280373 current_received_ts = 123.279861 current_seq = 98 count = 92 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 123.280373 last_received_ts = 123.279861 last_seq = 98 current_ts = 123.297043 current_received_ts = 123.296593 current_seq = 99 count = 93 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 123.297043 last_received_ts = 123.296593 last_seq = 99 current_ts = 123.313713 current_received_ts = 123.313469 current_seq = 100 count = 94 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 123.313713 last_received_ts = 123.313469 last_seq = 100 current_ts = 123.330368 current_received_ts = 123.330200 current_seq = 101 count = 95 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 123.330368 last_received_ts = 123.330200 last_seq = 101 current_ts = 123.347038 current_received_ts = 123.346596 current_seq = 102 count = 96 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.347038 last_received_ts = 123.346596 last_seq = 102 current_ts = 123.363708 current_received_ts = 123.363914 current_seq = 103 count = 97 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 123.363708 last_received_ts = 123.363914 last_seq = 103 current_ts = 123.380379 current_received_ts = 123.380257 current_seq = 104 count = 98 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 123.380379 last_received_ts = 123.380257 last_seq = 104 current_ts = 123.397049 current_received_ts = 123.396706 current_seq = 105 count = 99 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.397049 last_received_ts = 123.396706 last_seq = 105 current_ts = 123.413712 current_received_ts = 123.413521 current_seq = 106 count = 100 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.413712 last_received_ts = 123.413521 last_seq = 106 current_ts = 123.430367 current_received_ts = 123.430199 current_seq = 107 count = 101 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 123.430367 last_received_ts = 123.430199 last_seq = 107 current_ts = 123.447044 current_received_ts = 123.446541 current_seq = 108 count = 102 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 123.447044 last_received_ts = 123.446541 last_seq = 108 current_ts = 123.463707 current_received_ts = 123.463928 current_seq = 109 count = 103 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 123.463707 last_received_ts = 123.463928 last_seq = 109 current_ts = 123.480377 current_received_ts = 123.480225 current_seq = 110 count = 104 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 123.480377 last_received_ts = 123.480225 last_seq = 110 current_ts = 123.497047 current_received_ts = 123.496582 current_seq = 111 count = 105 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.497047 last_received_ts = 123.496582 last_seq = 111 current_ts = 123.513718 current_received_ts = 123.513214 current_seq = 112 count = 106 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 15us (kms_flip:2294) DEBUG: name = flip last_ts = 123.513718 last_received_ts = 123.513214 last_seq = 112 current_ts = 123.530380 current_received_ts = 123.530174 current_seq = 113 count = 107 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 14us (kms_flip:2294) DEBUG: name = flip last_ts = 123.530380 last_received_ts = 123.530174 last_seq = 113 current_ts = 123.547050 current_received_ts = 123.546776 current_seq = 114 count = 108 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 14us (kms_flip:2294) DEBUG: name = flip last_ts = 123.547050 last_received_ts = 123.546776 last_seq = 114 current_ts = 123.563713 current_received_ts = 123.563148 current_seq = 115 count = 109 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 15us (kms_flip:2294) DEBUG: name = flip last_ts = 123.563713 last_received_ts = 123.563148 last_seq = 115 current_ts = 123.580376 current_received_ts = 123.580742 current_seq = 116 count = 110 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 16us (kms_flip:2294) DEBUG: name = flip last_ts = 123.580376 last_received_ts = 123.580742 last_seq = 116 current_ts = 123.597046 current_received_ts = 123.596497 current_seq = 117 count = 111 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 15us (kms_flip:2294) DEBUG: name = flip last_ts = 123.597046 last_received_ts = 123.596497 last_seq = 117 current_ts = 123.613716 current_received_ts = 123.613129 current_seq = 118 count = 112 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 14us (kms_flip:2294) DEBUG: name = flip last_ts = 123.613716 last_received_ts = 123.613129 last_seq = 118 current_ts = 123.630379 current_received_ts = 123.630096 current_seq = 119 count = 113 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 15us (kms_flip:2294) DEBUG: name = flip last_ts = 123.630379 last_received_ts = 123.630096 last_seq = 119 current_ts = 123.647049 current_received_ts = 123.646683 current_seq = 120 count = 114 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 14us (kms_flip:2294) DEBUG: name = flip last_ts = 123.647049 last_received_ts = 123.646683 last_seq = 120 current_ts = 123.663719 current_received_ts = 123.663368 current_seq = 121 count = 115 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 15us (kms_flip:2294) DEBUG: name = flip last_ts = 123.663719 last_received_ts = 123.663368 last_seq = 121 current_ts = 123.680389 current_received_ts = 123.680061 current_seq = 122 count = 116 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 14us (kms_flip:2294) DEBUG: name = flip last_ts = 123.680389 last_received_ts = 123.680061 last_seq = 122 current_ts = 123.697052 current_received_ts = 123.696678 current_seq = 123 count = 117 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 14us (kms_flip:2294) DEBUG: name = flip last_ts = 123.697052 last_received_ts = 123.696678 last_seq = 123 current_ts = 123.713722 current_received_ts = 123.713196 current_seq = 124 count = 118 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 14us (kms_flip:2294) DEBUG: name = flip last_ts = 123.713722 last_received_ts = 123.713196 last_seq = 124 current_ts = 123.730385 current_received_ts = 123.730057 current_seq = 125 count = 119 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 15us (kms_flip:2294) DEBUG: name = flip last_ts = 123.730385 last_received_ts = 123.730057 last_seq = 125 current_ts = 123.747040 current_received_ts = 123.746597 current_seq = 126 count = 120 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 26us (kms_flip:2294) DEBUG: name = flip last_ts = 123.747040 last_received_ts = 123.746597 last_seq = 126 current_ts = 123.763718 current_received_ts = 123.763916 current_seq = 127 count = 121 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 19us (kms_flip:2294) DEBUG: name = flip last_ts = 123.763718 last_received_ts = 123.763916 last_seq = 127 current_ts = 123.780388 current_received_ts = 123.780220 current_seq = 128 count = 122 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 123.780388 last_received_ts = 123.780220 last_seq = 128 current_ts = 123.797043 current_received_ts = 123.796600 current_seq = 129 count = 123 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 123.797043 last_received_ts = 123.796600 last_seq = 129 current_ts = 123.813713 current_received_ts = 123.813820 current_seq = 130 count = 124 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 123.813713 last_received_ts = 123.813820 last_seq = 130 current_ts = 123.830383 current_received_ts = 123.829887 current_seq = 131 count = 125 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.830383 last_received_ts = 123.829887 last_seq = 131 current_ts = 123.847054 current_received_ts = 123.847076 current_seq = 132 count = 126 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 21us (kms_flip:2294) DEBUG: name = flip last_ts = 123.847054 last_received_ts = 123.847076 last_seq = 132 current_ts = 123.863716 current_received_ts = 123.863914 current_seq = 133 count = 127 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 123.863716 last_received_ts = 123.863914 last_seq = 133 current_ts = 123.880379 current_received_ts = 123.880196 current_seq = 134 count = 128 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 26us (kms_flip:2294) DEBUG: name = flip last_ts = 123.880379 last_received_ts = 123.880196 last_seq = 134 current_ts = 123.897057 current_received_ts = 123.896584 current_seq = 135 count = 129 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.897057 last_received_ts = 123.896584 last_seq = 135 current_ts = 123.913712 current_received_ts = 123.913521 current_seq = 136 count = 130 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.913712 last_received_ts = 123.913521 last_seq = 136 current_ts = 123.930389 current_received_ts = 123.929893 current_seq = 137 count = 131 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 123.930389 last_received_ts = 123.929893 last_seq = 137 current_ts = 123.947060 current_received_ts = 123.946686 current_seq = 138 count = 132 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 123.947060 last_received_ts = 123.946686 last_seq = 138 current_ts = 123.963722 current_received_ts = 123.963776 current_seq = 139 count = 133 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 123.963722 last_received_ts = 123.963776 last_seq = 139 current_ts = 123.980385 current_received_ts = 123.980232 current_seq = 140 count = 134 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 26us (kms_flip:2294) DEBUG: name = flip last_ts = 123.980385 last_received_ts = 123.980232 last_seq = 140 current_ts = 123.997063 current_received_ts = 123.996597 current_seq = 141 count = 135 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 123.997063 last_received_ts = 123.996597 last_seq = 141 current_ts = 124.013718 current_received_ts = 124.013924 current_seq = 142 count = 136 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 124.013718 last_received_ts = 124.013924 last_seq = 142 current_ts = 124.030388 current_received_ts = 124.030190 current_seq = 143 count = 137 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 26us (kms_flip:2294) DEBUG: name = flip last_ts = 124.030388 last_received_ts = 124.030190 last_seq = 143 current_ts = 124.047058 current_received_ts = 124.046593 current_seq = 144 count = 138 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.047058 last_received_ts = 124.046593 last_seq = 144 current_ts = 124.063721 current_received_ts = 124.063812 current_seq = 145 count = 139 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 124.063721 last_received_ts = 124.063812 last_seq = 145 current_ts = 124.080399 current_received_ts = 124.079895 current_seq = 146 count = 140 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 124.080399 last_received_ts = 124.079895 last_seq = 146 current_ts = 124.097061 current_received_ts = 124.096695 current_seq = 147 count = 141 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.097061 last_received_ts = 124.096695 last_seq = 147 current_ts = 124.113716 current_received_ts = 124.113518 current_seq = 148 count = 142 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.113716 last_received_ts = 124.113518 last_seq = 148 current_ts = 124.130394 current_received_ts = 124.130188 current_seq = 149 count = 143 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 124.130394 last_received_ts = 124.130188 last_seq = 149 current_ts = 124.147064 current_received_ts = 124.146599 current_seq = 150 count = 144 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.147064 last_received_ts = 124.146599 last_seq = 150 current_ts = 124.163719 current_received_ts = 124.164146 current_seq = 151 count = 145 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 124.163719 last_received_ts = 124.164146 last_seq = 151 current_ts = 124.180389 current_received_ts = 124.179863 current_seq = 152 count = 146 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.180389 last_received_ts = 124.179863 last_seq = 152 current_ts = 124.197067 current_received_ts = 124.196693 current_seq = 153 count = 147 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.197067 last_received_ts = 124.196693 last_seq = 153 current_ts = 124.213730 current_received_ts = 124.213478 current_seq = 154 count = 148 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.213730 last_received_ts = 124.213478 last_seq = 154 current_ts = 124.230392 current_received_ts = 124.230202 current_seq = 155 count = 149 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 26us (kms_flip:2294) DEBUG: name = flip last_ts = 124.230392 last_received_ts = 124.230202 last_seq = 155 current_ts = 124.247070 current_received_ts = 124.246574 current_seq = 156 count = 150 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.247070 last_received_ts = 124.246574 last_seq = 156 current_ts = 124.263733 current_received_ts = 124.263680 current_seq = 157 count = 151 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 124.263733 last_received_ts = 124.263680 last_seq = 157 current_ts = 124.280388 current_received_ts = 124.280258 current_seq = 158 count = 152 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 47us (kms_flip:2294) DEBUG: name = flip last_ts = 124.280388 last_received_ts = 124.280258 last_seq = 158 current_ts = 124.297066 current_received_ts = 124.296577 current_seq = 159 count = 153 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.297066 last_received_ts = 124.296577 last_seq = 159 current_ts = 124.313728 current_received_ts = 124.313721 current_seq = 160 count = 154 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 124.313728 last_received_ts = 124.313721 last_seq = 160 current_ts = 124.330391 current_received_ts = 124.330193 current_seq = 161 count = 155 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.330391 last_received_ts = 124.330193 last_seq = 161 current_ts = 124.347069 current_received_ts = 124.346603 current_seq = 162 count = 156 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 26us (kms_flip:2294) DEBUG: name = flip last_ts = 124.347069 last_received_ts = 124.346603 last_seq = 162 current_ts = 124.363739 current_received_ts = 124.363754 current_seq = 163 count = 157 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 26us (kms_flip:2294) DEBUG: name = flip last_ts = 124.363739 last_received_ts = 124.363754 last_seq = 163 current_ts = 124.380394 current_received_ts = 124.380257 current_seq = 164 count = 158 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.380394 last_received_ts = 124.380257 last_seq = 164 current_ts = 124.397064 current_received_ts = 124.397087 current_seq = 165 count = 159 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 124.397064 last_received_ts = 124.397087 last_seq = 165 current_ts = 124.413727 current_received_ts = 124.413460 current_seq = 166 count = 160 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.413727 last_received_ts = 124.413460 last_seq = 166 current_ts = 124.430405 current_received_ts = 124.430199 current_seq = 167 count = 161 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.430405 last_received_ts = 124.430199 last_seq = 167 current_ts = 124.447067 current_received_ts = 124.446579 current_seq = 168 count = 162 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.447067 last_received_ts = 124.446579 last_seq = 168 current_ts = 124.463730 current_received_ts = 124.463463 current_seq = 169 count = 163 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.463730 last_received_ts = 124.463463 last_seq = 169 current_ts = 124.480408 current_received_ts = 124.479904 current_seq = 170 count = 164 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 124.480408 last_received_ts = 124.479904 last_seq = 170 current_ts = 124.497070 current_received_ts = 124.496719 current_seq = 171 count = 165 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 124.497070 last_received_ts = 124.496719 last_seq = 171 current_ts = 124.513725 current_received_ts = 124.513458 current_seq = 172 count = 166 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.513725 last_received_ts = 124.513458 last_seq = 172 current_ts = 124.530396 current_received_ts = 124.530197 current_seq = 173 count = 167 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.530396 last_received_ts = 124.530197 last_seq = 173 current_ts = 124.547073 current_received_ts = 124.546593 current_seq = 174 count = 168 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 124.547073 last_received_ts = 124.546593 last_seq = 174 current_ts = 124.563728 current_received_ts = 124.563934 current_seq = 175 count = 169 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 64us (kms_flip:2294) DEBUG: name = flip last_ts = 124.563728 last_received_ts = 124.563934 last_seq = 175 current_ts = 124.580399 current_received_ts = 124.580620 current_seq = 176 count = 170 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 21us (kms_flip:2294) DEBUG: name = flip last_ts = 124.580399 last_received_ts = 124.580620 last_seq = 176 current_ts = 124.597076 current_received_ts = 124.596619 current_seq = 177 count = 171 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.597076 last_received_ts = 124.596619 last_seq = 177 current_ts = 124.613739 current_received_ts = 124.613457 current_seq = 178 count = 172 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.613739 last_received_ts = 124.613457 last_seq = 178 current_ts = 124.630402 current_received_ts = 124.630203 current_seq = 179 count = 173 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.630402 last_received_ts = 124.630203 last_seq = 179 current_ts = 124.647072 current_received_ts = 124.646584 current_seq = 180 count = 174 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 124.647072 last_received_ts = 124.646584 last_seq = 180 current_ts = 124.663742 current_received_ts = 124.663513 current_seq = 181 count = 175 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 124.663742 last_received_ts = 124.663513 last_seq = 181 current_ts = 124.680412 current_received_ts = 124.679909 current_seq = 182 count = 176 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.680412 last_received_ts = 124.679909 last_seq = 182 current_ts = 124.697075 current_received_ts = 124.696709 current_seq = 183 count = 177 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.697075 last_received_ts = 124.696709 last_seq = 183 current_ts = 124.713745 current_received_ts = 124.713478 current_seq = 184 count = 178 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.713745 last_received_ts = 124.713478 last_seq = 184 current_ts = 124.730408 current_received_ts = 124.730247 current_seq = 185 count = 179 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.730408 last_received_ts = 124.730247 last_seq = 185 current_ts = 124.747078 current_received_ts = 124.746643 current_seq = 186 count = 180 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.747078 last_received_ts = 124.746643 last_seq = 186 current_ts = 124.763748 current_received_ts = 124.763779 current_seq = 187 count = 181 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 124.763748 last_received_ts = 124.763779 last_seq = 187 current_ts = 124.780411 current_received_ts = 124.779938 current_seq = 188 count = 182 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 48us (kms_flip:2294) DEBUG: name = flip last_ts = 124.780411 last_received_ts = 124.779938 last_seq = 188 current_ts = 124.797081 current_received_ts = 124.797066 current_seq = 189 count = 183 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 21us (kms_flip:2294) DEBUG: name = flip last_ts = 124.797081 last_received_ts = 124.797066 last_seq = 189 current_ts = 124.813736 current_received_ts = 124.813499 current_seq = 190 count = 184 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 124.813736 last_received_ts = 124.813499 last_seq = 190 current_ts = 124.830406 current_received_ts = 124.830193 current_seq = 191 count = 185 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.830406 last_received_ts = 124.830193 last_seq = 191 current_ts = 124.847084 current_received_ts = 124.846603 current_seq = 192 count = 186 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 124.847084 last_received_ts = 124.846603 last_seq = 192 current_ts = 124.863739 current_received_ts = 124.863518 current_seq = 193 count = 187 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 124.863739 last_received_ts = 124.863518 last_seq = 193 current_ts = 124.880402 current_received_ts = 124.879898 current_seq = 194 count = 188 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.880402 last_received_ts = 124.879898 last_seq = 194 current_ts = 124.897072 current_received_ts = 124.896729 current_seq = 195 count = 189 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 21us (kms_flip:2294) DEBUG: name = flip last_ts = 124.897072 last_received_ts = 124.896729 last_seq = 195 current_ts = 124.913750 current_received_ts = 124.913513 current_seq = 196 count = 190 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 51us (kms_flip:2294) DEBUG: name = flip last_ts = 124.913750 last_received_ts = 124.913513 last_seq = 196 current_ts = 124.930412 current_received_ts = 124.930222 current_seq = 197 count = 191 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 25us (kms_flip:2294) DEBUG: name = flip last_ts = 124.930412 last_received_ts = 124.930222 last_seq = 197 current_ts = 124.947083 current_received_ts = 124.946739 current_seq = 198 count = 192 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.947083 last_received_ts = 124.946739 last_seq = 198 current_ts = 124.963745 current_received_ts = 124.963684 current_seq = 199 count = 193 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 124.963745 last_received_ts = 124.963684 last_seq = 199 current_ts = 124.980415 current_received_ts = 124.980202 current_seq = 200 count = 194 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 124.980415 last_received_ts = 124.980202 last_seq = 200 current_ts = 124.997086 current_received_ts = 124.996628 current_seq = 201 count = 195 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 124.997086 last_received_ts = 124.996628 last_seq = 201 current_ts = 125.013756 current_received_ts = 125.013298 current_seq = 202 count = 196 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 125.013756 last_received_ts = 125.013298 last_seq = 202 current_ts = 125.030411 current_received_ts = 125.030243 current_seq = 203 count = 197 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 125.030411 last_received_ts = 125.030243 last_seq = 203 current_ts = 125.047089 current_received_ts = 125.046654 current_seq = 204 count = 198 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 24us (kms_flip:2294) DEBUG: name = flip last_ts = 125.047089 last_received_ts = 125.046654 last_seq = 204 current_ts = 125.063744 current_received_ts = 125.063812 current_seq = 205 count = 199 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 22us (kms_flip:2294) DEBUG: name = flip last_ts = 125.063744 last_received_ts = 125.063812 last_seq = 205 current_ts = 125.080421 current_received_ts = 125.079933 current_seq = 206 count = 200 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 46us (kms_flip:2294) DEBUG: name = flip last_ts = 125.080421 last_received_ts = 125.079933 last_seq = 206 current_ts = 125.097084 current_received_ts = 125.096786 current_seq = 207 count = 201 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 23us (kms_flip:2294) DEBUG: name = flip last_ts = 125.097084 last_received_ts = 125.096786 last_seq = 207 current_ts = 125.113747 current_received_ts = 125.113495 current_seq = 208 count = 202 seq_step = 1 (kms_flip:2294) DEBUG: Vblank took 1137us (kms_flip:2294) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2294) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2294) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:2294) igt_core-INFO: Stack trace: (kms_flip:2294) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2294) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:2294) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:2294) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() (kms_flip:2294) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:2294) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2294) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2294) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest C-HDMI-A1: FAIL (3.810s)
Dmesg	<6> [121.268965] [IGT] kms_flip: starting dynamic subtest C-HDMI-A1 <7> [121.270217] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:182] <7> [121.270564] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:184] <7> [121.310479] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A] <7> [121.312028] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [121.312281] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [121.313024] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [121.313437] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1) <7> [121.313866] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_count (expected 4, found 0) <7> [121.314249] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000) <7> [121.314642] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [121.315077] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [121.315457] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [121.315873] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [121.316298] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [121.316730] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [121.317207] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [121.317615] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [121.318032] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [121.318443] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [121.318862] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [121.319241] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [121.319625] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [121.320052] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [121.320456] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [121.320911] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [121.321336] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [121.321737] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [121.322163] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [121.322570] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [121.323006] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [121.323413] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [121.323817] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [121.324197] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [121.324585] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [121.325949] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [121.326451] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [121.326876] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [121.327258] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [121.327715] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [121.328162] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_infoframe (expected yes, found no) <7> [121.328597] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [121.329153] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [121.329570] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [121.329987] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in port_clock (expected 222750, found 0) <7> [121.330369] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [121.330786] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000) <7> [121.331196] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in avi infoframe <7> [121.331633] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [121.332202] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [121.332207] i915 0000:00:02.0: colorspace: RGB <7> [121.332210] i915 0000:00:02.0: scan mode: Underscan <7> [121.332214] i915 0000:00:02.0: colorimetry: No Data <7> [121.332217] i915 0000:00:02.0: picture aspect: No Data <7> [121.332220] i915 0000:00:02.0: active aspect: Same as Picture <7> [121.332223] i915 0000:00:02.0: itc: No Data <7> [121.332226] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [121.332229] i915 0000:00:02.0: quantization range: Full <7> [121.332232] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [121.332235] i915 0000:00:02.0: video code: 0 <7> [121.332238] i915 0000:00:02.0: ycc quantization range: Full <7> [121.332241] i915 0000:00:02.0: hdmi content type: Graphics <7> [121.332244] i915 0000:00:02.0: pixel repeat: 0 <7> [121.332247] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [121.332251] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [121.332707] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in spd infoframe <7> [121.333138] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [121.333563] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [121.333568] i915 0000:00:02.0: vendor: Intel <7> [121.333572] i915 0000:00:02.0: product: Integrated gfx <7> [121.333595] i915 0000:00:02.0: source device information: PC General (0x9) <7> [121.333599] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [121.334026] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hdmi infoframe <7> [121.334431] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [121.334831] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [121.334835] i915 0000:00:02.0: empty frame <7> [121.334839] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [121.335219] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] fastset requirement not met, forcing full modeset <7> [121.335635] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:121:pipe B] releasing PORT PLL B <7> [121.336099] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:121:pipe B] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x2 -> 0x0 <7> [121.336547] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:115:cursor B] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0 <7> [121.337016] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:121:pipe B] min cdclk: 192000 kHz -> 0 kHz <7> [121.337467] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [121.337932] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz <7> [121.338311] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4 <7> [121.338698] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:121:pipe B] enable: no [modeset] <7> [121.339243] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:79:plane 1B] fb: [NOFB], visible: no <7> [121.339697] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:88:plane 2B] fb: [NOFB], visible: no <7> [121.340121] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:97:plane 3B] fb: [NOFB], visible: no <7> [121.340501] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:106:plane 4B] fb: [NOFB], visible: no <7> [121.340929] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:115:cursor B] fb: [NOFB], visible: no <7> [121.341489] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:166:HDMI-A-1][ENCODER:165:DDI B/PHY B] Disable audio codec on [CRTC:121:pipe B] <7> [121.363438] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port B <7> [121.364505] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B <7> [121.376344] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10 <7> [121.380876] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time <7> [121.486317] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_B <7> [121.487459] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL B (active 0x2, on? 1) for [CRTC:121:pipe B] <7> [121.489710] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL B <7> [121.491162] 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> [121.491763] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [121.492261] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [121.492683] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:166:HDMI-A-1] <7> [121.493343] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-b <7> [121.493844] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:121:pipe B] <7> [121.495076] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [121.495581] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz <7> [121.496095] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13 <7> [121.496674] 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> [121.497441] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C] <7> [121.497916] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C] <7> [121.497979] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:166:HDMI-A-1] <7> [121.498165] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 12 bpc for HDMI output (pipe bpp: 36) <7> [121.498726] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:164:pipe C] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [121.499250] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:165:DDI B/PHY B] [CRTC:164:pipe C] <7> [121.499648] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [121.500238] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [121.500665] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [121.501126] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [121.501508] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d) <7> [121.501927] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [121.502307] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [121.502769] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL <7> [121.502805] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled <7> [121.502847] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [121.503304] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [121.503700] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [121.504141] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [121.504549] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [121.504978] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [121.505385] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [121.505768] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [121.506182] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [121.506674] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [121.507088] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [121.507470] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [121.507889] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [121.508285] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [121.508728] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [121.510228] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [121.510850] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [121.511235] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [121.511613] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [121.512099] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [121.512595] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [121.513013] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [121.513510] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [121.513986] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [121.514393] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [121.514775] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [121.515197] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [121.515612] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [121.516022] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in has_infoframe (expected no, found yes) <7> [121.516404] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in dpll_hw_state <7> [121.516839] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [121.517218] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: ebb0: 0x0, ebb4: 0x0,pll0: 0x0, pll1: 0x0, pll2: 0x0, pll3: 0x0, pll6: 0x0, pll8: 0x0, pll9: 0x0, pll10: 0x0, pcsdw12: 0x0 <7> [121.517640] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [121.518053] i915 0000:00:02.0: [drm:intel_pipe_config_compare [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> [121.518496] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [121.518915] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [121.519297] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [121.519675] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in port_clock (expected 0, found 222750) <7> [121.520115] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [121.520521] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006) <7> [121.520945] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in avi infoframe <7> [121.521354] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [121.521736] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [121.522146] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [121.522152] i915 0000:00:02.0: colorspace: RGB <7> [121.522155] i915 0000:00:02.0: scan mode: Underscan <7> [121.522159] i915 0000:00:02.0: colorimetry: No Data <7> [121.522162] i915 0000:00:02.0: picture aspect: No Data <7> [121.522165] i915 0000:00:02.0: active aspect: Same as Picture <7> [121.522168] i915 0000:00:02.0: itc: No Data <7> [121.522171] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [121.522174] i915 0000:00:02.0: quantization range: Full <7> [121.522177] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [121.522180] i915 0000:00:02.0: video code: 0 <7> [121.522183] i915 0000:00:02.0: ycc quantization range: Full <7> [121.522186] i915 0000:00:02.0: hdmi content type: Graphics <7> [121.522190] i915 0000:00:02.0: pixel repeat: 0 <7> [121.522192] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [121.522196] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in spd infoframe <7> [121.522597] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [121.522997] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [121.523424] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [121.523428] i915 0000:00:02.0: vendor: Intel <7> [121.523432] i915 0000:00:02.0: product: Integrated gfx <7> [121.523435] i915 0000:00:02.0: source device information: PC General (0x9) <7> [121.523439] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in hdmi infoframe <7> [121.523855] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [121.524349] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [121.524731] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [121.524735] i915 0000:00:02.0: empty frame <7> [121.524740] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:164:pipe C] fastset requirement not met, forcing full modeset <7> [121.525262] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:164:pipe C] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x4 <7> [121.525714] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:122:plane 1C] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988 <7> [121.526125] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:158:cursor C] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32 <7> [121.526503] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,*twm, swm, stwm <7> [121.526929] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0 <7> [121.527325] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0 <7> [121.527702] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 17, 17, 17, 34, 34, 34, 34, 34, 31, 0, 0 <7> [121.528130] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] min_ddb_uv 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [121.528579] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:164:pipe C] min cdclk: 0 kHz -> 192000 kHz <7> [121.529037] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:164:pipe C] using pre-allocated PORT PLL B <7> [121.529424] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:164:pipe C] reserving PORT PLL B <7> [121.529842] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:164:pipe C] enable: yes [modeset] <7> [121.530225] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [121.530604] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: C, pipe bpp: 36, dithering: 0 <7> [121.531016] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [121.531399] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [121.531778] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [121.532199] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [121.532580] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [121.532978] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6 <7> [121.533356] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [121.533360] i915 0000:00:02.0: colorspace: RGB <7> [121.533364] i915 0000:00:02.0: scan mode: Underscan <7> [121.533367] i915 0000:00:02.0: colorimetry: No Data <7> [121.533370] i915 0000:00:02.0: picture aspect: No Data <7> [121.533373] i915 0000:00:02.0: active aspect: Same as Picture <7> [121.533376] i915 0000:00:02.0: itc: No Data <7> [121.533379] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [121.533382] i915 0000:00:02.0: quantization range: Full <7> [121.533385] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [121.533388] i915 0000:00:02.0: video code: 0 <7> [121.533391] i915 0000:00:02.0: ycc quantization range: Full <7> [121.533394] i915 0000:00:02.0: hdmi content type: Graphics <7> [121.533397] i915 0000:00:02.0: pixel repeat: 0 <7> [121.533400] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [121.533404] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [121.533408] i915 0000:00:02.0: vendor: Intel <7> [121.533411] i915 0000:00:02.0: product: Integrated gfx <7> [121.533414] i915 0000:00:02.0: source device information: PC General (0x9) <7> [121.533417] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [121.533421] i915 0000:00:02.0: empty frame <7> [121.533424] 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> [121.533846] 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> [121.534227] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [121.534603] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [121.535011] 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> [121.535401] 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> [121.535780] 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> [121.536268] 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> [121.536674] 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> [121.537178] 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> [121.537578] 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> [121.538013] 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> [121.538416] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pixel rate 148500, min cdclk 192000, min voltage level 0 <7> [121.538852] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [121.539257] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 1, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [121.539638] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [121.540041] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [121.540428] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [121.540842] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [121.541220] 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> [121.541602] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [121.542010] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [121.542388] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [121.542764] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [121.543248] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [121.543632] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [121.544028] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [121.544508] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:122:plane 1C] fb: [FB:182] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [121.544971] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [121.545381] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [121.545763] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:131:plane 2C] fb: [NOFB], visible: no <7> [121.546190] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:140:plane 3C] fb: [NOFB], visible: no <7> [121.546597] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:149:plane 4C] fb: [NOFB], visible: no <7> [121.547018] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:158:cursor C] fb: [NOFB], visible: no <7> [121.549721] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-b <7> [121.550697] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [121.551159] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [121.551725] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL B (active 0x4, on? 0) for [CRTC:164:pipe C] <7> [121.552159] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL B <7> [121.552944] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_B <7> [121.553469] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe C <7> [121.588211] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:166:HDMI-A-1][ENCODER:165:DDI B/PHY B] Enable audio codec on [CRTC:164:pipe C], 32 bytes ELD <7> [121.604865] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000) <7> [121.605345] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <7> [121.607431] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:166:HDMI-A-1] <7> [121.609141] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:164:pipe C] <6> [125.081251] [IGT] kms_flip: finished subtest C-HDMI-A1, FAIL

Detail

Value

Duration

3.81 seconds

Hostname

shard-glk1

Igt-Version

IGT-Version: 2.4-g8966d7c15 (x86_64) (Linux: 7.1.0-rc3-CI_DRM_18470-g767b83aa80c6+ x86_64)

Out

Starting dynamic subtest: C-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-HDMI-A1: FAIL (3.810s)

Err

Starting dynamic subtest: C-HDMI-A1
(kms_flip:2294) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2294) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2294) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2294) DEBUG: Vblank took 26us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.097038
last_received_ts = 123.096611
last_seq = 87
current_ts = 123.113693
current_received_ts = 123.113869
current_seq = 88
count = 82
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.113693
last_received_ts = 123.113869
last_seq = 88
current_ts = 123.130371
current_received_ts = 123.130211
current_seq = 89
count = 83
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.130371
last_received_ts = 123.130211
last_seq = 89
current_ts = 123.147041
current_received_ts = 123.146576
current_seq = 90
count = 84
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.147041
last_received_ts = 123.146576
last_seq = 90
current_ts = 123.163696
current_received_ts = 123.163666
current_seq = 91
count = 85
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.163696
last_received_ts = 123.163666
last_seq = 91
current_ts = 123.180367
current_received_ts = 123.180382
current_seq = 92
count = 86
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 38us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.180367
last_received_ts = 123.180382
last_seq = 92
current_ts = 123.197037
current_received_ts = 123.196564
current_seq = 93
count = 87
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.197037
last_received_ts = 123.196564
last_seq = 93
current_ts = 123.213699
current_received_ts = 123.213448
current_seq = 94
count = 88
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.213699
last_received_ts = 123.213448
last_seq = 94
current_ts = 123.230377
current_received_ts = 123.230194
current_seq = 95
count = 89
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.230377
last_received_ts = 123.230194
last_seq = 95
current_ts = 123.247032
current_received_ts = 123.246552
current_seq = 96
count = 90
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.247032
last_received_ts = 123.246552
last_seq = 96
current_ts = 123.263695
current_received_ts = 123.263458
current_seq = 97
count = 91
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.263695
last_received_ts = 123.263458
last_seq = 97
current_ts = 123.280373
current_received_ts = 123.279861
current_seq = 98
count = 92
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.280373
last_received_ts = 123.279861
last_seq = 98
current_ts = 123.297043
current_received_ts = 123.296593
current_seq = 99
count = 93
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.297043
last_received_ts = 123.296593
last_seq = 99
current_ts = 123.313713
current_received_ts = 123.313469
current_seq = 100
count = 94
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.313713
last_received_ts = 123.313469
last_seq = 100
current_ts = 123.330368
current_received_ts = 123.330200
current_seq = 101
count = 95
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.330368
last_received_ts = 123.330200
last_seq = 101
current_ts = 123.347038
current_received_ts = 123.346596
current_seq = 102
count = 96
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.347038
last_received_ts = 123.346596
last_seq = 102
current_ts = 123.363708
current_received_ts = 123.363914
current_seq = 103
count = 97
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.363708
last_received_ts = 123.363914
last_seq = 103
current_ts = 123.380379
current_received_ts = 123.380257
current_seq = 104
count = 98
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.380379
last_received_ts = 123.380257
last_seq = 104
current_ts = 123.397049
current_received_ts = 123.396706
current_seq = 105
count = 99
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.397049
last_received_ts = 123.396706
last_seq = 105
current_ts = 123.413712
current_received_ts = 123.413521
current_seq = 106
count = 100
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.413712
last_received_ts = 123.413521
last_seq = 106
current_ts = 123.430367
current_received_ts = 123.430199
current_seq = 107
count = 101
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.430367
last_received_ts = 123.430199
last_seq = 107
current_ts = 123.447044
current_received_ts = 123.446541
current_seq = 108
count = 102
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.447044
last_received_ts = 123.446541
last_seq = 108
current_ts = 123.463707
current_received_ts = 123.463928
current_seq = 109
count = 103
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.463707
last_received_ts = 123.463928
last_seq = 109
current_ts = 123.480377
current_received_ts = 123.480225
current_seq = 110
count = 104
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.480377
last_received_ts = 123.480225
last_seq = 110
current_ts = 123.497047
current_received_ts = 123.496582
current_seq = 111
count = 105
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.497047
last_received_ts = 123.496582
last_seq = 111
current_ts = 123.513718
current_received_ts = 123.513214
current_seq = 112
count = 106
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 15us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.513718
last_received_ts = 123.513214
last_seq = 112
current_ts = 123.530380
current_received_ts = 123.530174
current_seq = 113
count = 107
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 14us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.530380
last_received_ts = 123.530174
last_seq = 113
current_ts = 123.547050
current_received_ts = 123.546776
current_seq = 114
count = 108
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 14us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.547050
last_received_ts = 123.546776
last_seq = 114
current_ts = 123.563713
current_received_ts = 123.563148
current_seq = 115
count = 109
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 15us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.563713
last_received_ts = 123.563148
last_seq = 115
current_ts = 123.580376
current_received_ts = 123.580742
current_seq = 116
count = 110
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 16us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.580376
last_received_ts = 123.580742
last_seq = 116
current_ts = 123.597046
current_received_ts = 123.596497
current_seq = 117
count = 111
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 15us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.597046
last_received_ts = 123.596497
last_seq = 117
current_ts = 123.613716
current_received_ts = 123.613129
current_seq = 118
count = 112
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 14us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.613716
last_received_ts = 123.613129
last_seq = 118
current_ts = 123.630379
current_received_ts = 123.630096
current_seq = 119
count = 113
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 15us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.630379
last_received_ts = 123.630096
last_seq = 119
current_ts = 123.647049
current_received_ts = 123.646683
current_seq = 120
count = 114
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 14us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.647049
last_received_ts = 123.646683
last_seq = 120
current_ts = 123.663719
current_received_ts = 123.663368
current_seq = 121
count = 115
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 15us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.663719
last_received_ts = 123.663368
last_seq = 121
current_ts = 123.680389
current_received_ts = 123.680061
current_seq = 122
count = 116
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 14us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.680389
last_received_ts = 123.680061
last_seq = 122
current_ts = 123.697052
current_received_ts = 123.696678
current_seq = 123
count = 117
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 14us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.697052
last_received_ts = 123.696678
last_seq = 123
current_ts = 123.713722
current_received_ts = 123.713196
current_seq = 124
count = 118
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 14us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.713722
last_received_ts = 123.713196
last_seq = 124
current_ts = 123.730385
current_received_ts = 123.730057
current_seq = 125
count = 119
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 15us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.730385
last_received_ts = 123.730057
last_seq = 125
current_ts = 123.747040
current_received_ts = 123.746597
current_seq = 126
count = 120
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 26us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.747040
last_received_ts = 123.746597
last_seq = 126
current_ts = 123.763718
current_received_ts = 123.763916
current_seq = 127
count = 121
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 19us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.763718
last_received_ts = 123.763916
last_seq = 127
current_ts = 123.780388
current_received_ts = 123.780220
current_seq = 128
count = 122
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.780388
last_received_ts = 123.780220
last_seq = 128
current_ts = 123.797043
current_received_ts = 123.796600
current_seq = 129
count = 123
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.797043
last_received_ts = 123.796600
last_seq = 129
current_ts = 123.813713
current_received_ts = 123.813820
current_seq = 130
count = 124
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.813713
last_received_ts = 123.813820
last_seq = 130
current_ts = 123.830383
current_received_ts = 123.829887
current_seq = 131
count = 125
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.830383
last_received_ts = 123.829887
last_seq = 131
current_ts = 123.847054
current_received_ts = 123.847076
current_seq = 132
count = 126
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 21us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.847054
last_received_ts = 123.847076
last_seq = 132
current_ts = 123.863716
current_received_ts = 123.863914
current_seq = 133
count = 127
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.863716
last_received_ts = 123.863914
last_seq = 133
current_ts = 123.880379
current_received_ts = 123.880196
current_seq = 134
count = 128
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 26us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.880379
last_received_ts = 123.880196
last_seq = 134
current_ts = 123.897057
current_received_ts = 123.896584
current_seq = 135
count = 129
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.897057
last_received_ts = 123.896584
last_seq = 135
current_ts = 123.913712
current_received_ts = 123.913521
current_seq = 136
count = 130
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.913712
last_received_ts = 123.913521
last_seq = 136
current_ts = 123.930389
current_received_ts = 123.929893
current_seq = 137
count = 131
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.930389
last_received_ts = 123.929893
last_seq = 137
current_ts = 123.947060
current_received_ts = 123.946686
current_seq = 138
count = 132
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.947060
last_received_ts = 123.946686
last_seq = 138
current_ts = 123.963722
current_received_ts = 123.963776
current_seq = 139
count = 133
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.963722
last_received_ts = 123.963776
last_seq = 139
current_ts = 123.980385
current_received_ts = 123.980232
current_seq = 140
count = 134
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 26us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.980385
last_received_ts = 123.980232
last_seq = 140
current_ts = 123.997063
current_received_ts = 123.996597
current_seq = 141
count = 135
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 123.997063
last_received_ts = 123.996597
last_seq = 141
current_ts = 124.013718
current_received_ts = 124.013924
current_seq = 142
count = 136
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.013718
last_received_ts = 124.013924
last_seq = 142
current_ts = 124.030388
current_received_ts = 124.030190
current_seq = 143
count = 137
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 26us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.030388
last_received_ts = 124.030190
last_seq = 143
current_ts = 124.047058
current_received_ts = 124.046593
current_seq = 144
count = 138
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.047058
last_received_ts = 124.046593
last_seq = 144
current_ts = 124.063721
current_received_ts = 124.063812
current_seq = 145
count = 139
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.063721
last_received_ts = 124.063812
last_seq = 145
current_ts = 124.080399
current_received_ts = 124.079895
current_seq = 146
count = 140
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.080399
last_received_ts = 124.079895
last_seq = 146
current_ts = 124.097061
current_received_ts = 124.096695
current_seq = 147
count = 141
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.097061
last_received_ts = 124.096695
last_seq = 147
current_ts = 124.113716
current_received_ts = 124.113518
current_seq = 148
count = 142
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.113716
last_received_ts = 124.113518
last_seq = 148
current_ts = 124.130394
current_received_ts = 124.130188
current_seq = 149
count = 143
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.130394
last_received_ts = 124.130188
last_seq = 149
current_ts = 124.147064
current_received_ts = 124.146599
current_seq = 150
count = 144
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.147064
last_received_ts = 124.146599
last_seq = 150
current_ts = 124.163719
current_received_ts = 124.164146
current_seq = 151
count = 145
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.163719
last_received_ts = 124.164146
last_seq = 151
current_ts = 124.180389
current_received_ts = 124.179863
current_seq = 152
count = 146
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.180389
last_received_ts = 124.179863
last_seq = 152
current_ts = 124.197067
current_received_ts = 124.196693
current_seq = 153
count = 147
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.197067
last_received_ts = 124.196693
last_seq = 153
current_ts = 124.213730
current_received_ts = 124.213478
current_seq = 154
count = 148
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.213730
last_received_ts = 124.213478
last_seq = 154
current_ts = 124.230392
current_received_ts = 124.230202
current_seq = 155
count = 149
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 26us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.230392
last_received_ts = 124.230202
last_seq = 155
current_ts = 124.247070
current_received_ts = 124.246574
current_seq = 156
count = 150
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.247070
last_received_ts = 124.246574
last_seq = 156
current_ts = 124.263733
current_received_ts = 124.263680
current_seq = 157
count = 151
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.263733
last_received_ts = 124.263680
last_seq = 157
current_ts = 124.280388
current_received_ts = 124.280258
current_seq = 158
count = 152
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 47us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.280388
last_received_ts = 124.280258
last_seq = 158
current_ts = 124.297066
current_received_ts = 124.296577
current_seq = 159
count = 153
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.297066
last_received_ts = 124.296577
last_seq = 159
current_ts = 124.313728
current_received_ts = 124.313721
current_seq = 160
count = 154
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.313728
last_received_ts = 124.313721
last_seq = 160
current_ts = 124.330391
current_received_ts = 124.330193
current_seq = 161
count = 155
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.330391
last_received_ts = 124.330193
last_seq = 161
current_ts = 124.347069
current_received_ts = 124.346603
current_seq = 162
count = 156
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 26us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.347069
last_received_ts = 124.346603
last_seq = 162
current_ts = 124.363739
current_received_ts = 124.363754
current_seq = 163
count = 157
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 26us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.363739
last_received_ts = 124.363754
last_seq = 163
current_ts = 124.380394
current_received_ts = 124.380257
current_seq = 164
count = 158
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.380394
last_received_ts = 124.380257
last_seq = 164
current_ts = 124.397064
current_received_ts = 124.397087
current_seq = 165
count = 159
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.397064
last_received_ts = 124.397087
last_seq = 165
current_ts = 124.413727
current_received_ts = 124.413460
current_seq = 166
count = 160
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.413727
last_received_ts = 124.413460
last_seq = 166
current_ts = 124.430405
current_received_ts = 124.430199
current_seq = 167
count = 161
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.430405
last_received_ts = 124.430199
last_seq = 167
current_ts = 124.447067
current_received_ts = 124.446579
current_seq = 168
count = 162
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.447067
last_received_ts = 124.446579
last_seq = 168
current_ts = 124.463730
current_received_ts = 124.463463
current_seq = 169
count = 163
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.463730
last_received_ts = 124.463463
last_seq = 169
current_ts = 124.480408
current_received_ts = 124.479904
current_seq = 170
count = 164
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.480408
last_received_ts = 124.479904
last_seq = 170
current_ts = 124.497070
current_received_ts = 124.496719
current_seq = 171
count = 165
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.497070
last_received_ts = 124.496719
last_seq = 171
current_ts = 124.513725
current_received_ts = 124.513458
current_seq = 172
count = 166
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.513725
last_received_ts = 124.513458
last_seq = 172
current_ts = 124.530396
current_received_ts = 124.530197
current_seq = 173
count = 167
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.530396
last_received_ts = 124.530197
last_seq = 173
current_ts = 124.547073
current_received_ts = 124.546593
current_seq = 174
count = 168
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.547073
last_received_ts = 124.546593
last_seq = 174
current_ts = 124.563728
current_received_ts = 124.563934
current_seq = 175
count = 169
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 64us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.563728
last_received_ts = 124.563934
last_seq = 175
current_ts = 124.580399
current_received_ts = 124.580620
current_seq = 176
count = 170
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 21us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.580399
last_received_ts = 124.580620
last_seq = 176
current_ts = 124.597076
current_received_ts = 124.596619
current_seq = 177
count = 171
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.597076
last_received_ts = 124.596619
last_seq = 177
current_ts = 124.613739
current_received_ts = 124.613457
current_seq = 178
count = 172
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.613739
last_received_ts = 124.613457
last_seq = 178
current_ts = 124.630402
current_received_ts = 124.630203
current_seq = 179
count = 173
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.630402
last_received_ts = 124.630203
last_seq = 179
current_ts = 124.647072
current_received_ts = 124.646584
current_seq = 180
count = 174
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.647072
last_received_ts = 124.646584
last_seq = 180
current_ts = 124.663742
current_received_ts = 124.663513
current_seq = 181
count = 175
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.663742
last_received_ts = 124.663513
last_seq = 181
current_ts = 124.680412
current_received_ts = 124.679909
current_seq = 182
count = 176
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.680412
last_received_ts = 124.679909
last_seq = 182
current_ts = 124.697075
current_received_ts = 124.696709
current_seq = 183
count = 177
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.697075
last_received_ts = 124.696709
last_seq = 183
current_ts = 124.713745
current_received_ts = 124.713478
current_seq = 184
count = 178
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.713745
last_received_ts = 124.713478
last_seq = 184
current_ts = 124.730408
current_received_ts = 124.730247
current_seq = 185
count = 179
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.730408
last_received_ts = 124.730247
last_seq = 185
current_ts = 124.747078
current_received_ts = 124.746643
current_seq = 186
count = 180
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.747078
last_received_ts = 124.746643
last_seq = 186
current_ts = 124.763748
current_received_ts = 124.763779
current_seq = 187
count = 181
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.763748
last_received_ts = 124.763779
last_seq = 187
current_ts = 124.780411
current_received_ts = 124.779938
current_seq = 188
count = 182
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 48us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.780411
last_received_ts = 124.779938
last_seq = 188
current_ts = 124.797081
current_received_ts = 124.797066
current_seq = 189
count = 183
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 21us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.797081
last_received_ts = 124.797066
last_seq = 189
current_ts = 124.813736
current_received_ts = 124.813499
current_seq = 190
count = 184
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.813736
last_received_ts = 124.813499
last_seq = 190
current_ts = 124.830406
current_received_ts = 124.830193
current_seq = 191
count = 185
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.830406
last_received_ts = 124.830193
last_seq = 191
current_ts = 124.847084
current_received_ts = 124.846603
current_seq = 192
count = 186
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.847084
last_received_ts = 124.846603
last_seq = 192
current_ts = 124.863739
current_received_ts = 124.863518
current_seq = 193
count = 187
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.863739
last_received_ts = 124.863518
last_seq = 193
current_ts = 124.880402
current_received_ts = 124.879898
current_seq = 194
count = 188
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.880402
last_received_ts = 124.879898
last_seq = 194
current_ts = 124.897072
current_received_ts = 124.896729
current_seq = 195
count = 189
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 21us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.897072
last_received_ts = 124.896729
last_seq = 195
current_ts = 124.913750
current_received_ts = 124.913513
current_seq = 196
count = 190
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 51us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.913750
last_received_ts = 124.913513
last_seq = 196
current_ts = 124.930412
current_received_ts = 124.930222
current_seq = 197
count = 191
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 25us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.930412
last_received_ts = 124.930222
last_seq = 197
current_ts = 124.947083
current_received_ts = 124.946739
current_seq = 198
count = 192
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.947083
last_received_ts = 124.946739
last_seq = 198
current_ts = 124.963745
current_received_ts = 124.963684
current_seq = 199
count = 193
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.963745
last_received_ts = 124.963684
last_seq = 199
current_ts = 124.980415
current_received_ts = 124.980202
current_seq = 200
count = 194
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.980415
last_received_ts = 124.980202
last_seq = 200
current_ts = 124.997086
current_received_ts = 124.996628
current_seq = 201
count = 195
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 124.997086
last_received_ts = 124.996628
last_seq = 201
current_ts = 125.013756
current_received_ts = 125.013298
current_seq = 202
count = 196
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 125.013756
last_received_ts = 125.013298
last_seq = 202
current_ts = 125.030411
current_received_ts = 125.030243
current_seq = 203
count = 197
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 125.030411
last_received_ts = 125.030243
last_seq = 203
current_ts = 125.047089
current_received_ts = 125.046654
current_seq = 204
count = 198
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 24us
(kms_flip:2294) DEBUG: name = flip
last_ts = 125.047089
last_received_ts = 125.046654
last_seq = 204
current_ts = 125.063744
current_received_ts = 125.063812
current_seq = 205
count = 199
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 22us
(kms_flip:2294) DEBUG: name = flip
last_ts = 125.063744
last_received_ts = 125.063812
last_seq = 205
current_ts = 125.080421
current_received_ts = 125.079933
current_seq = 206
count = 200
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 46us
(kms_flip:2294) DEBUG: name = flip
last_ts = 125.080421
last_received_ts = 125.079933
last_seq = 206
current_ts = 125.097084
current_received_ts = 125.096786
current_seq = 207
count = 201
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 23us
(kms_flip:2294) DEBUG: name = flip
last_ts = 125.097084
last_received_ts = 125.096786
last_seq = 207
current_ts = 125.113747
current_received_ts = 125.113495
current_seq = 208
count = 202
seq_step = 1
(kms_flip:2294) DEBUG: Vblank took 1137us
(kms_flip:2294) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2294) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2294) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2294) igt_core-INFO: Stack trace:
(kms_flip:2294) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2294) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:2294) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:2294) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:2294) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:2294) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2294) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2294) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A1: FAIL (3.810s)

Dmesg

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [121.517218] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: ebb0: 0x0, ebb4: 0x0,pll0: 0x0, pll1: 0x0, pll2: 0x0, pll3: 0x0, pll6: 0x0, pll8: 0x0, pll9: 0x0, pll10: 0x0, pcsdw12: 0x0

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

<7> [121.518053] i915 0000:00:02.0: [drm:intel_pipe_config_compare [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> [121.518496] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:164:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 36)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [121.527702] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:122:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 17, 17, 17, 34, 34, 34, 34, 34, 31, 0, 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [121.533424] 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> [121.533846] 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> [121.534227] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

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

<7> [121.535011] 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> [121.535401] 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> [121.535780] 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> [121.536268] 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> [121.536674] 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> [121.537178] 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> [121.537578] 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> [121.538013] 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> [121.538416] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pixel rate 148500, min cdclk 192000, min voltage level 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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