igt@kms_flip@flip-vs-expired-vblank@b-edp1 on shard-lnl@xe-pw-165754v1 Test details

Detail	Value
Duration	6.30 seconds
Hostname	shard-lnl-4
Igt-Version	IGT-Version: 2.4-g02b0e01dd (x86_64) (Linux: 7.1.0-rc1-lgci-xe-xe-pw-165754v1-debug+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 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:2184 __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 B-eDP1: FAIL (6.305s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:6550) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:6550) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:6550) DEBUG: name = flip last_ts = 273.491516 last_received_ts = 273.491028 last_seq = 179 current_ts = 273.508179 current_received_ts = 273.507690 current_seq = 180 count = 176 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 273.508179 last_received_ts = 273.507690 last_seq = 180 current_ts = 273.524841 current_received_ts = 273.524353 current_seq = 181 count = 177 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 273.524841 last_received_ts = 273.524353 last_seq = 181 current_ts = 273.541504 current_received_ts = 273.540985 current_seq = 182 count = 178 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 273.541504 last_received_ts = 273.540985 last_seq = 182 current_ts = 273.558167 current_received_ts = 273.557678 current_seq = 183 count = 179 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 63us (kms_flip:6550) DEBUG: name = flip last_ts = 273.558167 last_received_ts = 273.557678 last_seq = 183 current_ts = 273.574829 current_received_ts = 273.574341 current_seq = 184 count = 180 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 165us (kms_flip:6550) DEBUG: name = flip last_ts = 273.574829 last_received_ts = 273.574341 last_seq = 184 current_ts = 273.591492 current_received_ts = 273.590973 current_seq = 185 count = 181 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 88us (kms_flip:6550) DEBUG: name = flip last_ts = 273.591492 last_received_ts = 273.590973 last_seq = 185 current_ts = 273.608154 current_received_ts = 273.607666 current_seq = 186 count = 182 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 70us (kms_flip:6550) DEBUG: name = flip last_ts = 273.608154 last_received_ts = 273.607666 last_seq = 186 current_ts = 273.624847 current_received_ts = 273.624329 current_seq = 187 count = 183 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 128us (kms_flip:6550) DEBUG: name = flip last_ts = 273.624847 last_received_ts = 273.624329 last_seq = 187 current_ts = 273.641510 current_received_ts = 273.640991 current_seq = 188 count = 184 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 88us (kms_flip:6550) DEBUG: name = flip last_ts = 273.641510 last_received_ts = 273.640991 last_seq = 188 current_ts = 273.658173 current_received_ts = 273.657623 current_seq = 189 count = 185 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 273.658173 last_received_ts = 273.657623 last_seq = 189 current_ts = 273.674835 current_received_ts = 273.674347 current_seq = 190 count = 186 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 273.674835 last_received_ts = 273.674347 last_seq = 190 current_ts = 273.691498 current_received_ts = 273.690979 current_seq = 191 count = 187 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 88us (kms_flip:6550) DEBUG: name = flip last_ts = 273.691498 last_received_ts = 273.690979 last_seq = 191 current_ts = 273.708160 current_received_ts = 273.707642 current_seq = 192 count = 188 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 93us (kms_flip:6550) DEBUG: name = flip last_ts = 273.708160 last_received_ts = 273.707642 last_seq = 192 current_ts = 273.724823 current_received_ts = 273.724304 current_seq = 193 count = 189 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 151us (kms_flip:6550) DEBUG: name = flip last_ts = 273.724823 last_received_ts = 273.724304 last_seq = 193 current_ts = 273.741486 current_received_ts = 273.740997 current_seq = 194 count = 190 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 91us (kms_flip:6550) DEBUG: name = flip last_ts = 273.741486 last_received_ts = 273.740997 last_seq = 194 current_ts = 273.758148 current_received_ts = 273.757660 current_seq = 195 count = 191 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 95us (kms_flip:6550) DEBUG: name = flip last_ts = 273.758148 last_received_ts = 273.757660 last_seq = 195 current_ts = 273.774811 current_received_ts = 273.774292 current_seq = 196 count = 192 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 159us (kms_flip:6550) DEBUG: name = flip last_ts = 273.774811 last_received_ts = 273.774292 last_seq = 196 current_ts = 273.791473 current_received_ts = 273.790985 current_seq = 197 count = 193 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 97us (kms_flip:6550) DEBUG: name = flip last_ts = 273.791473 last_received_ts = 273.790985 last_seq = 197 current_ts = 273.808136 current_received_ts = 273.807648 current_seq = 198 count = 194 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 112us (kms_flip:6550) DEBUG: name = flip last_ts = 273.808136 last_received_ts = 273.807648 last_seq = 198 current_ts = 273.824799 current_received_ts = 273.824310 current_seq = 199 count = 195 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 152us (kms_flip:6550) DEBUG: name = flip last_ts = 273.824799 last_received_ts = 273.824310 last_seq = 199 current_ts = 273.841461 current_received_ts = 273.840942 current_seq = 200 count = 196 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 114us (kms_flip:6550) DEBUG: name = flip last_ts = 273.841461 last_received_ts = 273.840942 last_seq = 200 current_ts = 273.858124 current_received_ts = 273.857605 current_seq = 201 count = 197 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 273.858124 last_received_ts = 273.857605 last_seq = 201 current_ts = 273.874786 current_received_ts = 273.874268 current_seq = 202 count = 198 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 167us (kms_flip:6550) DEBUG: name = flip last_ts = 273.874786 last_received_ts = 273.874268 last_seq = 202 current_ts = 273.891479 current_received_ts = 273.890930 current_seq = 203 count = 199 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 137us (kms_flip:6550) DEBUG: name = flip last_ts = 273.891479 last_received_ts = 273.890930 last_seq = 203 current_ts = 273.908142 current_received_ts = 273.907623 current_seq = 204 count = 200 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 273.908142 last_received_ts = 273.907623 last_seq = 204 current_ts = 273.924805 current_received_ts = 273.924286 current_seq = 205 count = 201 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 152us (kms_flip:6550) DEBUG: name = flip last_ts = 273.924805 last_received_ts = 273.924286 last_seq = 205 current_ts = 273.941467 current_received_ts = 273.940948 current_seq = 206 count = 202 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 137us (kms_flip:6550) DEBUG: name = flip last_ts = 273.941467 last_received_ts = 273.940948 last_seq = 206 current_ts = 273.958130 current_received_ts = 273.957611 current_seq = 207 count = 203 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 273.958130 last_received_ts = 273.957611 last_seq = 207 current_ts = 273.974792 current_received_ts = 273.974274 current_seq = 208 count = 204 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 179us (kms_flip:6550) DEBUG: name = flip last_ts = 273.974792 last_received_ts = 273.974274 last_seq = 208 current_ts = 273.991455 current_received_ts = 273.990936 current_seq = 209 count = 205 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 138us (kms_flip:6550) DEBUG: name = flip last_ts = 273.991455 last_received_ts = 273.990936 last_seq = 209 current_ts = 274.008118 current_received_ts = 274.007599 current_seq = 210 count = 206 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.008118 last_received_ts = 274.007599 last_seq = 210 current_ts = 274.024780 current_received_ts = 274.024231 current_seq = 211 count = 207 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.024780 last_received_ts = 274.024231 last_seq = 211 current_ts = 274.041443 current_received_ts = 274.040924 current_seq = 212 count = 208 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 128us (kms_flip:6550) DEBUG: name = flip last_ts = 274.041443 last_received_ts = 274.040924 last_seq = 212 current_ts = 274.058105 current_received_ts = 274.057587 current_seq = 213 count = 209 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.058105 last_received_ts = 274.057587 last_seq = 213 current_ts = 274.074768 current_received_ts = 274.074219 current_seq = 214 count = 210 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 274.074768 last_received_ts = 274.074219 last_seq = 214 current_ts = 274.091431 current_received_ts = 274.090912 current_seq = 215 count = 211 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 126us (kms_flip:6550) DEBUG: name = flip last_ts = 274.091431 last_received_ts = 274.090912 last_seq = 215 current_ts = 274.108093 current_received_ts = 274.107544 current_seq = 216 count = 212 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 274.108093 last_received_ts = 274.107544 last_seq = 216 current_ts = 274.124756 current_received_ts = 274.124237 current_seq = 217 count = 213 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 100us (kms_flip:6550) DEBUG: name = flip last_ts = 274.124756 last_received_ts = 274.124237 last_seq = 217 current_ts = 274.141418 current_received_ts = 274.140900 current_seq = 218 count = 214 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 141us (kms_flip:6550) DEBUG: name = flip last_ts = 274.141418 last_received_ts = 274.140900 last_seq = 218 current_ts = 274.158081 current_received_ts = 274.157562 current_seq = 219 count = 215 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 88us (kms_flip:6550) DEBUG: name = flip last_ts = 274.158081 last_received_ts = 274.157562 last_seq = 219 current_ts = 274.174774 current_received_ts = 274.174255 current_seq = 220 count = 216 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.174774 last_received_ts = 274.174255 last_seq = 220 current_ts = 274.191406 current_received_ts = 274.190887 current_seq = 221 count = 217 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 150us (kms_flip:6550) DEBUG: name = flip last_ts = 274.191406 last_received_ts = 274.190887 last_seq = 221 current_ts = 274.208099 current_received_ts = 274.207550 current_seq = 222 count = 218 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.208099 last_received_ts = 274.207550 last_seq = 222 current_ts = 274.224731 current_received_ts = 274.224243 current_seq = 223 count = 219 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 93us (kms_flip:6550) DEBUG: name = flip last_ts = 274.224731 last_received_ts = 274.224243 last_seq = 223 current_ts = 274.241425 current_received_ts = 274.240906 current_seq = 224 count = 220 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 142us (kms_flip:6550) DEBUG: name = flip last_ts = 274.241425 last_received_ts = 274.240906 last_seq = 224 current_ts = 274.258087 current_received_ts = 274.257538 current_seq = 225 count = 221 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 274.258087 last_received_ts = 274.257538 last_seq = 225 current_ts = 274.274750 current_received_ts = 274.274231 current_seq = 226 count = 222 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 67us (kms_flip:6550) DEBUG: name = flip last_ts = 274.274750 last_received_ts = 274.274231 last_seq = 226 current_ts = 274.291412 current_received_ts = 274.290894 current_seq = 227 count = 223 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 149us (kms_flip:6550) DEBUG: name = flip last_ts = 274.291412 last_received_ts = 274.290894 last_seq = 227 current_ts = 274.308075 current_received_ts = 274.307526 current_seq = 228 count = 224 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 104us (kms_flip:6550) DEBUG: name = flip last_ts = 274.308075 last_received_ts = 274.307526 last_seq = 228 current_ts = 274.324738 current_received_ts = 274.324219 current_seq = 229 count = 225 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.324738 last_received_ts = 274.324219 last_seq = 229 current_ts = 274.341400 current_received_ts = 274.340881 current_seq = 230 count = 226 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 131us (kms_flip:6550) DEBUG: name = flip last_ts = 274.341400 last_received_ts = 274.340881 last_seq = 230 current_ts = 274.358063 current_received_ts = 274.357544 current_seq = 231 count = 227 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 100us (kms_flip:6550) DEBUG: name = flip last_ts = 274.358063 last_received_ts = 274.357544 last_seq = 231 current_ts = 274.374725 current_received_ts = 274.374207 current_seq = 232 count = 228 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 274.374725 last_received_ts = 274.374207 last_seq = 232 current_ts = 274.391388 current_received_ts = 274.390869 current_seq = 233 count = 229 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 141us (kms_flip:6550) DEBUG: name = flip last_ts = 274.391388 last_received_ts = 274.390869 last_seq = 233 current_ts = 274.408051 current_received_ts = 274.407532 current_seq = 234 count = 230 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 274.408051 last_received_ts = 274.407532 last_seq = 234 current_ts = 274.424713 current_received_ts = 274.424225 current_seq = 235 count = 231 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.424713 last_received_ts = 274.424225 last_seq = 235 current_ts = 274.441376 current_received_ts = 274.440857 current_seq = 236 count = 232 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 100us (kms_flip:6550) DEBUG: name = flip last_ts = 274.441376 last_received_ts = 274.440857 last_seq = 236 current_ts = 274.458069 current_received_ts = 274.457520 current_seq = 237 count = 233 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.458069 last_received_ts = 274.457520 last_seq = 237 current_ts = 274.474701 current_received_ts = 274.474182 current_seq = 238 count = 234 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 93us (kms_flip:6550) DEBUG: name = flip last_ts = 274.474701 last_received_ts = 274.474182 last_seq = 238 current_ts = 274.491364 current_received_ts = 274.490875 current_seq = 239 count = 235 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.491364 last_received_ts = 274.490875 last_seq = 239 current_ts = 274.508057 current_received_ts = 274.507416 current_seq = 240 count = 236 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.508057 last_received_ts = 274.507416 last_seq = 240 current_ts = 274.524719 current_received_ts = 274.524200 current_seq = 241 count = 237 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.524719 last_received_ts = 274.524200 last_seq = 241 current_ts = 274.541382 current_received_ts = 274.540863 current_seq = 242 count = 238 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.541382 last_received_ts = 274.540863 last_seq = 242 current_ts = 274.558044 current_received_ts = 274.557495 current_seq = 243 count = 239 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 100us (kms_flip:6550) DEBUG: name = flip last_ts = 274.558044 last_received_ts = 274.557495 last_seq = 243 current_ts = 274.574707 current_received_ts = 274.574188 current_seq = 244 count = 240 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 99us (kms_flip:6550) DEBUG: name = flip last_ts = 274.574707 last_received_ts = 274.574188 last_seq = 244 current_ts = 274.591370 current_received_ts = 274.590851 current_seq = 245 count = 241 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 274.591370 last_received_ts = 274.590851 last_seq = 245 current_ts = 274.608032 current_received_ts = 274.607513 current_seq = 246 count = 242 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.608032 last_received_ts = 274.607513 last_seq = 246 current_ts = 274.624695 current_received_ts = 274.624207 current_seq = 247 count = 243 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 274.624695 last_received_ts = 274.624207 last_seq = 247 current_ts = 274.641357 current_received_ts = 274.640839 current_seq = 248 count = 244 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.641357 last_received_ts = 274.640839 last_seq = 248 current_ts = 274.658020 current_received_ts = 274.657501 current_seq = 249 count = 245 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 274.658020 last_received_ts = 274.657501 last_seq = 249 current_ts = 274.674683 current_received_ts = 274.674194 current_seq = 250 count = 246 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 274.674683 last_received_ts = 274.674194 last_seq = 250 current_ts = 274.691345 current_received_ts = 274.690826 current_seq = 251 count = 247 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 274.691345 last_received_ts = 274.690826 last_seq = 251 current_ts = 274.708008 current_received_ts = 274.707489 current_seq = 252 count = 248 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.708008 last_received_ts = 274.707489 last_seq = 252 current_ts = 274.724670 current_received_ts = 274.724182 current_seq = 253 count = 249 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.724670 last_received_ts = 274.724182 last_seq = 253 current_ts = 274.741333 current_received_ts = 274.740814 current_seq = 254 count = 250 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.741333 last_received_ts = 274.740814 last_seq = 254 current_ts = 274.757996 current_received_ts = 274.757507 current_seq = 255 count = 251 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 93us (kms_flip:6550) DEBUG: name = flip last_ts = 274.757996 last_received_ts = 274.757507 last_seq = 255 current_ts = 274.774658 current_received_ts = 274.774170 current_seq = 256 count = 252 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 88us (kms_flip:6550) DEBUG: name = flip last_ts = 274.774658 last_received_ts = 274.774170 last_seq = 256 current_ts = 274.791351 current_received_ts = 274.790802 current_seq = 257 count = 253 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 92us (kms_flip:6550) DEBUG: name = flip last_ts = 274.791351 last_received_ts = 274.790802 last_seq = 257 current_ts = 274.808014 current_received_ts = 274.807465 current_seq = 258 count = 254 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.808014 last_received_ts = 274.807465 last_seq = 258 current_ts = 274.824677 current_received_ts = 274.824158 current_seq = 259 count = 255 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.824677 last_received_ts = 274.824158 last_seq = 259 current_ts = 274.841339 current_received_ts = 274.840790 current_seq = 260 count = 256 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 98us (kms_flip:6550) DEBUG: name = flip last_ts = 274.841339 last_received_ts = 274.840790 last_seq = 260 current_ts = 274.858002 current_received_ts = 274.857422 current_seq = 261 count = 257 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.858002 last_received_ts = 274.857422 last_seq = 261 current_ts = 274.874664 current_received_ts = 274.874146 current_seq = 262 count = 258 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.874664 last_received_ts = 274.874146 last_seq = 262 current_ts = 274.891327 current_received_ts = 274.890778 current_seq = 263 count = 259 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.891327 last_received_ts = 274.890778 last_seq = 263 current_ts = 274.907990 current_received_ts = 274.907440 current_seq = 264 count = 260 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 274.907990 last_received_ts = 274.907440 last_seq = 264 current_ts = 274.924652 current_received_ts = 274.924164 current_seq = 265 count = 261 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 274.924652 last_received_ts = 274.924164 last_seq = 265 current_ts = 274.941315 current_received_ts = 274.940796 current_seq = 266 count = 262 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.941315 last_received_ts = 274.940796 last_seq = 266 current_ts = 274.957977 current_received_ts = 274.957428 current_seq = 267 count = 263 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 93us (kms_flip:6550) DEBUG: name = flip last_ts = 274.957977 last_received_ts = 274.957428 last_seq = 267 current_ts = 274.974640 current_received_ts = 274.974121 current_seq = 268 count = 264 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.974640 last_received_ts = 274.974121 last_seq = 268 current_ts = 274.991302 current_received_ts = 274.990784 current_seq = 269 count = 265 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 274.991302 last_received_ts = 274.990784 last_seq = 269 current_ts = 275.007965 current_received_ts = 275.007446 current_seq = 270 count = 266 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 100us (kms_flip:6550) DEBUG: name = flip last_ts = 275.007965 last_received_ts = 275.007446 last_seq = 270 current_ts = 275.024628 current_received_ts = 275.024109 current_seq = 271 count = 267 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 96us (kms_flip:6550) DEBUG: name = flip last_ts = 275.024628 last_received_ts = 275.024109 last_seq = 271 current_ts = 275.041290 current_received_ts = 275.040771 current_seq = 272 count = 268 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 275.041290 last_received_ts = 275.040771 last_seq = 272 current_ts = 275.057953 current_received_ts = 275.057434 current_seq = 273 count = 269 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 275.057953 last_received_ts = 275.057434 last_seq = 273 current_ts = 275.074615 current_received_ts = 275.074127 current_seq = 274 count = 270 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 275.074615 last_received_ts = 275.074127 last_seq = 274 current_ts = 275.091278 current_received_ts = 275.090790 current_seq = 275 count = 271 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 275.091278 last_received_ts = 275.090790 last_seq = 275 current_ts = 275.107971 current_received_ts = 275.107391 current_seq = 276 count = 272 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 275.107971 last_received_ts = 275.107391 last_seq = 276 current_ts = 275.124634 current_received_ts = 275.124115 current_seq = 277 count = 273 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 275.124634 last_received_ts = 275.124115 last_seq = 277 current_ts = 275.141296 current_received_ts = 275.140747 current_seq = 278 count = 274 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 275.141296 last_received_ts = 275.140747 last_seq = 278 current_ts = 275.157959 current_received_ts = 275.157410 current_seq = 279 count = 275 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 275.157959 last_received_ts = 275.157410 last_seq = 279 current_ts = 275.174622 current_received_ts = 275.174103 current_seq = 280 count = 276 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 275.174622 last_received_ts = 275.174103 last_seq = 280 current_ts = 275.191284 current_received_ts = 275.190765 current_seq = 281 count = 277 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 275.191284 last_received_ts = 275.190765 last_seq = 281 current_ts = 275.207947 current_received_ts = 275.207397 current_seq = 282 count = 278 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 93us (kms_flip:6550) DEBUG: name = flip last_ts = 275.207947 last_received_ts = 275.207397 last_seq = 282 current_ts = 275.224609 current_received_ts = 275.224091 current_seq = 283 count = 279 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 275.224609 last_received_ts = 275.224091 last_seq = 283 current_ts = 275.241272 current_received_ts = 275.240753 current_seq = 284 count = 280 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 275.241272 last_received_ts = 275.240753 last_seq = 284 current_ts = 275.257935 current_received_ts = 275.257416 current_seq = 285 count = 281 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 88us (kms_flip:6550) DEBUG: name = flip last_ts = 275.257935 last_received_ts = 275.257416 last_seq = 285 current_ts = 275.274597 current_received_ts = 275.274078 current_seq = 286 count = 282 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 275.274597 last_received_ts = 275.274078 last_seq = 286 current_ts = 275.291260 current_received_ts = 275.290771 current_seq = 287 count = 283 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 275.291260 last_received_ts = 275.290771 last_seq = 287 current_ts = 275.307922 current_received_ts = 275.307404 current_seq = 288 count = 284 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 275.307922 last_received_ts = 275.307404 last_seq = 288 current_ts = 275.324585 current_received_ts = 275.324066 current_seq = 289 count = 285 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 275.324585 last_received_ts = 275.324066 last_seq = 289 current_ts = 275.341248 current_received_ts = 275.340759 current_seq = 290 count = 286 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 94us (kms_flip:6550) DEBUG: name = flip last_ts = 275.341248 last_received_ts = 275.340759 last_seq = 290 current_ts = 275.357910 current_received_ts = 275.357422 current_seq = 291 count = 287 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 275.357910 last_received_ts = 275.357422 last_seq = 291 current_ts = 275.374573 current_received_ts = 275.374084 current_seq = 292 count = 288 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 275.374573 last_received_ts = 275.374084 last_seq = 292 current_ts = 275.391235 current_received_ts = 275.390717 current_seq = 293 count = 289 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 104us (kms_flip:6550) DEBUG: name = flip last_ts = 275.391235 last_received_ts = 275.390717 last_seq = 293 current_ts = 275.407898 current_received_ts = 275.407410 current_seq = 294 count = 290 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 275.407898 last_received_ts = 275.407410 last_seq = 294 current_ts = 275.424591 current_received_ts = 275.424072 current_seq = 295 count = 291 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 275.424591 last_received_ts = 275.424072 last_seq = 295 current_ts = 275.441254 current_received_ts = 275.440765 current_seq = 296 count = 292 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 112us (kms_flip:6550) DEBUG: name = flip last_ts = 275.441254 last_received_ts = 275.440765 last_seq = 296 current_ts = 275.457916 current_received_ts = 275.457397 current_seq = 297 count = 293 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 100us (kms_flip:6550) DEBUG: name = flip last_ts = 275.457916 last_received_ts = 275.457397 last_seq = 297 current_ts = 275.474579 current_received_ts = 275.474091 current_seq = 298 count = 294 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 101us (kms_flip:6550) DEBUG: name = flip last_ts = 275.474579 last_received_ts = 275.474091 last_seq = 298 current_ts = 275.491241 current_received_ts = 275.490723 current_seq = 299 count = 295 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 89us (kms_flip:6550) DEBUG: name = flip last_ts = 275.491241 last_received_ts = 275.490723 last_seq = 299 current_ts = 275.507904 current_received_ts = 275.507385 current_seq = 300 count = 296 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 102us (kms_flip:6550) DEBUG: name = flip last_ts = 275.507904 last_received_ts = 275.507385 last_seq = 300 current_ts = 275.524567 current_received_ts = 275.524078 current_seq = 301 count = 297 seq_step = 1 (kms_flip:6550) DEBUG: Vblank took 1197us (kms_flip:6550) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:6550) CRITICAL: Failed assertion: end - start < 500 (kms_flip:6550) igt_core-INFO: Stack trace: (kms_flip:6550) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:6550) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:6550) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:6550) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() (kms_flip:6550) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:6550) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:6550) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:6550) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (6.305s)
Dmesg	<6> [284.699730] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [284.702204] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431] <7> [284.704027] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [284.713636] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [284.713898] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [284.714080] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [284.779876] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [284.780073] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [284.780360] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [284.780620] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [284.780838] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [284.781044] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [284.781248] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [284.781446] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [284.781651] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [284.781841] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [284.782024] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [284.782207] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [284.782389] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [284.782563] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [284.782791] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [284.782953] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [284.783112] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [284.783270] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [284.783422] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [284.783572] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [284.783741] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [284.783883] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [284.784018] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [284.784151] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [284.784284] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [284.784413] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [284.784540] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [284.784683] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [284.784807] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [284.784927] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [284.785044] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [284.785162] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [284.785279] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [284.785406] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [284.785521] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [284.785647] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [284.785757] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [284.785865] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [284.785968] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [284.786073] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [284.786176] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [284.786329] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [284.786421] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [284.786538] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [284.786649] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [284.786767] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [284.786877] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [284.786981] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [284.787132] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [284.787257] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [284.787372] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [284.787482] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [284.787576] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [284.787702] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [284.787810] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [284.787963] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [284.788073] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [284.788302] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [284.788396] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [284.989808] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [284.990494] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [284.996018] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [284.996483] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [284.997000] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [285.048071] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [285.048512] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [285.049000] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [285.049450] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [285.050107] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [285.049982] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [285.050685] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [285.051308] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [285.051806] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [285.052296] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [285.052843] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [285.053309] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [285.053743] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [285.054175] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [285.054653] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [285.055132] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [285.055561] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [285.056020] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [285.056431] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [285.056874] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [285.057264] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [285.057835] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [285.058239] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [285.058593] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [285.059136] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [285.059700] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [285.060273] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [285.060750] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [285.061217] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [285.061561] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [285.062657] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [285.063086] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [285.063401] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [285.063466] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [285.063675] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [285.064077] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [285.064416] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [285.064801] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [285.065129] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [285.065431] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [285.065758] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [285.066042] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [285.066329] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [285.066591] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [285.066829] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [285.067095] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [285.067328] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [285.067536] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [285.067757] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [285.067945] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [285.068128] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [285.068310] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [285.068482] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [285.068674] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [285.068876] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [285.069049] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [285.069205] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [285.069355] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [285.069504] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [285.069680] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [285.069827] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [285.069962] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [285.070092] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [285.070217] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [285.070359] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [285.070502] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [285.070641] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [285.070781] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [285.070922] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [285.071051] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [285.071166] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [285.071289] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [285.071401] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [285.071509] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dpll_hw_state <7> [285.071629] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] expected: <7> [285.071747] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 0, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [285.071857] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: <7> [285.071953] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0x0000, tx[1] = 0x0000, tx[2] = 0x0000 <7> [285.072049] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0000, cmn[1] = 0x0000, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [285.072141] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[0] = 0x0000 <7> [285.072231] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[1] = 0x0000 <7> [285.072321] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[2] = 0x0000 <7> [285.072408] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[3] = 0x0000 <7> [285.072492] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[4] = 0x0000 <7> [285.072585] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[5] = 0x0000 <7> [285.072683] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[6] = 0x0000 <7> [285.072778] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[7] = 0x0000 <7> [285.072871] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[8] = 0x0000 <7> [285.072954] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[9] = 0x0000 <7> [285.073031] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000 <7> [285.073108] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00 <7> [285.073184] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] found: <7> [285.073260] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [285.073338] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_hw_state: fracen: no, <7> [285.073422] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] multiplier: 225, tx_clk_div: 1. <7> [285.073507] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_rawhw_state: <7> [285.073595] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] tx: 0x10, cmn: 0x21 <7> [285.073693] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [285.073795] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [285.073891] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [285.073986] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [285.074080] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [285.074153] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [285.074225] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [285.074296] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [285.074378] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [285.074472] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [285.074611] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [285.074700] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [285.074817] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [285.074901] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:264:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [285.074966] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [285.075022] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [285.075077] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [285.075130] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [285.075203] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [285.075317] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [285.075415] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [285.075503] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [285.075607] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [285.075714] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [285.075818] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [285.075940] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [285.076034] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [285.076122] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [285.076230] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [285.076320] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [285.076421] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [285.076516] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [285.076605] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [285.076708] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [285.076810] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [285.076904] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [285.076982] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [285.077060] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [285.077138] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [285.077228] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [285.077317] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [285.077400] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [285.077478] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [285.077558] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [285.077719] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [285.077825] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [285.077914] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [285.077996] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [285.078072] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [285.078151] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [285.078244] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [285.078333] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [285.078413] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [285.078491] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [285.078573] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [285.078691] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [285.078791] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [285.078888] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [285.078976] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [285.079076] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [285.079171] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0 <7> [285.079251] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [285.079333] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [285.079416] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [285.079497] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [285.079585] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [285.079668] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [285.079750] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [285.079846] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [285.079942] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [285.080026] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [285.080102] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [285.080182] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [285.080274] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [285.080369] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [285.080464] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [285.080542] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [285.080647] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [285.080658] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [285.080746] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [285.080825] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [285.080844] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [285.080941] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [285.080953] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [285.081038] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [285.081106] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [285.081129] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [285.081225] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [285.081334] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [285.081441] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [285.081521] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [285.081603] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [285.081706] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [285.081817] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:431] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [285.081923] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [285.082010] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [285.082093] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [285.082178] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [285.082274] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [285.082368] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [285.082460] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [285.082922] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [285.083036] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [285.083282] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [285.083422] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [285.083549] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [285.083742] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [285.083865] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [285.083987] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [285.084099] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [285.084197] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [285.084271] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [285.084347] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [285.084419] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [285.084491] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [285.084560] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [285.084655] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [285.084739] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [285.084830] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [285.084912] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [285.084981] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [285.085044] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [285.085110] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [285.085153] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [285.085215] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [285.085274] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [285.085400] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [285.085389] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [285.085475] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [285.085597] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [285.085516] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [285.086621] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [285.086752] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [285.088787] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [285.088900] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (460 ms remaining) <7> [285.557903] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [285.599146] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [285.599533] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [285.599954] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [285.635956] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [285.636380] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [285.636762] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [285.637280] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [285.805746] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [285.806265] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [285.806723] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [285.808956] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [285.810517] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [285.811393] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [285.812632] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [285.814018] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [285.815182] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [285.815560] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [285.817130] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [285.817509] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [285.818361] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [285.818936] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [285.819333] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [285.819839] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [285.836009] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [285.837976] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [285.838459] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <7> [288.341728] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off <7> [288.342235] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [290.838684] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [290.839449] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [290.840089] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [291.005641] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

