igt@kms_flip@flip-vs-expired-vblank@b-edp1 on shard-lnl@xe-3755-36a8f6b405f4a0def4462366cd17992897e1362b Test details

Detail	Value
Duration	6.43 seconds
Hostname	shard-lnl-3
Igt-Version	IGT-Version: 2.1-ged51b1517 (x86_64) (Linux: 6.17.0-rc6-lgci-xe-xe-3755-36a8f6b405f4a0def+ 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:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1884 run_test() #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040() #4 ../tests/kms_flip.c:2040 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (6.434s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:6433) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:6433) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:6433) DEBUG: name = flip last_ts = 212.531555 last_received_ts = 212.530991 last_seq = 186 current_ts = 212.548218 current_received_ts = 212.547653 current_seq = 187 count = 183 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 72us (kms_flip:6433) DEBUG: name = flip last_ts = 212.548218 last_received_ts = 212.547653 last_seq = 187 current_ts = 212.564880 current_received_ts = 212.564301 current_seq = 188 count = 184 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 86us (kms_flip:6433) DEBUG: name = flip last_ts = 212.564880 last_received_ts = 212.564301 last_seq = 188 current_ts = 212.581543 current_received_ts = 212.581055 current_seq = 189 count = 185 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 78us (kms_flip:6433) DEBUG: name = flip last_ts = 212.581543 last_received_ts = 212.581055 last_seq = 189 current_ts = 212.598206 current_received_ts = 212.597687 current_seq = 190 count = 186 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 83us (kms_flip:6433) DEBUG: name = flip last_ts = 212.598206 last_received_ts = 212.597687 last_seq = 190 current_ts = 212.614883 current_received_ts = 212.614334 current_seq = 191 count = 187 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 91us (kms_flip:6433) DEBUG: name = flip last_ts = 212.614883 last_received_ts = 212.614334 last_seq = 191 current_ts = 212.631546 current_received_ts = 212.630981 current_seq = 192 count = 188 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 71us (kms_flip:6433) DEBUG: name = flip last_ts = 212.631546 last_received_ts = 212.630981 last_seq = 192 current_ts = 212.648209 current_received_ts = 212.647644 current_seq = 193 count = 189 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 89us (kms_flip:6433) DEBUG: name = flip last_ts = 212.648209 last_received_ts = 212.647644 last_seq = 193 current_ts = 212.664886 current_received_ts = 212.664368 current_seq = 194 count = 190 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 111us (kms_flip:6433) DEBUG: name = flip last_ts = 212.664886 last_received_ts = 212.664368 last_seq = 194 current_ts = 212.681549 current_received_ts = 212.681000 current_seq = 195 count = 191 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 76us (kms_flip:6433) DEBUG: name = flip last_ts = 212.681549 last_received_ts = 212.681000 last_seq = 195 current_ts = 212.698212 current_received_ts = 212.697662 current_seq = 196 count = 192 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 79us (kms_flip:6433) DEBUG: name = flip last_ts = 212.698212 last_received_ts = 212.697662 last_seq = 196 current_ts = 212.714874 current_received_ts = 212.714294 current_seq = 197 count = 193 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 81us (kms_flip:6433) DEBUG: name = flip last_ts = 212.714874 last_received_ts = 212.714294 last_seq = 197 current_ts = 212.731537 current_received_ts = 212.730988 current_seq = 198 count = 194 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 69us (kms_flip:6433) DEBUG: name = flip last_ts = 212.731537 last_received_ts = 212.730988 last_seq = 198 current_ts = 212.748199 current_received_ts = 212.747650 current_seq = 199 count = 195 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 54us (kms_flip:6433) DEBUG: name = flip last_ts = 212.748199 last_received_ts = 212.747650 last_seq = 199 current_ts = 212.764862 current_received_ts = 212.764282 current_seq = 200 count = 196 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 87us (kms_flip:6433) DEBUG: name = flip last_ts = 212.764862 last_received_ts = 212.764282 last_seq = 200 current_ts = 212.781525 current_received_ts = 212.781021 current_seq = 201 count = 197 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 76us (kms_flip:6433) DEBUG: name = flip last_ts = 212.781525 last_received_ts = 212.781021 last_seq = 201 current_ts = 212.798203 current_received_ts = 212.797638 current_seq = 202 count = 198 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 72us (kms_flip:6433) DEBUG: name = flip last_ts = 212.798203 last_received_ts = 212.797638 last_seq = 202 current_ts = 212.814865 current_received_ts = 212.814346 current_seq = 203 count = 199 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 86us (kms_flip:6433) DEBUG: name = flip last_ts = 212.814865 last_received_ts = 212.814346 last_seq = 203 current_ts = 212.831528 current_received_ts = 212.830978 current_seq = 204 count = 200 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 100us (kms_flip:6433) DEBUG: name = flip last_ts = 212.831528 last_received_ts = 212.830978 last_seq = 204 current_ts = 212.848190 current_received_ts = 212.847641 current_seq = 205 count = 201 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 71us (kms_flip:6433) DEBUG: name = flip last_ts = 212.848190 last_received_ts = 212.847641 last_seq = 205 current_ts = 212.864868 current_received_ts = 212.864258 current_seq = 206 count = 202 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 71us (kms_flip:6433) DEBUG: name = flip last_ts = 212.864868 last_received_ts = 212.864258 last_seq = 206 current_ts = 212.881531 current_received_ts = 212.880981 current_seq = 207 count = 203 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 53us (kms_flip:6433) DEBUG: name = flip last_ts = 212.881531 last_received_ts = 212.880981 last_seq = 207 current_ts = 212.898193 current_received_ts = 212.897644 current_seq = 208 count = 204 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 212.898193 last_received_ts = 212.897644 last_seq = 208 current_ts = 212.914856 current_received_ts = 212.914230 current_seq = 209 count = 205 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 73us (kms_flip:6433) DEBUG: name = flip last_ts = 212.914856 last_received_ts = 212.914230 last_seq = 209 current_ts = 212.931519 current_received_ts = 212.930969 current_seq = 210 count = 206 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 100us (kms_flip:6433) DEBUG: name = flip last_ts = 212.931519 last_received_ts = 212.930969 last_seq = 210 current_ts = 212.948196 current_received_ts = 212.947647 current_seq = 211 count = 207 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 51us (kms_flip:6433) DEBUG: name = flip last_ts = 212.948196 last_received_ts = 212.947647 last_seq = 211 current_ts = 212.964859 current_received_ts = 212.964310 current_seq = 212 count = 208 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 82us (kms_flip:6433) DEBUG: name = flip last_ts = 212.964859 last_received_ts = 212.964310 last_seq = 212 current_ts = 212.981522 current_received_ts = 212.980972 current_seq = 213 count = 209 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 98us (kms_flip:6433) DEBUG: name = flip last_ts = 212.981522 last_received_ts = 212.980972 last_seq = 213 current_ts = 212.998184 current_received_ts = 212.997604 current_seq = 214 count = 210 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 81us (kms_flip:6433) DEBUG: name = flip last_ts = 212.998184 last_received_ts = 212.997604 last_seq = 214 current_ts = 213.014862 current_received_ts = 213.014282 current_seq = 215 count = 211 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 106us (kms_flip:6433) DEBUG: name = flip last_ts = 213.014862 last_received_ts = 213.014282 last_seq = 215 current_ts = 213.031509 current_received_ts = 213.030991 current_seq = 216 count = 212 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 75us (kms_flip:6433) DEBUG: name = flip last_ts = 213.031509 last_received_ts = 213.030991 last_seq = 216 current_ts = 213.048187 current_received_ts = 213.047653 current_seq = 217 count = 213 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 80us (kms_flip:6433) DEBUG: name = flip last_ts = 213.048187 last_received_ts = 213.047653 last_seq = 217 current_ts = 213.064850 current_received_ts = 213.064255 current_seq = 218 count = 214 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 213.064850 last_received_ts = 213.064255 last_seq = 218 current_ts = 213.081512 current_received_ts = 213.080978 current_seq = 219 count = 215 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 76us (kms_flip:6433) DEBUG: name = flip last_ts = 213.081512 last_received_ts = 213.080978 last_seq = 219 current_ts = 213.098175 current_received_ts = 213.097641 current_seq = 220 count = 216 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 72us (kms_flip:6433) DEBUG: name = flip last_ts = 213.098175 last_received_ts = 213.097641 last_seq = 220 current_ts = 213.114838 current_received_ts = 213.114197 current_seq = 221 count = 217 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 73us (kms_flip:6433) DEBUG: name = flip last_ts = 213.114838 last_received_ts = 213.114197 last_seq = 221 current_ts = 213.131500 current_received_ts = 213.130951 current_seq = 222 count = 218 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 91us (kms_flip:6433) DEBUG: name = flip last_ts = 213.131500 last_received_ts = 213.130951 last_seq = 222 current_ts = 213.148178 current_received_ts = 213.147614 current_seq = 223 count = 219 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 72us (kms_flip:6433) DEBUG: name = flip last_ts = 213.148178 last_received_ts = 213.147614 last_seq = 223 current_ts = 213.164841 current_received_ts = 213.164291 current_seq = 224 count = 220 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 107us (kms_flip:6433) DEBUG: name = flip last_ts = 213.164841 last_received_ts = 213.164291 last_seq = 224 current_ts = 213.181503 current_received_ts = 213.180923 current_seq = 225 count = 221 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 110us (kms_flip:6433) DEBUG: name = flip last_ts = 213.181503 last_received_ts = 213.180923 last_seq = 225 current_ts = 213.198166 current_received_ts = 213.197601 current_seq = 226 count = 222 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 51us (kms_flip:6433) DEBUG: name = flip last_ts = 213.198166 last_received_ts = 213.197601 last_seq = 226 current_ts = 213.214844 current_received_ts = 213.214203 current_seq = 227 count = 223 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 72us (kms_flip:6433) DEBUG: name = flip last_ts = 213.214844 last_received_ts = 213.214203 last_seq = 227 current_ts = 213.231506 current_received_ts = 213.230927 current_seq = 228 count = 224 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 117us (kms_flip:6433) DEBUG: name = flip last_ts = 213.231506 last_received_ts = 213.230927 last_seq = 228 current_ts = 213.248169 current_received_ts = 213.247589 current_seq = 229 count = 225 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 213.248169 last_received_ts = 213.247589 last_seq = 229 current_ts = 213.264832 current_received_ts = 213.264191 current_seq = 230 count = 226 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 78us (kms_flip:6433) DEBUG: name = flip last_ts = 213.264832 last_received_ts = 213.264191 last_seq = 230 current_ts = 213.281494 current_received_ts = 213.280945 current_seq = 231 count = 227 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 118us (kms_flip:6433) DEBUG: name = flip last_ts = 213.281494 last_received_ts = 213.280945 last_seq = 231 current_ts = 213.298157 current_received_ts = 213.297607 current_seq = 232 count = 228 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 213.298157 last_received_ts = 213.297607 last_seq = 232 current_ts = 213.314819 current_received_ts = 213.314255 current_seq = 233 count = 229 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 115us (kms_flip:6433) DEBUG: name = flip last_ts = 213.314819 last_received_ts = 213.314255 last_seq = 233 current_ts = 213.331497 current_received_ts = 213.330917 current_seq = 234 count = 230 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 98us (kms_flip:6433) DEBUG: name = flip last_ts = 213.331497 last_received_ts = 213.330917 last_seq = 234 current_ts = 213.348160 current_received_ts = 213.347610 current_seq = 235 count = 231 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 86us (kms_flip:6433) DEBUG: name = flip last_ts = 213.348160 last_received_ts = 213.347610 last_seq = 235 current_ts = 213.364822 current_received_ts = 213.364166 current_seq = 236 count = 232 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 72us (kms_flip:6433) DEBUG: name = flip last_ts = 213.364822 last_received_ts = 213.364166 last_seq = 236 current_ts = 213.381485 current_received_ts = 213.380936 current_seq = 237 count = 233 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 106us (kms_flip:6433) DEBUG: name = flip last_ts = 213.381485 last_received_ts = 213.380936 last_seq = 237 current_ts = 213.398148 current_received_ts = 213.397614 current_seq = 238 count = 234 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 213.398148 last_received_ts = 213.397614 last_seq = 238 current_ts = 213.414825 current_received_ts = 213.414185 current_seq = 239 count = 235 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 85us (kms_flip:6433) DEBUG: name = flip last_ts = 213.414825 last_received_ts = 213.414185 last_seq = 239 current_ts = 213.431488 current_received_ts = 213.430939 current_seq = 240 count = 236 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 101us (kms_flip:6433) DEBUG: name = flip last_ts = 213.431488 last_received_ts = 213.430939 last_seq = 240 current_ts = 213.448151 current_received_ts = 213.447586 current_seq = 241 count = 237 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 213.448151 last_received_ts = 213.447586 last_seq = 241 current_ts = 213.464813 current_received_ts = 213.464249 current_seq = 242 count = 238 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 100us (kms_flip:6433) DEBUG: name = flip last_ts = 213.464813 last_received_ts = 213.464249 last_seq = 242 current_ts = 213.481476 current_received_ts = 213.480927 current_seq = 243 count = 239 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 104us (kms_flip:6433) DEBUG: name = flip last_ts = 213.481476 last_received_ts = 213.480927 last_seq = 243 current_ts = 213.498138 current_received_ts = 213.497589 current_seq = 244 count = 240 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 213.498138 last_received_ts = 213.497589 last_seq = 244 current_ts = 213.514816 current_received_ts = 213.514175 current_seq = 245 count = 241 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 52us (kms_flip:6433) DEBUG: name = flip last_ts = 213.514816 last_received_ts = 213.514175 last_seq = 245 current_ts = 213.531479 current_received_ts = 213.530930 current_seq = 246 count = 242 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 115us (kms_flip:6433) DEBUG: name = flip last_ts = 213.531479 last_received_ts = 213.530930 last_seq = 246 current_ts = 213.548141 current_received_ts = 213.547577 current_seq = 247 count = 243 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 213.548141 last_received_ts = 213.547577 last_seq = 247 current_ts = 213.564804 current_received_ts = 213.564240 current_seq = 248 count = 244 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 123us (kms_flip:6433) DEBUG: name = flip last_ts = 213.564804 last_received_ts = 213.564240 last_seq = 248 current_ts = 213.581467 current_received_ts = 213.580948 current_seq = 249 count = 245 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 106us (kms_flip:6433) DEBUG: name = flip last_ts = 213.581467 last_received_ts = 213.580948 last_seq = 249 current_ts = 213.598145 current_received_ts = 213.597626 current_seq = 250 count = 246 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 92us (kms_flip:6433) DEBUG: name = flip last_ts = 213.598145 last_received_ts = 213.597626 last_seq = 250 current_ts = 213.614807 current_received_ts = 213.614182 current_seq = 251 count = 247 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 79us (kms_flip:6433) DEBUG: name = flip last_ts = 213.614807 last_received_ts = 213.614182 last_seq = 251 current_ts = 213.631470 current_received_ts = 213.630920 current_seq = 252 count = 248 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 102us (kms_flip:6433) DEBUG: name = flip last_ts = 213.631470 last_received_ts = 213.630920 last_seq = 252 current_ts = 213.648132 current_received_ts = 213.647583 current_seq = 253 count = 249 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 78us (kms_flip:6433) DEBUG: name = flip last_ts = 213.648132 last_received_ts = 213.647583 last_seq = 253 current_ts = 213.664795 current_received_ts = 213.664230 current_seq = 254 count = 250 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 213.664795 last_received_ts = 213.664230 last_seq = 254 current_ts = 213.681473 current_received_ts = 213.680923 current_seq = 255 count = 251 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 104us (kms_flip:6433) DEBUG: name = flip last_ts = 213.681473 last_received_ts = 213.680923 last_seq = 255 current_ts = 213.698120 current_received_ts = 213.697586 current_seq = 256 count = 252 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 213.698120 last_received_ts = 213.697586 last_seq = 256 current_ts = 213.714798 current_received_ts = 213.714249 current_seq = 257 count = 253 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 120us (kms_flip:6433) DEBUG: name = flip last_ts = 213.714798 last_received_ts = 213.714249 last_seq = 257 current_ts = 213.731461 current_received_ts = 213.730911 current_seq = 258 count = 254 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 94us (kms_flip:6433) DEBUG: name = flip last_ts = 213.731461 last_received_ts = 213.730911 last_seq = 258 current_ts = 213.748123 current_received_ts = 213.747574 current_seq = 259 count = 255 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 56us (kms_flip:6433) DEBUG: name = flip last_ts = 213.748123 last_received_ts = 213.747574 last_seq = 259 current_ts = 213.764786 current_received_ts = 213.764160 current_seq = 260 count = 256 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 71us (kms_flip:6433) DEBUG: name = flip last_ts = 213.764786 last_received_ts = 213.764160 last_seq = 260 current_ts = 213.781448 current_received_ts = 213.780914 current_seq = 261 count = 257 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 98us (kms_flip:6433) DEBUG: name = flip last_ts = 213.781448 last_received_ts = 213.780914 last_seq = 261 current_ts = 213.798126 current_received_ts = 213.797577 current_seq = 262 count = 258 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 81us (kms_flip:6433) DEBUG: name = flip last_ts = 213.798126 last_received_ts = 213.797577 last_seq = 262 current_ts = 213.814789 current_received_ts = 213.814240 current_seq = 263 count = 259 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 101us (kms_flip:6433) DEBUG: name = flip last_ts = 213.814789 last_received_ts = 213.814240 last_seq = 263 current_ts = 213.831451 current_received_ts = 213.830933 current_seq = 264 count = 260 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 145us (kms_flip:6433) DEBUG: name = flip last_ts = 213.831451 last_received_ts = 213.830933 last_seq = 264 current_ts = 213.848114 current_received_ts = 213.847580 current_seq = 265 count = 261 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 213.848114 last_received_ts = 213.847580 last_seq = 265 current_ts = 213.864777 current_received_ts = 213.864227 current_seq = 266 count = 262 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 213.864777 last_received_ts = 213.864227 last_seq = 266 current_ts = 213.881439 current_received_ts = 213.880890 current_seq = 267 count = 263 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 79us (kms_flip:6433) DEBUG: name = flip last_ts = 213.881439 last_received_ts = 213.880890 last_seq = 267 current_ts = 213.898117 current_received_ts = 213.897598 current_seq = 268 count = 264 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 58us (kms_flip:6433) DEBUG: name = flip last_ts = 213.898117 last_received_ts = 213.897598 last_seq = 268 current_ts = 213.914780 current_received_ts = 213.914230 current_seq = 269 count = 265 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 76us (kms_flip:6433) DEBUG: name = flip last_ts = 213.914780 last_received_ts = 213.914230 last_seq = 269 current_ts = 213.931442 current_received_ts = 213.930878 current_seq = 270 count = 266 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 85us (kms_flip:6433) DEBUG: name = flip last_ts = 213.931442 last_received_ts = 213.930878 last_seq = 270 current_ts = 213.948105 current_received_ts = 213.947571 current_seq = 271 count = 267 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 72us (kms_flip:6433) DEBUG: name = flip last_ts = 213.948105 last_received_ts = 213.947571 last_seq = 271 current_ts = 213.964767 current_received_ts = 213.964218 current_seq = 272 count = 268 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 118us (kms_flip:6433) DEBUG: name = flip last_ts = 213.964767 last_received_ts = 213.964218 last_seq = 272 current_ts = 213.981445 current_received_ts = 213.980881 current_seq = 273 count = 269 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 80us (kms_flip:6433) DEBUG: name = flip last_ts = 213.981445 last_received_ts = 213.980881 last_seq = 273 current_ts = 213.998108 current_received_ts = 213.997528 current_seq = 274 count = 270 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 78us (kms_flip:6433) DEBUG: name = flip last_ts = 213.998108 last_received_ts = 213.997528 last_seq = 274 current_ts = 214.014771 current_received_ts = 214.014175 current_seq = 275 count = 271 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 71us (kms_flip:6433) DEBUG: name = flip last_ts = 214.014771 last_received_ts = 214.014175 last_seq = 275 current_ts = 214.031433 current_received_ts = 214.030884 current_seq = 276 count = 272 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 76us (kms_flip:6433) DEBUG: name = flip last_ts = 214.031433 last_received_ts = 214.030884 last_seq = 276 current_ts = 214.048096 current_received_ts = 214.047546 current_seq = 277 count = 273 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 71us (kms_flip:6433) DEBUG: name = flip last_ts = 214.048096 last_received_ts = 214.047546 last_seq = 277 current_ts = 214.064774 current_received_ts = 214.064209 current_seq = 278 count = 274 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 71us (kms_flip:6433) DEBUG: name = flip last_ts = 214.064774 last_received_ts = 214.064209 last_seq = 278 current_ts = 214.081436 current_received_ts = 214.080887 current_seq = 279 count = 275 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 71us (kms_flip:6433) DEBUG: name = flip last_ts = 214.081436 last_received_ts = 214.080887 last_seq = 279 current_ts = 214.098099 current_received_ts = 214.097534 current_seq = 280 count = 276 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 87us (kms_flip:6433) DEBUG: name = flip last_ts = 214.098099 last_received_ts = 214.097534 last_seq = 280 current_ts = 214.114761 current_received_ts = 214.114197 current_seq = 281 count = 277 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 81us (kms_flip:6433) DEBUG: name = flip last_ts = 214.114761 last_received_ts = 214.114197 last_seq = 281 current_ts = 214.131424 current_received_ts = 214.130890 current_seq = 282 count = 278 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 52us (kms_flip:6433) DEBUG: name = flip last_ts = 214.131424 last_received_ts = 214.130890 last_seq = 282 current_ts = 214.148102 current_received_ts = 214.147537 current_seq = 283 count = 279 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 74us (kms_flip:6433) DEBUG: name = flip last_ts = 214.148102 last_received_ts = 214.147537 last_seq = 283 current_ts = 214.164764 current_received_ts = 214.164185 current_seq = 284 count = 280 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 73us (kms_flip:6433) DEBUG: name = flip last_ts = 214.164764 last_received_ts = 214.164185 last_seq = 284 current_ts = 214.181427 current_received_ts = 214.180878 current_seq = 285 count = 281 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 88us (kms_flip:6433) DEBUG: name = flip last_ts = 214.181427 last_received_ts = 214.180878 last_seq = 285 current_ts = 214.198090 current_received_ts = 214.197556 current_seq = 286 count = 282 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 79us (kms_flip:6433) DEBUG: name = flip last_ts = 214.198090 last_received_ts = 214.197556 last_seq = 286 current_ts = 214.214752 current_received_ts = 214.214218 current_seq = 287 count = 283 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 81us (kms_flip:6433) DEBUG: name = flip last_ts = 214.214752 last_received_ts = 214.214218 last_seq = 287 current_ts = 214.231415 current_received_ts = 214.230865 current_seq = 288 count = 284 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 72us (kms_flip:6433) DEBUG: name = flip last_ts = 214.231415 last_received_ts = 214.230865 last_seq = 288 current_ts = 214.248093 current_received_ts = 214.247528 current_seq = 289 count = 285 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 76us (kms_flip:6433) DEBUG: name = flip last_ts = 214.248093 last_received_ts = 214.247528 last_seq = 289 current_ts = 214.264740 current_received_ts = 214.264236 current_seq = 290 count = 286 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 113us (kms_flip:6433) DEBUG: name = flip last_ts = 214.264740 last_received_ts = 214.264236 last_seq = 290 current_ts = 214.281418 current_received_ts = 214.280869 current_seq = 291 count = 287 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 86us (kms_flip:6433) DEBUG: name = flip last_ts = 214.281418 last_received_ts = 214.280869 last_seq = 291 current_ts = 214.298080 current_received_ts = 214.297501 current_seq = 292 count = 288 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 214.298080 last_received_ts = 214.297501 last_seq = 292 current_ts = 214.314743 current_received_ts = 214.314178 current_seq = 293 count = 289 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 72us (kms_flip:6433) DEBUG: name = flip last_ts = 214.314743 last_received_ts = 214.314178 last_seq = 293 current_ts = 214.331406 current_received_ts = 214.330841 current_seq = 294 count = 290 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 87us (kms_flip:6433) DEBUG: name = flip last_ts = 214.331406 last_received_ts = 214.330841 last_seq = 294 current_ts = 214.348068 current_received_ts = 214.347519 current_seq = 295 count = 291 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 52us (kms_flip:6433) DEBUG: name = flip last_ts = 214.348068 last_received_ts = 214.347519 last_seq = 295 current_ts = 214.364731 current_received_ts = 214.364182 current_seq = 296 count = 292 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 89us (kms_flip:6433) DEBUG: name = flip last_ts = 214.364731 last_received_ts = 214.364182 last_seq = 296 current_ts = 214.381409 current_received_ts = 214.380844 current_seq = 297 count = 293 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 72us (kms_flip:6433) DEBUG: name = flip last_ts = 214.381409 last_received_ts = 214.380844 last_seq = 297 current_ts = 214.398071 current_received_ts = 214.397537 current_seq = 298 count = 294 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 87us (kms_flip:6433) DEBUG: name = flip last_ts = 214.398071 last_received_ts = 214.397537 last_seq = 298 current_ts = 214.414734 current_received_ts = 214.414246 current_seq = 299 count = 295 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 110us (kms_flip:6433) DEBUG: name = flip last_ts = 214.414734 last_received_ts = 214.414246 last_seq = 299 current_ts = 214.431396 current_received_ts = 214.430878 current_seq = 300 count = 296 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 81us (kms_flip:6433) DEBUG: name = flip last_ts = 214.431396 last_received_ts = 214.430878 last_seq = 300 current_ts = 214.448059 current_received_ts = 214.447556 current_seq = 301 count = 297 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 76us (kms_flip:6433) DEBUG: name = flip last_ts = 214.448059 last_received_ts = 214.447556 last_seq = 301 current_ts = 214.464722 current_received_ts = 214.464157 current_seq = 302 count = 298 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 214.464722 last_received_ts = 214.464157 last_seq = 302 current_ts = 214.481400 current_received_ts = 214.480865 current_seq = 303 count = 299 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 72us (kms_flip:6433) DEBUG: name = flip last_ts = 214.481400 last_received_ts = 214.480865 last_seq = 303 current_ts = 214.498062 current_received_ts = 214.497513 current_seq = 304 count = 300 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 86us (kms_flip:6433) DEBUG: name = flip last_ts = 214.498062 last_received_ts = 214.497513 last_seq = 304 current_ts = 214.514725 current_received_ts = 214.514221 current_seq = 305 count = 301 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 78us (kms_flip:6433) DEBUG: name = flip last_ts = 214.514725 last_received_ts = 214.514221 last_seq = 305 current_ts = 214.531387 current_received_ts = 214.530869 current_seq = 306 count = 302 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 214.531387 last_received_ts = 214.530869 last_seq = 306 current_ts = 214.548050 current_received_ts = 214.547516 current_seq = 307 count = 303 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 77us (kms_flip:6433) DEBUG: name = flip last_ts = 214.548050 last_received_ts = 214.547516 last_seq = 307 current_ts = 214.564713 current_received_ts = 214.564163 current_seq = 308 count = 304 seq_step = 1 (kms_flip:6433) DEBUG: Vblank took 1324us (kms_flip:6433) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:6433) CRITICAL: Failed assertion: end - start < 500 (kms_flip:6433) igt_core-INFO: Stack trace: (kms_flip:6433) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:6433) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:6433) igt_core-INFO: #2 ../tests/kms_flip.c:1884 run_test() (kms_flip:6433) igt_core-INFO: #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040() (kms_flip:6433) igt_core-INFO: #4 ../tests/kms_flip.c:2040 main() (kms_flip:6433) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:6433) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:6433) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (6.434s)
Dmesg	<6> [239.587868] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [239.589799] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:241] <7> [239.591011] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:244] <7> [239.601465] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [239.601780] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [239.602041] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [239.671148] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:88:pipe A] <7> [239.671414] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [239.671733] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [239.671981] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [239.672214] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [239.672448] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88: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> [239.672662] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [239.672865] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [239.673061] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [239.673252] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [239.673484] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [239.673675] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [239.673847] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [239.674017] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [239.674198] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [239.674364] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [239.674522] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [239.674672] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [239.674821] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [239.674970] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [239.675118] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [239.675259] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [239.675414] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [239.675556] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [239.675699] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [239.675839] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [239.675979] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [239.676116] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [239.676247] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [239.676446] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [239.676572] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [239.676696] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [239.676817] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [239.676935] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [239.677052] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [239.677170] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [239.677281] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [239.677407] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [239.677519] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [239.677629] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:88:pipe A] fastset requirement not met, forcing full modeset <7> [239.677794] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [239.677908] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:88:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [239.678056] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:83:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [239.678178] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via squashing <7> [239.678299] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [239.678430] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 0, actual 0 <7> [239.678585] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:88:pipe A] enable: no [modeset] <7> [239.678700] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:33:plane 1A] fb: [NOFB], visible: no <7> [239.678812] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:43:plane 2A] fb: [NOFB], visible: no <7> [239.678919] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:53:plane 3A] fb: [NOFB], visible: no <7> [239.679025] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:63:plane 4A] fb: [NOFB], visible: no <7> [239.679128] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:73:plane 5A] fb: [NOFB], visible: no <7> [239.679228] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:83:cursor A] fb: [NOFB], visible: no <7> [239.679397] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [239.679527] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [239.679781] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [239.679881] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [239.888621] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 0 <7> [239.889085] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [239.899872] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power off <7> [239.900389] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power off time <7> [239.900833] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [239.953068] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [239.953748] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - short <7> [239.956336] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [239.956868] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [239.957359] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A] <7> [239.957648] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1] <7> [239.957915] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A] <7> [239.958189] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B] <7> [239.958487] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C] <7> [239.958453] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:204:DDI A/PHY A] <7> [239.958750] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2] <7> [239.959015] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A] <7> [239.959342] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B] <7> [239.959610] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C] <7> [239.959872] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3] <7> [239.960203] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A] <7> [239.960524] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B] <7> [239.960811] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C] <7> [239.961093] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1] <7> [239.961451] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [239.961753] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [239.962048] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [239.962584] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [239.963078] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:88:pipe A] <7> [239.963522] 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> [239.963977] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [239.964315] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [239.965159] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B] <7> [239.965554] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C] <7> [239.965854] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B] <7> [239.965926] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:205:eDP-1] <7> [239.966108] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:205:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [239.966548] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:204:DDI A/PHY A][CRTC:145:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 max link_bpp 30.0000 <7> [239.966916] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 link rate required 1303913 available 1728000 <7> [239.967269] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:145:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [239.967671] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:204:DDI A/PHY A] [CRTC:145:pipe B] <7> [239.968047] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [239.968417] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [239.968803] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [239.969137] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [239.969478] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145: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> [239.969782] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [239.970066] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [239.970399] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [239.970674] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [239.970942] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [239.971199] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [239.971462] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [239.971698] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [239.971958] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [239.972176] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [239.972397] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [239.972633] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [239.972827] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [239.973014] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [239.973198] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [239.973389] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [239.973563] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [239.973727] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [239.973888] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [239.974049] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [239.974204] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [239.974374] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [239.974527] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [239.974691] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [239.974854] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [239.975013] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [239.975149] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [239.975291] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [239.975425] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [239.975559] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in dpll_hw_state.cx0pll C20 <7> [239.975687] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] expected: <7> [239.975814] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c20pll_hw_state: <7> [239.975947] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx[0] = 0x0000, tx[1] = 0x0000, tx[2] = 0x0000 <7> [239.976077] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] cmn[0] = 0x0000, cmn[1] = 0x0000, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [239.976201] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[0] = 0x0000 <7> [239.976400] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[1] = 0x0000 <7> [239.976519] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[2] = 0x0000 <7> [239.976632] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[3] = 0x0000 <7> [239.976743] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[4] = 0x0000 <7> [239.976850] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[5] = 0x0000 <7> [239.976955] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[6] = 0x0000 <7> [239.977062] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[7] = 0x0000 <7> [239.977164] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[8] = 0x0000 <7> [239.977262] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[9] = 0x0000 <7> [239.977372] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] found: <7> [239.977468] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_hw_state: fracen: no, <7> [239.977563] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] multiplier: 225, tx_clk_div: 1. <7> [239.977653] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_rawhw_state: <7> [239.977743] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx: 0x10, cmn: 0x21 <7> [239.977831] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [239.977920] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [239.978009] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [239.978099] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [239.978185] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [239.978270] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [239.978369] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [239.978452] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [239.978534] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [239.978613] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:145:pipe B] fastset requirement not met, forcing full modeset <7> [239.978726] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [239.978799] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:145:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [239.978895] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:90:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [239.978969] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:140:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [239.979032] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90: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> [239.979089] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 12, 13, 0, 0, 0, 4, 0 <7> [239.979145] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 274, 297, 0, 0, 197, 92, 197 <7> [239.979199] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 365, 456, 0, 0, 198, 183, 198 <7> [239.979275] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:145:pipe B] data rate 1390840 num active planes 1 <7> [239.979368] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [239.979452] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [239.979531] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [239.979611] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [239.979684] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [239.979755] xe 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [xe]] [PLANE:90:plane 1B] min cdclk (173855 kHz) > [CRTC:145:pipe B] min cdclk (0 kHz) <7> [239.979815] xe 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [xe]] new bandwidth min cdclk (27165 kHz) > old min cdclk (0 kHz) <7> [239.979889] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via squashing <7> [239.979960] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [239.980031] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 0, actual 0 <7> [239.980113] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:145:pipe B] enable: yes [modeset] <7> [239.980188] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [239.980259] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [239.980338] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [239.980424] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [239.980504] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [239.980574] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [239.980645] 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> [239.980717] 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> [239.980789] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [239.980859] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [239.980929] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [239.980997] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [239.981064] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [239.981132] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [239.981199] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [239.981265] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [239.981339] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [239.981419] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [239.981494] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [239.981561] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [239.981626] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0 <7> [239.981691] 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: 106 vsync start: 103, vsync end: 97 <7> [239.981756] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1800, vmax vblank: 1800, vmin vtotal: 1906, vmax vtotal: 1906 <7> [239.981821] 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> [239.981887] 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> [239.981951] 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> [239.982016] 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> [239.982079] 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> [239.982143] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710 <7> [239.982209] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [239.982275] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [239.982352] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [239.982433] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [239.982503] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0x69780, dpll_md: 0x42110, fp0: 0x1a2, fp1: 0x1000000 <7> [239.982569] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [239.982635] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [239.982700] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [239.982764] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [239.982829] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [239.982893] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [239.982958] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [239.983022] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [239.983087] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [239.983151] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [239.983214] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [239.983277] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [239.983358] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:90:plane 1B] fb: [FB:241] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [239.983378] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [239.983443] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [239.983512] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [239.983519] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [239.983576] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:100:plane 2B] fb: [NOFB], visible: no <7> [239.983612] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [239.983639] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:110:plane 3B] fb: [NOFB], visible: no <7> [239.983702] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:120:plane 4B] fb: [NOFB], visible: no <7> [239.983727] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [239.983765] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:130:plane 5B] fb: [NOFB], visible: no <7> [239.983829] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:140:cursor B] fb: [NOFB], visible: no <7> [239.984161] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [239.984247] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [239.984482] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [239.984613] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [239.984727] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [239.984854] 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> [239.984937] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [239.985019] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [239.985095] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A] <7> [239.985157] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1] <7> [239.985218] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A] <7> [239.985278] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B] <7> [239.985351] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C] <7> [239.985422] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2] <7> [239.985486] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A] <7> [239.985544] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B] <7> [239.985599] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C] <7> [239.985657] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3] <7> [239.985715] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A] <7> [239.985770] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B] <7> [239.985826] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C] <7> [239.985881] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [239.986029] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [239.986087] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [239.986188] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [239.987297] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power on <7> [239.987363] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power cycle (470 ms remaining) <7> [239.991660] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [239.991859] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - long <7> [239.991952] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [239.992194] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:204:DDI A/PHY A] <7> [240.464497] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [240.515349] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [240.515649] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power on <7> [240.515903] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [240.552375] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [240.552729] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - long <7> [240.553032] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [240.553575] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:204:DDI A/PHY A] <7> [240.724782] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [240.726881] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD on <7> [240.727153] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [240.729245] 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> [240.730501] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [240.731260] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [240.732302] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [240.733418] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [240.734425] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Clock recovery OK <7> [240.734726] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [240.736065] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [240.736419] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [240.737255] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [240.737667] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [240.737969] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [240.738361] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 4518 <7> [240.754545] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [240.756338] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1] <7> [240.756713] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:145:pipe B] <7> [243.264109] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD off <7> [243.264490] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [245.871978] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [245.872433] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [245.872851] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [246.023282] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

6.43 seconds

Hostname

shard-lnl-3

Igt-Version

IGT-Version: 2.1-ged51b1517 (x86_64) (Linux: 6.17.0-rc6-lgci-xe-xe-3755-36a8f6b405f4a0def+ 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:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1884 run_test()
  #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (6.434s)

Err

Starting dynamic subtest: B-eDP1
(kms_flip:6433) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:6433) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.531555
last_received_ts = 212.530991
last_seq = 186
current_ts = 212.548218
current_received_ts = 212.547653
current_seq = 187
count = 183
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 72us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.548218
last_received_ts = 212.547653
last_seq = 187
current_ts = 212.564880
current_received_ts = 212.564301
current_seq = 188
count = 184
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 86us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.564880
last_received_ts = 212.564301
last_seq = 188
current_ts = 212.581543
current_received_ts = 212.581055
current_seq = 189
count = 185
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 78us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.581543
last_received_ts = 212.581055
last_seq = 189
current_ts = 212.598206
current_received_ts = 212.597687
current_seq = 190
count = 186
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 83us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.598206
last_received_ts = 212.597687
last_seq = 190
current_ts = 212.614883
current_received_ts = 212.614334
current_seq = 191
count = 187
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 91us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.614883
last_received_ts = 212.614334
last_seq = 191
current_ts = 212.631546
current_received_ts = 212.630981
current_seq = 192
count = 188
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 71us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.631546
last_received_ts = 212.630981
last_seq = 192
current_ts = 212.648209
current_received_ts = 212.647644
current_seq = 193
count = 189
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 89us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.648209
last_received_ts = 212.647644
last_seq = 193
current_ts = 212.664886
current_received_ts = 212.664368
current_seq = 194
count = 190
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 111us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.664886
last_received_ts = 212.664368
last_seq = 194
current_ts = 212.681549
current_received_ts = 212.681000
current_seq = 195
count = 191
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 76us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.681549
last_received_ts = 212.681000
last_seq = 195
current_ts = 212.698212
current_received_ts = 212.697662
current_seq = 196
count = 192
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 79us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.698212
last_received_ts = 212.697662
last_seq = 196
current_ts = 212.714874
current_received_ts = 212.714294
current_seq = 197
count = 193
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 81us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.714874
last_received_ts = 212.714294
last_seq = 197
current_ts = 212.731537
current_received_ts = 212.730988
current_seq = 198
count = 194
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 69us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.731537
last_received_ts = 212.730988
last_seq = 198
current_ts = 212.748199
current_received_ts = 212.747650
current_seq = 199
count = 195
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 54us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.748199
last_received_ts = 212.747650
last_seq = 199
current_ts = 212.764862
current_received_ts = 212.764282
current_seq = 200
count = 196
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 87us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.764862
last_received_ts = 212.764282
last_seq = 200
current_ts = 212.781525
current_received_ts = 212.781021
current_seq = 201
count = 197
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 76us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.781525
last_received_ts = 212.781021
last_seq = 201
current_ts = 212.798203
current_received_ts = 212.797638
current_seq = 202
count = 198
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 72us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.798203
last_received_ts = 212.797638
last_seq = 202
current_ts = 212.814865
current_received_ts = 212.814346
current_seq = 203
count = 199
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 86us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.814865
last_received_ts = 212.814346
last_seq = 203
current_ts = 212.831528
current_received_ts = 212.830978
current_seq = 204
count = 200
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 100us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.831528
last_received_ts = 212.830978
last_seq = 204
current_ts = 212.848190
current_received_ts = 212.847641
current_seq = 205
count = 201
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 71us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.848190
last_received_ts = 212.847641
last_seq = 205
current_ts = 212.864868
current_received_ts = 212.864258
current_seq = 206
count = 202
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 71us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.864868
last_received_ts = 212.864258
last_seq = 206
current_ts = 212.881531
current_received_ts = 212.880981
current_seq = 207
count = 203
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 53us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.881531
last_received_ts = 212.880981
last_seq = 207
current_ts = 212.898193
current_received_ts = 212.897644
current_seq = 208
count = 204
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.898193
last_received_ts = 212.897644
last_seq = 208
current_ts = 212.914856
current_received_ts = 212.914230
current_seq = 209
count = 205
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 73us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.914856
last_received_ts = 212.914230
last_seq = 209
current_ts = 212.931519
current_received_ts = 212.930969
current_seq = 210
count = 206
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 100us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.931519
last_received_ts = 212.930969
last_seq = 210
current_ts = 212.948196
current_received_ts = 212.947647
current_seq = 211
count = 207
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 51us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.948196
last_received_ts = 212.947647
last_seq = 211
current_ts = 212.964859
current_received_ts = 212.964310
current_seq = 212
count = 208
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 82us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.964859
last_received_ts = 212.964310
last_seq = 212
current_ts = 212.981522
current_received_ts = 212.980972
current_seq = 213
count = 209
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 98us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.981522
last_received_ts = 212.980972
last_seq = 213
current_ts = 212.998184
current_received_ts = 212.997604
current_seq = 214
count = 210
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 81us
(kms_flip:6433) DEBUG: name = flip
last_ts = 212.998184
last_received_ts = 212.997604
last_seq = 214
current_ts = 213.014862
current_received_ts = 213.014282
current_seq = 215
count = 211
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 106us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.014862
last_received_ts = 213.014282
last_seq = 215
current_ts = 213.031509
current_received_ts = 213.030991
current_seq = 216
count = 212
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 75us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.031509
last_received_ts = 213.030991
last_seq = 216
current_ts = 213.048187
current_received_ts = 213.047653
current_seq = 217
count = 213
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 80us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.048187
last_received_ts = 213.047653
last_seq = 217
current_ts = 213.064850
current_received_ts = 213.064255
current_seq = 218
count = 214
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.064850
last_received_ts = 213.064255
last_seq = 218
current_ts = 213.081512
current_received_ts = 213.080978
current_seq = 219
count = 215
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 76us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.081512
last_received_ts = 213.080978
last_seq = 219
current_ts = 213.098175
current_received_ts = 213.097641
current_seq = 220
count = 216
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 72us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.098175
last_received_ts = 213.097641
last_seq = 220
current_ts = 213.114838
current_received_ts = 213.114197
current_seq = 221
count = 217
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 73us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.114838
last_received_ts = 213.114197
last_seq = 221
current_ts = 213.131500
current_received_ts = 213.130951
current_seq = 222
count = 218
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 91us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.131500
last_received_ts = 213.130951
last_seq = 222
current_ts = 213.148178
current_received_ts = 213.147614
current_seq = 223
count = 219
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 72us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.148178
last_received_ts = 213.147614
last_seq = 223
current_ts = 213.164841
current_received_ts = 213.164291
current_seq = 224
count = 220
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 107us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.164841
last_received_ts = 213.164291
last_seq = 224
current_ts = 213.181503
current_received_ts = 213.180923
current_seq = 225
count = 221
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 110us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.181503
last_received_ts = 213.180923
last_seq = 225
current_ts = 213.198166
current_received_ts = 213.197601
current_seq = 226
count = 222
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 51us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.198166
last_received_ts = 213.197601
last_seq = 226
current_ts = 213.214844
current_received_ts = 213.214203
current_seq = 227
count = 223
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 72us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.214844
last_received_ts = 213.214203
last_seq = 227
current_ts = 213.231506
current_received_ts = 213.230927
current_seq = 228
count = 224
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 117us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.231506
last_received_ts = 213.230927
last_seq = 228
current_ts = 213.248169
current_received_ts = 213.247589
current_seq = 229
count = 225
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.248169
last_received_ts = 213.247589
last_seq = 229
current_ts = 213.264832
current_received_ts = 213.264191
current_seq = 230
count = 226
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 78us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.264832
last_received_ts = 213.264191
last_seq = 230
current_ts = 213.281494
current_received_ts = 213.280945
current_seq = 231
count = 227
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 118us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.281494
last_received_ts = 213.280945
last_seq = 231
current_ts = 213.298157
current_received_ts = 213.297607
current_seq = 232
count = 228
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.298157
last_received_ts = 213.297607
last_seq = 232
current_ts = 213.314819
current_received_ts = 213.314255
current_seq = 233
count = 229
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 115us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.314819
last_received_ts = 213.314255
last_seq = 233
current_ts = 213.331497
current_received_ts = 213.330917
current_seq = 234
count = 230
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 98us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.331497
last_received_ts = 213.330917
last_seq = 234
current_ts = 213.348160
current_received_ts = 213.347610
current_seq = 235
count = 231
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 86us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.348160
last_received_ts = 213.347610
last_seq = 235
current_ts = 213.364822
current_received_ts = 213.364166
current_seq = 236
count = 232
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 72us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.364822
last_received_ts = 213.364166
last_seq = 236
current_ts = 213.381485
current_received_ts = 213.380936
current_seq = 237
count = 233
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 106us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.381485
last_received_ts = 213.380936
last_seq = 237
current_ts = 213.398148
current_received_ts = 213.397614
current_seq = 238
count = 234
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.398148
last_received_ts = 213.397614
last_seq = 238
current_ts = 213.414825
current_received_ts = 213.414185
current_seq = 239
count = 235
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 85us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.414825
last_received_ts = 213.414185
last_seq = 239
current_ts = 213.431488
current_received_ts = 213.430939
current_seq = 240
count = 236
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 101us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.431488
last_received_ts = 213.430939
last_seq = 240
current_ts = 213.448151
current_received_ts = 213.447586
current_seq = 241
count = 237
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.448151
last_received_ts = 213.447586
last_seq = 241
current_ts = 213.464813
current_received_ts = 213.464249
current_seq = 242
count = 238
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 100us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.464813
last_received_ts = 213.464249
last_seq = 242
current_ts = 213.481476
current_received_ts = 213.480927
current_seq = 243
count = 239
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 104us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.481476
last_received_ts = 213.480927
last_seq = 243
current_ts = 213.498138
current_received_ts = 213.497589
current_seq = 244
count = 240
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.498138
last_received_ts = 213.497589
last_seq = 244
current_ts = 213.514816
current_received_ts = 213.514175
current_seq = 245
count = 241
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 52us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.514816
last_received_ts = 213.514175
last_seq = 245
current_ts = 213.531479
current_received_ts = 213.530930
current_seq = 246
count = 242
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 115us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.531479
last_received_ts = 213.530930
last_seq = 246
current_ts = 213.548141
current_received_ts = 213.547577
current_seq = 247
count = 243
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.548141
last_received_ts = 213.547577
last_seq = 247
current_ts = 213.564804
current_received_ts = 213.564240
current_seq = 248
count = 244
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 123us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.564804
last_received_ts = 213.564240
last_seq = 248
current_ts = 213.581467
current_received_ts = 213.580948
current_seq = 249
count = 245
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 106us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.581467
last_received_ts = 213.580948
last_seq = 249
current_ts = 213.598145
current_received_ts = 213.597626
current_seq = 250
count = 246
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 92us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.598145
last_received_ts = 213.597626
last_seq = 250
current_ts = 213.614807
current_received_ts = 213.614182
current_seq = 251
count = 247
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 79us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.614807
last_received_ts = 213.614182
last_seq = 251
current_ts = 213.631470
current_received_ts = 213.630920
current_seq = 252
count = 248
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 102us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.631470
last_received_ts = 213.630920
last_seq = 252
current_ts = 213.648132
current_received_ts = 213.647583
current_seq = 253
count = 249
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 78us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.648132
last_received_ts = 213.647583
last_seq = 253
current_ts = 213.664795
current_received_ts = 213.664230
current_seq = 254
count = 250
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.664795
last_received_ts = 213.664230
last_seq = 254
current_ts = 213.681473
current_received_ts = 213.680923
current_seq = 255
count = 251
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 104us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.681473
last_received_ts = 213.680923
last_seq = 255
current_ts = 213.698120
current_received_ts = 213.697586
current_seq = 256
count = 252
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.698120
last_received_ts = 213.697586
last_seq = 256
current_ts = 213.714798
current_received_ts = 213.714249
current_seq = 257
count = 253
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 120us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.714798
last_received_ts = 213.714249
last_seq = 257
current_ts = 213.731461
current_received_ts = 213.730911
current_seq = 258
count = 254
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 94us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.731461
last_received_ts = 213.730911
last_seq = 258
current_ts = 213.748123
current_received_ts = 213.747574
current_seq = 259
count = 255
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 56us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.748123
last_received_ts = 213.747574
last_seq = 259
current_ts = 213.764786
current_received_ts = 213.764160
current_seq = 260
count = 256
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 71us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.764786
last_received_ts = 213.764160
last_seq = 260
current_ts = 213.781448
current_received_ts = 213.780914
current_seq = 261
count = 257
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 98us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.781448
last_received_ts = 213.780914
last_seq = 261
current_ts = 213.798126
current_received_ts = 213.797577
current_seq = 262
count = 258
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 81us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.798126
last_received_ts = 213.797577
last_seq = 262
current_ts = 213.814789
current_received_ts = 213.814240
current_seq = 263
count = 259
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 101us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.814789
last_received_ts = 213.814240
last_seq = 263
current_ts = 213.831451
current_received_ts = 213.830933
current_seq = 264
count = 260
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 145us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.831451
last_received_ts = 213.830933
last_seq = 264
current_ts = 213.848114
current_received_ts = 213.847580
current_seq = 265
count = 261
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.848114
last_received_ts = 213.847580
last_seq = 265
current_ts = 213.864777
current_received_ts = 213.864227
current_seq = 266
count = 262
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.864777
last_received_ts = 213.864227
last_seq = 266
current_ts = 213.881439
current_received_ts = 213.880890
current_seq = 267
count = 263
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 79us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.881439
last_received_ts = 213.880890
last_seq = 267
current_ts = 213.898117
current_received_ts = 213.897598
current_seq = 268
count = 264
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 58us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.898117
last_received_ts = 213.897598
last_seq = 268
current_ts = 213.914780
current_received_ts = 213.914230
current_seq = 269
count = 265
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 76us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.914780
last_received_ts = 213.914230
last_seq = 269
current_ts = 213.931442
current_received_ts = 213.930878
current_seq = 270
count = 266
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 85us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.931442
last_received_ts = 213.930878
last_seq = 270
current_ts = 213.948105
current_received_ts = 213.947571
current_seq = 271
count = 267
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 72us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.948105
last_received_ts = 213.947571
last_seq = 271
current_ts = 213.964767
current_received_ts = 213.964218
current_seq = 272
count = 268
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 118us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.964767
last_received_ts = 213.964218
last_seq = 272
current_ts = 213.981445
current_received_ts = 213.980881
current_seq = 273
count = 269
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 80us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.981445
last_received_ts = 213.980881
last_seq = 273
current_ts = 213.998108
current_received_ts = 213.997528
current_seq = 274
count = 270
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 78us
(kms_flip:6433) DEBUG: name = flip
last_ts = 213.998108
last_received_ts = 213.997528
last_seq = 274
current_ts = 214.014771
current_received_ts = 214.014175
current_seq = 275
count = 271
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 71us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.014771
last_received_ts = 214.014175
last_seq = 275
current_ts = 214.031433
current_received_ts = 214.030884
current_seq = 276
count = 272
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 76us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.031433
last_received_ts = 214.030884
last_seq = 276
current_ts = 214.048096
current_received_ts = 214.047546
current_seq = 277
count = 273
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 71us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.048096
last_received_ts = 214.047546
last_seq = 277
current_ts = 214.064774
current_received_ts = 214.064209
current_seq = 278
count = 274
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 71us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.064774
last_received_ts = 214.064209
last_seq = 278
current_ts = 214.081436
current_received_ts = 214.080887
current_seq = 279
count = 275
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 71us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.081436
last_received_ts = 214.080887
last_seq = 279
current_ts = 214.098099
current_received_ts = 214.097534
current_seq = 280
count = 276
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 87us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.098099
last_received_ts = 214.097534
last_seq = 280
current_ts = 214.114761
current_received_ts = 214.114197
current_seq = 281
count = 277
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 81us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.114761
last_received_ts = 214.114197
last_seq = 281
current_ts = 214.131424
current_received_ts = 214.130890
current_seq = 282
count = 278
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 52us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.131424
last_received_ts = 214.130890
last_seq = 282
current_ts = 214.148102
current_received_ts = 214.147537
current_seq = 283
count = 279
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 74us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.148102
last_received_ts = 214.147537
last_seq = 283
current_ts = 214.164764
current_received_ts = 214.164185
current_seq = 284
count = 280
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 73us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.164764
last_received_ts = 214.164185
last_seq = 284
current_ts = 214.181427
current_received_ts = 214.180878
current_seq = 285
count = 281
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 88us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.181427
last_received_ts = 214.180878
last_seq = 285
current_ts = 214.198090
current_received_ts = 214.197556
current_seq = 286
count = 282
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 79us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.198090
last_received_ts = 214.197556
last_seq = 286
current_ts = 214.214752
current_received_ts = 214.214218
current_seq = 287
count = 283
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 81us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.214752
last_received_ts = 214.214218
last_seq = 287
current_ts = 214.231415
current_received_ts = 214.230865
current_seq = 288
count = 284
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 72us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.231415
last_received_ts = 214.230865
last_seq = 288
current_ts = 214.248093
current_received_ts = 214.247528
current_seq = 289
count = 285
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 76us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.248093
last_received_ts = 214.247528
last_seq = 289
current_ts = 214.264740
current_received_ts = 214.264236
current_seq = 290
count = 286
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 113us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.264740
last_received_ts = 214.264236
last_seq = 290
current_ts = 214.281418
current_received_ts = 214.280869
current_seq = 291
count = 287
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 86us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.281418
last_received_ts = 214.280869
last_seq = 291
current_ts = 214.298080
current_received_ts = 214.297501
current_seq = 292
count = 288
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.298080
last_received_ts = 214.297501
last_seq = 292
current_ts = 214.314743
current_received_ts = 214.314178
current_seq = 293
count = 289
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 72us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.314743
last_received_ts = 214.314178
last_seq = 293
current_ts = 214.331406
current_received_ts = 214.330841
current_seq = 294
count = 290
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 87us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.331406
last_received_ts = 214.330841
last_seq = 294
current_ts = 214.348068
current_received_ts = 214.347519
current_seq = 295
count = 291
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 52us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.348068
last_received_ts = 214.347519
last_seq = 295
current_ts = 214.364731
current_received_ts = 214.364182
current_seq = 296
count = 292
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 89us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.364731
last_received_ts = 214.364182
last_seq = 296
current_ts = 214.381409
current_received_ts = 214.380844
current_seq = 297
count = 293
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 72us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.381409
last_received_ts = 214.380844
last_seq = 297
current_ts = 214.398071
current_received_ts = 214.397537
current_seq = 298
count = 294
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 87us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.398071
last_received_ts = 214.397537
last_seq = 298
current_ts = 214.414734
current_received_ts = 214.414246
current_seq = 299
count = 295
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 110us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.414734
last_received_ts = 214.414246
last_seq = 299
current_ts = 214.431396
current_received_ts = 214.430878
current_seq = 300
count = 296
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 81us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.431396
last_received_ts = 214.430878
last_seq = 300
current_ts = 214.448059
current_received_ts = 214.447556
current_seq = 301
count = 297
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 76us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.448059
last_received_ts = 214.447556
last_seq = 301
current_ts = 214.464722
current_received_ts = 214.464157
current_seq = 302
count = 298
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.464722
last_received_ts = 214.464157
last_seq = 302
current_ts = 214.481400
current_received_ts = 214.480865
current_seq = 303
count = 299
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 72us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.481400
last_received_ts = 214.480865
last_seq = 303
current_ts = 214.498062
current_received_ts = 214.497513
current_seq = 304
count = 300
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 86us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.498062
last_received_ts = 214.497513
last_seq = 304
current_ts = 214.514725
current_received_ts = 214.514221
current_seq = 305
count = 301
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 78us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.514725
last_received_ts = 214.514221
last_seq = 305
current_ts = 214.531387
current_received_ts = 214.530869
current_seq = 306
count = 302
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.531387
last_received_ts = 214.530869
last_seq = 306
current_ts = 214.548050
current_received_ts = 214.547516
current_seq = 307
count = 303
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 77us
(kms_flip:6433) DEBUG: name = flip
last_ts = 214.548050
last_received_ts = 214.547516
last_seq = 307
current_ts = 214.564713
current_received_ts = 214.564163
current_seq = 308
count = 304
seq_step = 1
(kms_flip:6433) DEBUG: Vblank took 1324us
(kms_flip:6433) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:6433) CRITICAL: Failed assertion: end - start < 500
(kms_flip:6433) igt_core-INFO: Stack trace:
(kms_flip:6433) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:6433) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:6433) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:6433) igt_core-INFO:   #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
(kms_flip:6433) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:6433) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:6433) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:6433) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (6.434s)