6.30 seconds

Hostname

shard-lnl-4

Igt-Version

IGT-Version: 2.4-g02b0e01dd (x86_64) (Linux: 7.1.0-rc1-lgci-xe-xe-pw-165754v1-debug+ x86_64)

Out

Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
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:2184 __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 B-eDP1: FAIL (6.305s)

Err

Starting dynamic subtest: B-eDP1
(kms_flip:6550) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:6550) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.491516
last_received_ts = 273.491028
last_seq = 179
current_ts = 273.508179
current_received_ts = 273.507690
current_seq = 180
count = 176
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.508179
last_received_ts = 273.507690
last_seq = 180
current_ts = 273.524841
current_received_ts = 273.524353
current_seq = 181
count = 177
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.524841
last_received_ts = 273.524353
last_seq = 181
current_ts = 273.541504
current_received_ts = 273.540985
current_seq = 182
count = 178
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.541504
last_received_ts = 273.540985
last_seq = 182
current_ts = 273.558167
current_received_ts = 273.557678
current_seq = 183
count = 179
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 63us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.558167
last_received_ts = 273.557678
last_seq = 183
current_ts = 273.574829
current_received_ts = 273.574341
current_seq = 184
count = 180
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 165us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.574829
last_received_ts = 273.574341
last_seq = 184
current_ts = 273.591492
current_received_ts = 273.590973
current_seq = 185
count = 181
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 88us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.591492
last_received_ts = 273.590973
last_seq = 185
current_ts = 273.608154
current_received_ts = 273.607666
current_seq = 186
count = 182
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 70us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.608154
last_received_ts = 273.607666
last_seq = 186
current_ts = 273.624847
current_received_ts = 273.624329
current_seq = 187
count = 183
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 128us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.624847
last_received_ts = 273.624329
last_seq = 187
current_ts = 273.641510
current_received_ts = 273.640991
current_seq = 188
count = 184
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 88us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.641510
last_received_ts = 273.640991
last_seq = 188
current_ts = 273.658173
current_received_ts = 273.657623
current_seq = 189
count = 185
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.658173
last_received_ts = 273.657623
last_seq = 189
current_ts = 273.674835
current_received_ts = 273.674347
current_seq = 190
count = 186
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.674835
last_received_ts = 273.674347
last_seq = 190
current_ts = 273.691498
current_received_ts = 273.690979
current_seq = 191
count = 187
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 88us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.691498
last_received_ts = 273.690979
last_seq = 191
current_ts = 273.708160
current_received_ts = 273.707642
current_seq = 192
count = 188
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 93us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.708160
last_received_ts = 273.707642
last_seq = 192
current_ts = 273.724823
current_received_ts = 273.724304
current_seq = 193
count = 189
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 151us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.724823
last_received_ts = 273.724304
last_seq = 193
current_ts = 273.741486
current_received_ts = 273.740997
current_seq = 194
count = 190
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 91us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.741486
last_received_ts = 273.740997
last_seq = 194
current_ts = 273.758148
current_received_ts = 273.757660
current_seq = 195
count = 191
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 95us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.758148
last_received_ts = 273.757660
last_seq = 195
current_ts = 273.774811
current_received_ts = 273.774292
current_seq = 196
count = 192
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 159us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.774811
last_received_ts = 273.774292
last_seq = 196
current_ts = 273.791473
current_received_ts = 273.790985
current_seq = 197
count = 193
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 97us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.791473
last_received_ts = 273.790985
last_seq = 197
current_ts = 273.808136
current_received_ts = 273.807648
current_seq = 198
count = 194
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 112us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.808136
last_received_ts = 273.807648
last_seq = 198
current_ts = 273.824799
current_received_ts = 273.824310
current_seq = 199
count = 195
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 152us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.824799
last_received_ts = 273.824310
last_seq = 199
current_ts = 273.841461
current_received_ts = 273.840942
current_seq = 200
count = 196
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 114us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.841461
last_received_ts = 273.840942
last_seq = 200
current_ts = 273.858124
current_received_ts = 273.857605
current_seq = 201
count = 197
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.858124
last_received_ts = 273.857605
last_seq = 201
current_ts = 273.874786
current_received_ts = 273.874268
current_seq = 202
count = 198
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 167us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.874786
last_received_ts = 273.874268
last_seq = 202
current_ts = 273.891479
current_received_ts = 273.890930
current_seq = 203
count = 199
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 137us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.891479
last_received_ts = 273.890930
last_seq = 203
current_ts = 273.908142
current_received_ts = 273.907623
current_seq = 204
count = 200
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.908142
last_received_ts = 273.907623
last_seq = 204
current_ts = 273.924805
current_received_ts = 273.924286
current_seq = 205
count = 201
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 152us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.924805
last_received_ts = 273.924286
last_seq = 205
current_ts = 273.941467
current_received_ts = 273.940948
current_seq = 206
count = 202
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 137us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.941467
last_received_ts = 273.940948
last_seq = 206
current_ts = 273.958130
current_received_ts = 273.957611
current_seq = 207
count = 203
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.958130
last_received_ts = 273.957611
last_seq = 207
current_ts = 273.974792
current_received_ts = 273.974274
current_seq = 208
count = 204
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 179us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.974792
last_received_ts = 273.974274
last_seq = 208
current_ts = 273.991455
current_received_ts = 273.990936
current_seq = 209
count = 205
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 138us
(kms_flip:6550) DEBUG: name = flip
last_ts = 273.991455
last_received_ts = 273.990936
last_seq = 209
current_ts = 274.008118
current_received_ts = 274.007599
current_seq = 210
count = 206
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.008118
last_received_ts = 274.007599
last_seq = 210
current_ts = 274.024780
current_received_ts = 274.024231
current_seq = 211
count = 207
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.024780
last_received_ts = 274.024231
last_seq = 211
current_ts = 274.041443
current_received_ts = 274.040924
current_seq = 212
count = 208
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 128us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.041443
last_received_ts = 274.040924
last_seq = 212
current_ts = 274.058105
current_received_ts = 274.057587
current_seq = 213
count = 209
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.058105
last_received_ts = 274.057587
last_seq = 213
current_ts = 274.074768
current_received_ts = 274.074219
current_seq = 214
count = 210
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.074768
last_received_ts = 274.074219
last_seq = 214
current_ts = 274.091431
current_received_ts = 274.090912
current_seq = 215
count = 211
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 126us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.091431
last_received_ts = 274.090912
last_seq = 215
current_ts = 274.108093
current_received_ts = 274.107544
current_seq = 216
count = 212
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.108093
last_received_ts = 274.107544
last_seq = 216
current_ts = 274.124756
current_received_ts = 274.124237
current_seq = 217
count = 213
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 100us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.124756
last_received_ts = 274.124237
last_seq = 217
current_ts = 274.141418
current_received_ts = 274.140900
current_seq = 218
count = 214
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 141us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.141418
last_received_ts = 274.140900
last_seq = 218
current_ts = 274.158081
current_received_ts = 274.157562
current_seq = 219
count = 215
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 88us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.158081
last_received_ts = 274.157562
last_seq = 219
current_ts = 274.174774
current_received_ts = 274.174255
current_seq = 220
count = 216
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.174774
last_received_ts = 274.174255
last_seq = 220
current_ts = 274.191406
current_received_ts = 274.190887
current_seq = 221
count = 217
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 150us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.191406
last_received_ts = 274.190887
last_seq = 221
current_ts = 274.208099
current_received_ts = 274.207550
current_seq = 222
count = 218
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.208099
last_received_ts = 274.207550
last_seq = 222
current_ts = 274.224731
current_received_ts = 274.224243
current_seq = 223
count = 219
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 93us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.224731
last_received_ts = 274.224243
last_seq = 223
current_ts = 274.241425
current_received_ts = 274.240906
current_seq = 224
count = 220
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 142us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.241425
last_received_ts = 274.240906
last_seq = 224
current_ts = 274.258087
current_received_ts = 274.257538
current_seq = 225
count = 221
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.258087
last_received_ts = 274.257538
last_seq = 225
current_ts = 274.274750
current_received_ts = 274.274231
current_seq = 226
count = 222
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 67us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.274750
last_received_ts = 274.274231
last_seq = 226
current_ts = 274.291412
current_received_ts = 274.290894
current_seq = 227
count = 223
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 149us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.291412
last_received_ts = 274.290894
last_seq = 227
current_ts = 274.308075
current_received_ts = 274.307526
current_seq = 228
count = 224
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 104us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.308075
last_received_ts = 274.307526
last_seq = 228
current_ts = 274.324738
current_received_ts = 274.324219
current_seq = 229
count = 225
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.324738
last_received_ts = 274.324219
last_seq = 229
current_ts = 274.341400
current_received_ts = 274.340881
current_seq = 230
count = 226
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 131us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.341400
last_received_ts = 274.340881
last_seq = 230
current_ts = 274.358063
current_received_ts = 274.357544
current_seq = 231
count = 227
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 100us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.358063
last_received_ts = 274.357544
last_seq = 231
current_ts = 274.374725
current_received_ts = 274.374207
current_seq = 232
count = 228
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.374725
last_received_ts = 274.374207
last_seq = 232
current_ts = 274.391388
current_received_ts = 274.390869
current_seq = 233
count = 229
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 141us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.391388
last_received_ts = 274.390869
last_seq = 233
current_ts = 274.408051
current_received_ts = 274.407532
current_seq = 234
count = 230
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.408051
last_received_ts = 274.407532
last_seq = 234
current_ts = 274.424713
current_received_ts = 274.424225
current_seq = 235
count = 231
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.424713
last_received_ts = 274.424225
last_seq = 235
current_ts = 274.441376
current_received_ts = 274.440857
current_seq = 236
count = 232
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 100us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.441376
last_received_ts = 274.440857
last_seq = 236
current_ts = 274.458069
current_received_ts = 274.457520
current_seq = 237
count = 233
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.458069
last_received_ts = 274.457520
last_seq = 237
current_ts = 274.474701
current_received_ts = 274.474182
current_seq = 238
count = 234
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 93us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.474701
last_received_ts = 274.474182
last_seq = 238
current_ts = 274.491364
current_received_ts = 274.490875
current_seq = 239
count = 235
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.491364
last_received_ts = 274.490875
last_seq = 239
current_ts = 274.508057
current_received_ts = 274.507416
current_seq = 240
count = 236
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.508057
last_received_ts = 274.507416
last_seq = 240
current_ts = 274.524719
current_received_ts = 274.524200
current_seq = 241
count = 237
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.524719
last_received_ts = 274.524200
last_seq = 241
current_ts = 274.541382
current_received_ts = 274.540863
current_seq = 242
count = 238
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.541382
last_received_ts = 274.540863
last_seq = 242
current_ts = 274.558044
current_received_ts = 274.557495
current_seq = 243
count = 239
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 100us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.558044
last_received_ts = 274.557495
last_seq = 243
current_ts = 274.574707
current_received_ts = 274.574188
current_seq = 244
count = 240
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 99us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.574707
last_received_ts = 274.574188
last_seq = 244
current_ts = 274.591370
current_received_ts = 274.590851
current_seq = 245
count = 241
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.591370
last_received_ts = 274.590851
last_seq = 245
current_ts = 274.608032
current_received_ts = 274.607513
current_seq = 246
count = 242
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.608032
last_received_ts = 274.607513
last_seq = 246
current_ts = 274.624695
current_received_ts = 274.624207
current_seq = 247
count = 243
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.624695
last_received_ts = 274.624207
last_seq = 247
current_ts = 274.641357
current_received_ts = 274.640839
current_seq = 248
count = 244
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.641357
last_received_ts = 274.640839
last_seq = 248
current_ts = 274.658020
current_received_ts = 274.657501
current_seq = 249
count = 245
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.658020
last_received_ts = 274.657501
last_seq = 249
current_ts = 274.674683
current_received_ts = 274.674194
current_seq = 250
count = 246
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.674683
last_received_ts = 274.674194
last_seq = 250
current_ts = 274.691345
current_received_ts = 274.690826
current_seq = 251
count = 247
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.691345
last_received_ts = 274.690826
last_seq = 251
current_ts = 274.708008
current_received_ts = 274.707489
current_seq = 252
count = 248
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.708008
last_received_ts = 274.707489
last_seq = 252
current_ts = 274.724670
current_received_ts = 274.724182
current_seq = 253
count = 249
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.724670
last_received_ts = 274.724182
last_seq = 253
current_ts = 274.741333
current_received_ts = 274.740814
current_seq = 254
count = 250
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.741333
last_received_ts = 274.740814
last_seq = 254
current_ts = 274.757996
current_received_ts = 274.757507
current_seq = 255
count = 251
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 93us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.757996
last_received_ts = 274.757507
last_seq = 255
current_ts = 274.774658
current_received_ts = 274.774170
current_seq = 256
count = 252
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 88us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.774658
last_received_ts = 274.774170
last_seq = 256
current_ts = 274.791351
current_received_ts = 274.790802
current_seq = 257
count = 253
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 92us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.791351
last_received_ts = 274.790802
last_seq = 257
current_ts = 274.808014
current_received_ts = 274.807465
current_seq = 258
count = 254
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.808014
last_received_ts = 274.807465
last_seq = 258
current_ts = 274.824677
current_received_ts = 274.824158
current_seq = 259
count = 255
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.824677
last_received_ts = 274.824158
last_seq = 259
current_ts = 274.841339
current_received_ts = 274.840790
current_seq = 260
count = 256
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 98us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.841339
last_received_ts = 274.840790
last_seq = 260
current_ts = 274.858002
current_received_ts = 274.857422
current_seq = 261
count = 257
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.858002
last_received_ts = 274.857422
last_seq = 261
current_ts = 274.874664
current_received_ts = 274.874146
current_seq = 262
count = 258
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.874664
last_received_ts = 274.874146
last_seq = 262
current_ts = 274.891327
current_received_ts = 274.890778
current_seq = 263
count = 259
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.891327
last_received_ts = 274.890778
last_seq = 263
current_ts = 274.907990
current_received_ts = 274.907440
current_seq = 264
count = 260
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.907990
last_received_ts = 274.907440
last_seq = 264
current_ts = 274.924652
current_received_ts = 274.924164
current_seq = 265
count = 261
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.924652
last_received_ts = 274.924164
last_seq = 265
current_ts = 274.941315
current_received_ts = 274.940796
current_seq = 266
count = 262
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.941315
last_received_ts = 274.940796
last_seq = 266
current_ts = 274.957977
current_received_ts = 274.957428
current_seq = 267
count = 263
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 93us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.957977
last_received_ts = 274.957428
last_seq = 267
current_ts = 274.974640
current_received_ts = 274.974121
current_seq = 268
count = 264
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.974640
last_received_ts = 274.974121
last_seq = 268
current_ts = 274.991302
current_received_ts = 274.990784
current_seq = 269
count = 265
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 274.991302
last_received_ts = 274.990784
last_seq = 269
current_ts = 275.007965
current_received_ts = 275.007446
current_seq = 270
count = 266
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 100us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.007965
last_received_ts = 275.007446
last_seq = 270
current_ts = 275.024628
current_received_ts = 275.024109
current_seq = 271
count = 267
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 96us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.024628
last_received_ts = 275.024109
last_seq = 271
current_ts = 275.041290
current_received_ts = 275.040771
current_seq = 272
count = 268
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.041290
last_received_ts = 275.040771
last_seq = 272
current_ts = 275.057953
current_received_ts = 275.057434
current_seq = 273
count = 269
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.057953
last_received_ts = 275.057434
last_seq = 273
current_ts = 275.074615
current_received_ts = 275.074127
current_seq = 274
count = 270
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.074615
last_received_ts = 275.074127
last_seq = 274
current_ts = 275.091278
current_received_ts = 275.090790
current_seq = 275
count = 271
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.091278
last_received_ts = 275.090790
last_seq = 275
current_ts = 275.107971
current_received_ts = 275.107391
current_seq = 276
count = 272
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.107971
last_received_ts = 275.107391
last_seq = 276
current_ts = 275.124634
current_received_ts = 275.124115
current_seq = 277
count = 273
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.124634
last_received_ts = 275.124115
last_seq = 277
current_ts = 275.141296
current_received_ts = 275.140747
current_seq = 278
count = 274
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.141296
last_received_ts = 275.140747
last_seq = 278
current_ts = 275.157959
current_received_ts = 275.157410
current_seq = 279
count = 275
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.157959
last_received_ts = 275.157410
last_seq = 279
current_ts = 275.174622
current_received_ts = 275.174103
current_seq = 280
count = 276
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.174622
last_received_ts = 275.174103
last_seq = 280
current_ts = 275.191284
current_received_ts = 275.190765
current_seq = 281
count = 277
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.191284
last_received_ts = 275.190765
last_seq = 281
current_ts = 275.207947
current_received_ts = 275.207397
current_seq = 282
count = 278
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 93us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.207947
last_received_ts = 275.207397
last_seq = 282
current_ts = 275.224609
current_received_ts = 275.224091
current_seq = 283
count = 279
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.224609
last_received_ts = 275.224091
last_seq = 283
current_ts = 275.241272
current_received_ts = 275.240753
current_seq = 284
count = 280
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.241272
last_received_ts = 275.240753
last_seq = 284
current_ts = 275.257935
current_received_ts = 275.257416
current_seq = 285
count = 281
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 88us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.257935
last_received_ts = 275.257416
last_seq = 285
current_ts = 275.274597
current_received_ts = 275.274078
current_seq = 286
count = 282
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.274597
last_received_ts = 275.274078
last_seq = 286
current_ts = 275.291260
current_received_ts = 275.290771
current_seq = 287
count = 283
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.291260
last_received_ts = 275.290771
last_seq = 287
current_ts = 275.307922
current_received_ts = 275.307404
current_seq = 288
count = 284
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.307922
last_received_ts = 275.307404
last_seq = 288
current_ts = 275.324585
current_received_ts = 275.324066
current_seq = 289
count = 285
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.324585
last_received_ts = 275.324066
last_seq = 289
current_ts = 275.341248
current_received_ts = 275.340759
current_seq = 290
count = 286
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 94us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.341248
last_received_ts = 275.340759
last_seq = 290
current_ts = 275.357910
current_received_ts = 275.357422
current_seq = 291
count = 287
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.357910
last_received_ts = 275.357422
last_seq = 291
current_ts = 275.374573
current_received_ts = 275.374084
current_seq = 292
count = 288
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.374573
last_received_ts = 275.374084
last_seq = 292
current_ts = 275.391235
current_received_ts = 275.390717
current_seq = 293
count = 289
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 104us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.391235
last_received_ts = 275.390717
last_seq = 293
current_ts = 275.407898
current_received_ts = 275.407410
current_seq = 294
count = 290
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.407898
last_received_ts = 275.407410
last_seq = 294
current_ts = 275.424591
current_received_ts = 275.424072
current_seq = 295
count = 291
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.424591
last_received_ts = 275.424072
last_seq = 295
current_ts = 275.441254
current_received_ts = 275.440765
current_seq = 296
count = 292
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 112us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.441254
last_received_ts = 275.440765
last_seq = 296
current_ts = 275.457916
current_received_ts = 275.457397
current_seq = 297
count = 293
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 100us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.457916
last_received_ts = 275.457397
last_seq = 297
current_ts = 275.474579
current_received_ts = 275.474091
current_seq = 298
count = 294
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 101us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.474579
last_received_ts = 275.474091
last_seq = 298
current_ts = 275.491241
current_received_ts = 275.490723
current_seq = 299
count = 295
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 89us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.491241
last_received_ts = 275.490723
last_seq = 299
current_ts = 275.507904
current_received_ts = 275.507385
current_seq = 300
count = 296
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 102us
(kms_flip:6550) DEBUG: name = flip
last_ts = 275.507904
last_received_ts = 275.507385
last_seq = 300
current_ts = 275.524567
current_received_ts = 275.524078
current_seq = 301
count = 297
seq_step = 1
(kms_flip:6550) DEBUG: Vblank took 1197us
(kms_flip:6550) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:6550) CRITICAL: Failed assertion: end - start < 500
(kms_flip:6550) igt_core-INFO: Stack trace:
(kms_flip:6550) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:6550) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:6550) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:6550) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
(kms_flip:6550) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:6550) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:6550) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:6550) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (6.305s)