Dmesg

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

<7> [239.589799] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:241]

<7> [239.591011] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:244]

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

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

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

<7> [239.671148] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:88:pipe A]

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

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

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

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

<7> [239.672448] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88: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> [239.672662] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [239.963078] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:88:pipe A]

<7> [239.963522] 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> [239.963977] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

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

<7> [239.965159] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B]

<7> [239.965554] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C]

<7> [239.965854] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B]

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

<7> [239.966108] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:205:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)

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

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

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

<7> [239.967671] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:204:DDI A/PHY A] [CRTC:145:pipe B]

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

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

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

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

<7> [239.969478] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145: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> [239.969782] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [239.975559] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in dpll_hw_state.cx0pll C20

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

<7> [239.975814] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c20pll_hw_state:

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

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

<7> [239.976201] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[0] = 0x0000

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

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

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

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

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

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

<7> [239.977062] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[7] = 0x0000

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

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

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

<7> [239.977468] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_hw_state: fracen: no,

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

<7> [239.977653] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_rawhw_state:

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [239.978895] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:90:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

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

<7> [239.979032] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90: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> [239.979089] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 12, 13, 0, 0, 0, 4, 0

<7> [239.979145] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 274, 297, 0, 0, 197, 92, 197

<7> [239.979199] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 365, 456, 0, 0, 198, 183, 198

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

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

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

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

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

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

<7> [239.979755] xe 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [xe]] [PLANE:90:plane 1B] min cdclk (173855 kHz) > [CRTC:145:pipe B] min cdclk (0 kHz)

<7> [239.979815] xe 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [xe]] new bandwidth min cdclk (27165 kHz) > old min cdclk (0 kHz)

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

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

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

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

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

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

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

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

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

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

<7> [239.980645] 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> [239.980717] 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> [239.980789] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

<7> [239.980997] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0

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

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

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

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

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

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

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

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

<7> [239.981626] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0

<7> [239.981691] 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: 106 vsync start: 103, vsync end: 97

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

<7> [239.981821] 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> [239.981887] 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> [239.981951] 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> [239.982016] 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> [239.982079] 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> [239.982143] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710

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

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

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

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

<7> [239.982503] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0x69780, dpll_md: 0x42110, fp0: 0x1a2, fp1: 0x1000000

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [239.984854] 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> [239.984937] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [240.729245] 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> [240.730501] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Reloading eDP link rates

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [240.756713] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:145:pipe B]

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

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

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

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

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

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

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