Dmesg

<6> [284.699730] [IGT] kms_flip: starting dynamic subtest B-eDP1

<7> [284.702204] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431]

<7> [284.704027] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432]

<7> [284.713636] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

<7> [284.713898] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6

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

<7> [284.779876] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

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

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

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

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

<7> [284.781044] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0)

<7> [284.781248] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)

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

<7> [284.781651] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0)

<7> [284.781841] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0)

<7> [284.782024] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0)

<7> [284.782207] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0)

<7> [284.782389] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0)

<7> [284.782563] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0)

<7> [284.782791] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0)

<7> [284.782953] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0)

<7> [284.783112] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0)

<7> [284.783270] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0)

<7> [284.783422] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0)

<7> [284.783572] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0)

<7> [284.783741] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0)

<7> [284.783883] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0)

<7> [284.784018] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0)

<7> [284.784151] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0)

<7> [284.784284] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0)

<7> [284.784413] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0)

<7> [284.784540] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0)

<7> [284.784683] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0)

<7> [284.784807] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0)

<7> [284.784927] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0)

<7> [284.785044] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0)

<7> [284.785162] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0)

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

<7> [284.785406] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)

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

<7> [284.785647] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0)

<7> [284.785757] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0)

<7> [284.785865] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0)

<7> [284.785968] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0)

<7> [284.786073] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

<7> [284.786176] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0

<7> [284.786329] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no

<7> [284.786421] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0

<7> [284.786538] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0

<7> [284.786649] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz

<7> [284.786767] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing

<7> [284.786877] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz

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

<7> [284.787132] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset]

<7> [284.787257] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no

<7> [284.787372] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no

<7> [284.787482] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no

<7> [284.787576] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no

<7> [284.787702] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no

<7> [284.787810] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no

<7> [284.787963] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off

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

<7> [284.788302] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM

<7> [284.788396] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]]

<7> [284.989808] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0

<7> [284.990494] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A

<7> [284.996018] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off

<7> [284.996483] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time

<7> [284.997000] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060

<7> [285.048071] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [285.048512] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A]

<7> [285.049000] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000

<7> [285.049450] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short

<7> [285.050107] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0

<7> [285.049982] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A]

<7> [285.050685] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A

<7> [285.051308] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A]

<7> [285.051806] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1]

<7> [285.052296] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A]

<7> [285.052843] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B]

<7> [285.053309] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C]

<7> [285.053743] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2]

<7> [285.054175] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A]

<7> [285.054653] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B]

<7> [285.055132] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C]

<7> [285.055561] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3]

<7> [285.056020] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A]

<7> [285.056431] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B]

<7> [285.056874] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C]

<7> [285.057264] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1]

<7> [285.057835] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [285.058239] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: *)

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

<7> [285.059136] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A

<7> [285.059700] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000)

<7> [285.060273] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A]

<7> [285.060750] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

<7> [285.061217] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [285.061561] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384

<7> [285.062657] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B]

<7> [285.063086] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C]

<7> [285.063401] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B]

<7> [285.063466] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1]

<7> [285.063675] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)

<7> [285.064077] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000

<7> [285.064416] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000

<7> [285.064801] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0

<7> [285.065129] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B]

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

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

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

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

<7> [285.066591] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288)

<7> [285.066829] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)

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

<7> [285.067328] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)

<7> [285.067536] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)

<7> [285.067757] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)

<7> [285.067945] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)

<7> [285.068128] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)

<7> [285.068310] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)

<7> [285.068482] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)

<7> [285.068674] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800)

<7> [285.068876] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)

<7> [285.069049] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)

<7> [285.069205] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906)

<7> [285.069355] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906)

<7> [285.069504] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)

<7> [285.069680] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)

<7> [285.069827] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)

<7> [285.069962] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)

<7> [285.070092] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)

<7> [285.070217] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)

<7> [285.070359] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)

<7> [285.070502] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800)

<7> [285.070641] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)

<7> [285.070781] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)

<7> [285.070922] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906)

<7> [285.071051] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906)

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

<7> [285.071289] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)

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

<7> [285.071509] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dpll_hw_state

<7> [285.071629] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] expected:

<7> [285.071747] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 0, ssc_enabled: no, use_c10: no, tbt_mode: no

<7> [285.071857] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state:

<7> [285.071953] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0x0000, tx[1] = 0x0000, tx[2] = 0x0000

<7> [285.072049] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0000, cmn[1] = 0x0000, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [285.072141] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[0] = 0x0000

<7> [285.072231] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[1] = 0x0000

<7> [285.072321] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[2] = 0x0000

<7> [285.072408] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[3] = 0x0000

<7> [285.072492] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[4] = 0x0000

<7> [285.072585] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[5] = 0x0000

<7> [285.072683] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[6] = 0x0000

<7> [285.072778] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[7] = 0x0000

<7> [285.072871] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[8] = 0x0000

<7> [285.072954] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[9] = 0x0000

<7> [285.073031] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000

<7> [285.073108] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00

<7> [285.073184] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] found:

<7> [285.073260] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no

<7> [285.073338] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_hw_state: fracen: no,

<7> [285.073422] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] multiplier: 225, tx_clk_div: 1.

<7> [285.073507] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_rawhw_state:

<7> [285.073595] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] tx: 0x10, cmn: 0x21

<7> [285.073693] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1

<7> [285.073795] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0

<7> [285.073891] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0

<7> [285.073986] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1

<7> [285.074080] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23

<7> [285.074153] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30)

<7> [285.074225] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710)

<7> [285.074296] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710)

<7> [285.074378] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in port_clock (expected 0, found 432000)

<7> [285.074472] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset

<7> [285.074611] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes

<7> [285.074700] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2

<7> [285.074817] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

<7> [285.074901] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:264:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45

<7> [285.074966] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm

<7> [285.075022] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0

<7> [285.075077] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197

<7> [285.075130] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198

<7> [285.075203] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1

<7> [285.075317] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400

<7> [285.075415] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400

<7> [285.075503] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400

<7> [285.075607] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400

<7> [285.075714] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461

<7> [285.075818] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz

<7> [285.075940] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing

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

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

<7> [285.076230] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0

<7> [285.076320] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0

<7> [285.076421] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset]

<7> [285.076516] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB

<7> [285.076605] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0

<7> [285.076708] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid>

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

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

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

<7> [285.077060] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64

<7> [285.077138] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0

<7> [285.077228] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

<7> [285.077317] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled

<7> [285.077400] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled

<7> [285.077478] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0

<7> [285.077558] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4

<7> [285.077719] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14

<7> [285.077825] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB

<7> [285.077914] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB

<7> [285.077996] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0

<7> [285.078072] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range

<7> [285.078151] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined

<7> [285.078244] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1

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

<7> [285.078413] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97

<7> [285.078491] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906

<7> [285.078573] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

<7> [285.078691] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

<7> [285.078791] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

<7> [285.078888] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [285.078976] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa

<7> [285.079076] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [285.079171] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0

<7> [285.079251] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

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

<7> [285.079416] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0

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

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

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

<7> [285.079750] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no

<7> [285.079846] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

<7> [285.079942] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1.

<7> [285.080026] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state:

<7> [285.080102] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21

<7> [285.080182] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1

<7> [285.080274] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0

<7> [285.080369] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0

<7> [285.080464] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1

<7> [285.080542] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23

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

<7> [285.080658] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

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

<7> [285.080825] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6

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

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

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

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

<7> [285.081106] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on

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

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

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

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

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

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

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

<7> [285.081817] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:431] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes

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

<7> [285.082010] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0

<7> [285.082093] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no

<7> [285.082178] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no

<7> [285.082274] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no

<7> [285.082368] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no

<7> [285.082460] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no

<7> [285.082922] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on

<7> [285.083036] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off

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

<7> [285.083422] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2

<7> [285.083549] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B

<7> [285.083742] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000)

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

<7> [285.083987] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [285.084099] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480

<7> [285.084197] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A]

<7> [285.084271] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1]

<7> [285.084347] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A]

<7> [285.084419] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B]

<7> [285.084491] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C]

<7> [285.084560] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2]

<7> [285.084655] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A]

<7> [285.084739] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B]

<7> [285.084830] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C]

<7> [285.084912] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3]

<7> [285.084981] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A]

<7> [285.085044] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B]

<7> [285.085110] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C]

<7> [285.085153] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

<7> [285.085215] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf

<7> [285.085274] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long

<7> [285.085400] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *)

<7> [285.085389] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10

<7> [285.085475] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes)

<7> [285.085597] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A

<7> [285.085516] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A]

<7> [285.086621] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B]

<7> [285.086752] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0

<7> [285.088787] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on

<7> [285.088900] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (460 ms remaining)

<7> [285.557903] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060

<7> [285.599146] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [285.599533] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on

<7> [285.599954] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063

<7> [285.635956] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

<7> [285.636380] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long

<7> [285.636762] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20

<7> [285.637280] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A]

<7> [285.805746] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [285.806265] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on

<7> [285.806723] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b

<7> [285.808956] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80

<7> [285.810517] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates

<7> [285.811393] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05

<7> [285.812632] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0

<7> [285.814018] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1

<7> [285.815182] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK

<7> [285.815560] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4

<7> [285.817130] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful

<7> [285.817509] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4

<7> [285.818361] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B

<7> [285.818936] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]]

<7> [285.819333] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B

<7> [285.819839] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518

<7> [285.836009] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2

<7> [285.837976] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1]

<7> [285.838459] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B]

<7> [288.341728] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off

<7> [288.342235] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067

<7> [290.838684] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

<7> [290.839449] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6

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

<6> [291.005641] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank@b-edp1