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

Detail	Value
Duration	7.28 seconds
Hostname	shard-lnl-3
Igt-Version	IGT-Version: 2.4-gd34395a7e (x86_64) (Linux: 7.1.0-rc6-lgci-xe-xe-pw-167724v1-debug+ x86_64)
Out	Using IGT_SRANDOM=1780413070 for randomisation Opened device: /dev/dri/card0 Using monotonic timestamps Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2106 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-eDP1: FAIL (7.278s)
Err	Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 [376.108249] (kms_flip:7266) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [376.108400] (kms_flip:7266) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest A-eDP1 failed. ** DEBUG [374.090747] (kms_flip:7266) DEBUG: name = flip last_ts = 375.481750 last_received_ts = 375.480957 last_seq = 3394 current_ts = 375.498413 current_received_ts = 375.497620 current_seq = 3395 count = 234 seq_step = 1 [374.090815] (kms_flip:7266) DEBUG: Vblank took 62us [374.107408] (kms_flip:7266) DEBUG: name = flip last_ts = 375.498413 last_received_ts = 375.497620 last_seq = 3395 current_ts = 375.515106 current_received_ts = 375.514282 current_seq = 3396 count = 235 seq_step = 1 [374.107479] (kms_flip:7266) DEBUG: Vblank took 64us [374.124076] (kms_flip:7266) DEBUG: name = flip last_ts = 375.515106 last_received_ts = 375.514282 last_seq = 3396 current_ts = 375.531769 current_received_ts = 375.530945 current_seq = 3397 count = 236 seq_step = 1 [374.124164] (kms_flip:7266) DEBUG: Vblank took 83us [374.140741] (kms_flip:7266) DEBUG: name = flip last_ts = 375.531769 last_received_ts = 375.530945 last_seq = 3397 current_ts = 375.548431 current_received_ts = 375.547607 current_seq = 3398 count = 237 seq_step = 1 [374.140809] (kms_flip:7266) DEBUG: Vblank took 63us [374.157397] (kms_flip:7266) DEBUG: name = flip last_ts = 375.548431 last_received_ts = 375.547607 last_seq = 3398 current_ts = 375.565094 current_received_ts = 375.564270 current_seq = 3399 count = 238 seq_step = 1 [374.157465] (kms_flip:7266) DEBUG: Vblank took 61us [374.174071] (kms_flip:7266) DEBUG: name = flip last_ts = 375.565094 last_received_ts = 375.564270 last_seq = 3399 current_ts = 375.581757 current_received_ts = 375.580963 current_seq = 3400 count = 239 seq_step = 1 [374.174157] (kms_flip:7266) DEBUG: Vblank took 79us [374.190734] (kms_flip:7266) DEBUG: name = flip last_ts = 375.581757 last_received_ts = 375.580963 last_seq = 3400 current_ts = 375.598419 current_received_ts = 375.597626 current_seq = 3401 count = 240 seq_step = 1 [374.190802] (kms_flip:7266) DEBUG: Vblank took 62us [374.207399] (kms_flip:7266) DEBUG: name = flip last_ts = 375.598419 last_received_ts = 375.597626 last_seq = 3401 current_ts = 375.615082 current_received_ts = 375.614288 current_seq = 3402 count = 241 seq_step = 1 [374.207469] (kms_flip:7266) DEBUG: Vblank took 65us [374.224061] (kms_flip:7266) DEBUG: name = flip last_ts = 375.615082 last_received_ts = 375.614288 last_seq = 3402 current_ts = 375.631744 current_received_ts = 375.630951 current_seq = 3403 count = 242 seq_step = 1 [374.224149] (kms_flip:7266) DEBUG: Vblank took 82us [374.240726] (kms_flip:7266) DEBUG: name = flip last_ts = 375.631744 last_received_ts = 375.630951 last_seq = 3403 current_ts = 375.648407 current_received_ts = 375.647614 current_seq = 3404 count = 243 seq_step = 1 [374.240795] (kms_flip:7266) DEBUG: Vblank took 63us [374.257385] (kms_flip:7266) DEBUG: name = flip last_ts = 375.648407 last_received_ts = 375.647614 last_seq = 3404 current_ts = 375.665070 current_received_ts = 375.664276 current_seq = 3405 count = 244 seq_step = 1 [374.257454] (kms_flip:7266) DEBUG: Vblank took 63us [374.274053] (kms_flip:7266) DEBUG: name = flip last_ts = 375.665070 last_received_ts = 375.664276 last_seq = 3405 current_ts = 375.681732 current_received_ts = 375.680939 current_seq = 3406 count = 245 seq_step = 1 [374.274141] (kms_flip:7266) DEBUG: Vblank took 82us [374.290720] (kms_flip:7266) DEBUG: name = flip last_ts = 375.681732 last_received_ts = 375.680939 last_seq = 3406 current_ts = 375.698395 current_received_ts = 375.697601 current_seq = 3407 count = 246 seq_step = 1 [374.290789] (kms_flip:7266) DEBUG: Vblank took 64us [374.307377] (kms_flip:7266) DEBUG: name = flip last_ts = 375.698395 last_received_ts = 375.697601 last_seq = 3407 current_ts = 375.715057 current_received_ts = 375.714264 current_seq = 3408 count = 247 seq_step = 1 [374.307445] (kms_flip:7266) DEBUG: Vblank took 63us [374.324050] (kms_flip:7266) DEBUG: name = flip last_ts = 375.715057 last_received_ts = 375.714264 last_seq = 3408 current_ts = 375.731720 current_received_ts = 375.730927 current_seq = 3409 count = 248 seq_step = 1 [374.324145] (kms_flip:7266) DEBUG: Vblank took 89us [374.340712] (kms_flip:7266) DEBUG: name = flip last_ts = 375.731720 last_received_ts = 375.730927 last_seq = 3409 current_ts = 375.748383 current_received_ts = 375.747589 current_seq = 3410 count = 249 seq_step = 1 [374.340779] (kms_flip:7266) DEBUG: Vblank took 63us [374.357365] (kms_flip:7266) DEBUG: name = flip last_ts = 375.748383 last_received_ts = 375.747589 last_seq = 3410 current_ts = 375.765045 current_received_ts = 375.764252 current_seq = 3411 count = 250 seq_step = 1 [374.357435] (kms_flip:7266) DEBUG: Vblank took 65us [374.374055] (kms_flip:7266) DEBUG: name = flip last_ts = 375.765045 last_received_ts = 375.764252 last_seq = 3411 current_ts = 375.781738 current_received_ts = 375.780945 current_seq = 3412 count = 251 seq_step = 1 [374.374155] (kms_flip:7266) DEBUG: Vblank took 94us [374.390700] (kms_flip:7266) DEBUG: name = flip last_ts = 375.781738 last_received_ts = 375.780945 last_seq = 3412 current_ts = 375.798401 current_received_ts = 375.797577 current_seq = 3413 count = 252 seq_step = 1 [374.390768] (kms_flip:7266) DEBUG: Vblank took 62us [374.407370] (kms_flip:7266) DEBUG: name = flip last_ts = 375.798401 last_received_ts = 375.797577 last_seq = 3413 current_ts = 375.815063 current_received_ts = 375.814240 current_seq = 3414 count = 253 seq_step = 1 [374.407441] (kms_flip:7266) DEBUG: Vblank took 65us [374.424026] (kms_flip:7266) DEBUG: name = flip last_ts = 375.815063 last_received_ts = 375.814240 last_seq = 3414 current_ts = 375.831726 current_received_ts = 375.830902 current_seq = 3415 count = 254 seq_step = 1 [374.424094] (kms_flip:7266) DEBUG: Vblank took 62us [374.440696] (kms_flip:7266) DEBUG: name = flip last_ts = 375.831726 last_received_ts = 375.830902 last_seq = 3415 current_ts = 375.848389 current_received_ts = 375.847595 current_seq = 3416 count = 255 seq_step = 1 [374.440764] (kms_flip:7266) DEBUG: Vblank took 63us [374.457348] (kms_flip:7266) DEBUG: name = flip last_ts = 375.848389 last_received_ts = 375.847595 last_seq = 3416 current_ts = 375.865051 current_received_ts = 375.864227 current_seq = 3417 count = 256 seq_step = 1 [374.457416] (kms_flip:7266) DEBUG: Vblank took 62us [374.474019] (kms_flip:7266) DEBUG: name = flip last_ts = 375.865051 last_received_ts = 375.864227 last_seq = 3417 current_ts = 375.881714 current_received_ts = 375.880890 current_seq = 3418 count = 257 seq_step = 1 [374.474087] (kms_flip:7266) DEBUG: Vblank took 62us [374.490687] (kms_flip:7266) DEBUG: name = flip last_ts = 375.881714 last_received_ts = 375.880890 last_seq = 3418 current_ts = 375.898376 current_received_ts = 375.897583 current_seq = 3419 count = 258 seq_step = 1 [374.490756] (kms_flip:7266) DEBUG: Vblank took 63us [374.507342] (kms_flip:7266) DEBUG: name = flip last_ts = 375.898376 last_received_ts = 375.897583 last_seq = 3419 current_ts = 375.915039 current_received_ts = 375.914215 current_seq = 3420 count = 259 seq_step = 1 [374.507411] (kms_flip:7266) DEBUG: Vblank took 64us [374.524013] (kms_flip:7266) DEBUG: name = flip last_ts = 375.915039 last_received_ts = 375.914215 last_seq = 3420 current_ts = 375.931702 current_received_ts = 375.930908 current_seq = 3421 count = 260 seq_step = 1 [374.524081] (kms_flip:7266) DEBUG: Vblank took 62us [374.540679] (kms_flip:7266) DEBUG: name = flip last_ts = 375.931702 last_received_ts = 375.930908 last_seq = 3421 current_ts = 375.948364 current_received_ts = 375.947571 current_seq = 3422 count = 261 seq_step = 1 [374.540747] (kms_flip:7266) DEBUG: Vblank took 62us [374.557333] (kms_flip:7266) DEBUG: name = flip last_ts = 375.948364 last_received_ts = 375.947571 last_seq = 3422 current_ts = 375.965027 current_received_ts = 375.964233 current_seq = 3423 count = 262 seq_step = 1 [374.557401] (kms_flip:7266) DEBUG: Vblank took 62us [374.574004] (kms_flip:7266) DEBUG: name = flip last_ts = 375.965027 last_received_ts = 375.964233 last_seq = 3423 current_ts = 375.981689 current_received_ts = 375.980896 current_seq = 3424 count = 263 seq_step = 1 [374.574073] (kms_flip:7266) DEBUG: Vblank took 63us [374.590671] (kms_flip:7266) DEBUG: name = flip last_ts = 375.981689 last_received_ts = 375.980896 last_seq = 3424 current_ts = 375.998352 current_received_ts = 375.997559 current_seq = 3425 count = 264 seq_step = 1 [374.590740] (kms_flip:7266) DEBUG: Vblank took 62us [374.607326] (kms_flip:7266) DEBUG: name = flip last_ts = 375.998352 last_received_ts = 375.997559 last_seq = 3425 current_ts = 376.015015 current_received_ts = 376.014221 current_seq = 3426 count = 265 seq_step = 1 [374.607394] (kms_flip:7266) DEBUG: Vblank took 62us [374.623996] (kms_flip:7266) DEBUG: name = flip last_ts = 376.015015 last_received_ts = 376.014221 last_seq = 3426 current_ts = 376.031677 current_received_ts = 376.030884 current_seq = 3427 count = 266 seq_step = 1 [374.624063] (kms_flip:7266) DEBUG: Vblank took 62us [374.640659] (kms_flip:7266) DEBUG: name = flip last_ts = 376.031677 last_received_ts = 376.030884 last_seq = 3427 current_ts = 376.048340 current_received_ts = 376.047546 current_seq = 3428 count = 267 seq_step = 1 [374.640728] (kms_flip:7266) DEBUG: Vblank took 62us [374.657325] (kms_flip:7266) DEBUG: name = flip last_ts = 376.048340 last_received_ts = 376.047546 last_seq = 3428 current_ts = 376.065033 current_received_ts = 376.064209 current_seq = 3429 count = 268 seq_step = 1 [374.657392] (kms_flip:7266) DEBUG: Vblank took 62us [374.673983] (kms_flip:7266) DEBUG: name = flip last_ts = 376.065033 last_received_ts = 376.064209 last_seq = 3429 current_ts = 376.081665 current_received_ts = 376.080872 current_seq = 3430 count = 269 seq_step = 1 [374.674050] (kms_flip:7266) DEBUG: Vblank took 61us [374.690653] (kms_flip:7266) DEBUG: name = flip last_ts = 376.081665 last_received_ts = 376.080872 last_seq = 3430 current_ts = 376.098358 current_received_ts = 376.097534 current_seq = 3431 count = 270 seq_step = 1 [374.690722] (kms_flip:7266) DEBUG: Vblank took 62us [374.707306] (kms_flip:7266) DEBUG: name = flip last_ts = 376.098358 last_received_ts = 376.097534 last_seq = 3431 current_ts = 376.115021 current_received_ts = 376.114197 current_seq = 3432 count = 271 seq_step = 1 [374.707376] (kms_flip:7266) DEBUG: Vblank took 63us [374.723984] (kms_flip:7266) DEBUG: name = flip last_ts = 376.115021 last_received_ts = 376.114197 last_seq = 3432 current_ts = 376.131683 current_received_ts = 376.130859 current_seq = 3433 count = 272 seq_step = 1 [374.724053] (kms_flip:7266) DEBUG: Vblank took 64us [374.740655] (kms_flip:7266) DEBUG: name = flip last_ts = 376.131683 last_received_ts = 376.130859 last_seq = 3433 current_ts = 376.148346 current_received_ts = 376.147552 current_seq = 3434 count = 273 seq_step = 1 [374.740731] (kms_flip:7266) DEBUG: Vblank took 70us [374.757314] (kms_flip:7266) DEBUG: name = flip last_ts = 376.148346 last_received_ts = 376.147552 last_seq = 3434 current_ts = 376.165009 current_received_ts = 376.164215 current_seq = 3435 count = 274 seq_step = 1 [374.757389] (kms_flip:7266) DEBUG: Vblank took 69us [374.773975] (kms_flip:7266) DEBUG: name = flip last_ts = 376.165009 last_received_ts = 376.164215 last_seq = 3435 current_ts = 376.181671 current_received_ts = 376.180878 current_seq = 3436 count = 275 seq_step = 1 [374.774043] (kms_flip:7266) DEBUG: Vblank took 63us [374.790636] (kms_flip:7266) DEBUG: name = flip last_ts = 376.181671 last_received_ts = 376.180878 last_seq = 3436 current_ts = 376.198334 current_received_ts = 376.197540 current_seq = 3437 count = 276 seq_step = 1 [374.790704] (kms_flip:7266) DEBUG: Vblank took 63us [374.807294] (kms_flip:7266) DEBUG: name = flip last_ts = 376.198334 last_received_ts = 376.197540 last_seq = 3437 current_ts = 376.214996 current_received_ts = 376.214172 current_seq = 3438 count = 277 seq_step = 1 [374.807362] (kms_flip:7266) DEBUG: Vblank took 63us [374.823963] (kms_flip:7266) DEBUG: name = flip last_ts = 376.214996 last_received_ts = 376.214172 last_seq = 3438 current_ts = 376.231659 current_received_ts = 376.230865 current_seq = 3439 count = 278 seq_step = 1 [374.824032] (kms_flip:7266) DEBUG: Vblank took 62us [374.840630] (kms_flip:7266) DEBUG: name = flip last_ts = 376.231659 last_received_ts = 376.230865 last_seq = 3439 current_ts = 376.248322 current_received_ts = 376.247528 current_seq = 3440 count = 279 seq_step = 1 [374.840699] (kms_flip:7266) DEBUG: Vblank took 63us [374.857286] (kms_flip:7266) DEBUG: name = flip last_ts = 376.248322 last_received_ts = 376.247528 last_seq = 3440 current_ts = 376.264984 current_received_ts = 376.264191 current_seq = 3441 count = 280 seq_step = 1 [374.857355] (kms_flip:7266) DEBUG: Vblank took 63us [374.873956] (kms_flip:7266) DEBUG: name = flip last_ts = 376.264984 last_received_ts = 376.264191 last_seq = 3441 current_ts = 376.281647 current_received_ts = 376.280853 current_seq = 3442 count = 281 seq_step = 1 [374.874026] (kms_flip:7266) DEBUG: Vblank took 65us [374.890631] (kms_flip:7266) DEBUG: name = flip last_ts = 376.281647 last_received_ts = 376.280853 last_seq = 3442 current_ts = 376.298309 current_received_ts = 376.297516 current_seq = 3443 count = 282 seq_step = 1 [374.890687] (kms_flip:7266) DEBUG: Vblank took 50us [374.907293] (kms_flip:7266) DEBUG: name = flip last_ts = 376.298309 last_received_ts = 376.297516 last_seq = 3443 current_ts = 376.314972 current_received_ts = 376.314178 current_seq = 3444 count = 283 seq_step = 1 [374.907370] (kms_flip:7266) DEBUG: Vblank took 69us [374.923958] (kms_flip:7266) DEBUG: name = flip last_ts = 376.314972 last_received_ts = 376.314178 last_seq = 3444 current_ts = 376.331635 current_received_ts = 376.330841 current_seq = 3445 count = 284 seq_step = 1 [374.924036] (kms_flip:7266) DEBUG: Vblank took 72us [374.940622] (kms_flip:7266) DEBUG: name = flip last_ts = 376.331635 last_received_ts = 376.330841 last_seq = 3445 current_ts = 376.348297 current_received_ts = 376.347504 current_seq = 3446 count = 285 seq_step = 1 [374.940696] (kms_flip:7266) DEBUG: Vblank took 68us [374.957272] (kms_flip:7266) DEBUG: name = flip last_ts = 376.348297 last_received_ts = 376.347504 last_seq = 3446 current_ts = 376.364990 current_received_ts = 376.364166 current_seq = 3447 count = 286 seq_step = 1 [374.957341] (kms_flip:7266) DEBUG: Vblank took 63us [374.973942] (kms_flip:7266) DEBUG: name = flip last_ts = 376.364990 last_received_ts = 376.364166 last_seq = 3447 current_ts = 376.381653 current_received_ts = 376.380829 current_seq = 3448 count = 287 seq_step = 1 [374.974009] (kms_flip:7266) DEBUG: Vblank took 62us [374.990602] (kms_flip:7266) DEBUG: name = flip last_ts = 376.381653 last_received_ts = 376.380829 last_seq = 3448 current_ts = 376.398315 current_received_ts = 376.397491 current_seq = 3449 count = 288 seq_step = 1 [374.990669] (kms_flip:7266) DEBUG: Vblank took 62us [375.007264] (kms_flip:7266) DEBUG: name = flip last_ts = 376.398315 last_received_ts = 376.397491 last_seq = 3449 current_ts = 376.414978 current_received_ts = 376.414154 current_seq = 3450 count = 289 seq_step = 1 [375.007332] (kms_flip:7266) DEBUG: Vblank took 62us [375.023933] (kms_flip:7266) DEBUG: name = flip last_ts = 376.414978 last_received_ts = 376.414154 last_seq = 3450 current_ts = 376.431641 current_received_ts = 376.430817 current_seq = 3451 count = 290 seq_step = 1 [375.024001] (kms_flip:7266) DEBUG: Vblank took 63us [375.040609] (kms_flip:7266) DEBUG: name = flip last_ts = 376.431641 last_received_ts = 376.430817 last_seq = 3451 current_ts = 376.448303 current_received_ts = 376.447510 current_seq = 3452 count = 291 seq_step = 1 [375.040684] (kms_flip:7266) DEBUG: Vblank took 68us [375.057264] (kms_flip:7266) DEBUG: name = flip last_ts = 376.448303 last_received_ts = 376.447510 last_seq = 3452 current_ts = 376.464966 current_received_ts = 376.464172 current_seq = 3453 count = 292 seq_step = 1 [375.057339] (kms_flip:7266) DEBUG: Vblank took 68us [375.073925] (kms_flip:7266) DEBUG: name = flip last_ts = 376.464966 last_received_ts = 376.464172 last_seq = 3453 current_ts = 376.481628 current_received_ts = 376.480835 current_seq = 3454 count = 293 seq_step = 1 [375.073992] (kms_flip:7266) DEBUG: Vblank took 62us [375.090589] (kms_flip:7266) DEBUG: name = flip last_ts = 376.481628 last_received_ts = 376.480835 last_seq = 3454 current_ts = 376.498291 current_received_ts = 376.497498 current_seq = 3455 count = 294 seq_step = 1 [375.090657] (kms_flip:7266) DEBUG: Vblank took 63us [375.107251] (kms_flip:7266) DEBUG: name = flip last_ts = 376.498291 last_received_ts = 376.497498 last_seq = 3455 current_ts = 376.514954 current_received_ts = 376.514160 current_seq = 3456 count = 295 seq_step = 1 [375.107318] (kms_flip:7266) DEBUG: Vblank took 61us [375.123926] (kms_flip:7266) DEBUG: name = flip last_ts = 376.514954 last_received_ts = 376.514160 last_seq = 3456 current_ts = 376.531616 current_received_ts = 376.530823 current_seq = 3457 count = 296 seq_step = 1 [375.124001] (kms_flip:7266) DEBUG: Vblank took 69us [375.140592] (kms_flip:7266) DEBUG: name = flip last_ts = 376.531616 last_received_ts = 376.530823 last_seq = 3457 current_ts = 376.548279 current_received_ts = 376.547485 current_seq = 3458 count = 297 seq_step = 1 [375.140666] (kms_flip:7266) DEBUG: Vblank took 67us [375.157243] (kms_flip:7266) DEBUG: name = flip last_ts = 376.548279 last_received_ts = 376.547485 last_seq = 3458 current_ts = 376.564941 current_received_ts = 376.564148 current_seq = 3459 count = 298 seq_step = 1 [375.157312] (kms_flip:7266) DEBUG: Vblank took 63us [375.173906] (kms_flip:7266) DEBUG: name = flip last_ts = 376.564941 last_received_ts = 376.564148 last_seq = 3459 current_ts = 376.581604 current_received_ts = 376.580811 current_seq = 3460 count = 299 seq_step = 1 [375.173976] (kms_flip:7266) DEBUG: Vblank took 64us [375.190584] (kms_flip:7266) DEBUG: name = flip last_ts = 376.581604 last_received_ts = 376.580811 last_seq = 3460 current_ts = 376.598267 current_received_ts = 376.597473 current_seq = 3461 count = 300 seq_step = 1 [375.190657] (kms_flip:7266) DEBUG: Vblank took 68us [375.207241] (kms_flip:7266) DEBUG: name = flip last_ts = 376.598267 last_received_ts = 376.597473 last_seq = 3461 current_ts = 376.614960 current_received_ts = 376.614136 current_seq = 3462 count = 301 seq_step = 1 [375.207315] (kms_flip:7266) DEBUG: Vblank took 67us [375.223908] (kms_flip:7266) DEBUG: name = flip last_ts = 376.614960 last_received_ts = 376.614136 last_seq = 3462 current_ts = 376.631592 current_received_ts = 376.630798 current_seq = 3463 count = 302 seq_step = 1 [375.223983] (kms_flip:7266) DEBUG: Vblank took 68us [375.240571] (kms_flip:7266) DEBUG: name = flip last_ts = 376.631592 last_received_ts = 376.630798 last_seq = 3463 current_ts = 376.648254 current_received_ts = 376.647461 current_seq = 3464 count = 303 seq_step = 1 [375.240645] (kms_flip:7266) DEBUG: Vblank took 69us [375.257227] (kms_flip:7266) DEBUG: name = flip last_ts = 376.648254 last_received_ts = 376.647461 last_seq = 3464 current_ts = 376.664917 current_received_ts = 376.664124 current_seq = 3465 count = 304 seq_step = 1 [375.257295] (kms_flip:7266) DEBUG: Vblank took 62us [375.273901] (kms_flip:7266) DEBUG: name = flip last_ts = 376.664917 last_received_ts = 376.664124 last_seq = 3465 current_ts = 376.681610 current_received_ts = 376.680786 current_seq = 3466 count = 305 seq_step = 1 [375.273976] (kms_flip:7266) DEBUG: Vblank took 68us [375.290565] (kms_flip:7266) DEBUG: name = flip last_ts = 376.681610 last_received_ts = 376.680786 last_seq = 3466 current_ts = 376.698273 current_received_ts = 376.697479 current_seq = 3467 count = 306 seq_step = 1 [375.290639] (kms_flip:7266) DEBUG: Vblank took 68us [375.307234] (kms_flip:7266) DEBUG: name = flip last_ts = 376.698273 last_received_ts = 376.697479 last_seq = 3467 current_ts = 376.714935 current_received_ts = 376.714142 current_seq = 3468 count = 307 seq_step = 1 [375.307309] (kms_flip:7266) DEBUG: Vblank took 69us [375.323896] (kms_flip:7266) DEBUG: name = flip last_ts = 376.714935 last_received_ts = 376.714142 last_seq = 3468 current_ts = 376.731598 current_received_ts = 376.730804 current_seq = 3469 count = 308 seq_step = 1 [375.323971] (kms_flip:7266) DEBUG: Vblank took 69us [375.340558] (kms_flip:7266) DEBUG: name = flip last_ts = 376.731598 last_received_ts = 376.730804 last_seq = 3469 current_ts = 376.748260 current_received_ts = 376.747467 current_seq = 3470 count = 309 seq_step = 1 [375.340632] (kms_flip:7266) DEBUG: Vblank took 67us [375.357223] (kms_flip:7266) DEBUG: name = flip last_ts = 376.748260 last_received_ts = 376.747467 last_seq = 3470 current_ts = 376.764923 current_received_ts = 376.764130 current_seq = 3471 count = 310 seq_step = 1 [375.357297] (kms_flip:7266) DEBUG: Vblank took 69us [375.373887] (kms_flip:7266) DEBUG: name = flip last_ts = 376.764923 last_received_ts = 376.764130 last_seq = 3471 current_ts = 376.781586 current_received_ts = 376.780792 current_seq = 3472 count = 311 seq_step = 1 [375.373961] (kms_flip:7266) DEBUG: Vblank took 68us [375.390672] (kms_flip:7266) DEBUG: name = flip last_ts = 376.781586 last_received_ts = 376.780792 last_seq = 3472 current_ts = 376.798248 current_received_ts = 376.797546 current_seq = 3473 count = 312 seq_step = 1 [375.390757] (kms_flip:7266) DEBUG: Vblank took 61us [375.407263] (kms_flip:7266) DEBUG: name = flip last_ts = 376.798248 last_received_ts = 376.797546 last_seq = 3473 current_ts = 376.814911 current_received_ts = 376.814148 current_seq = 3474 count = 313 seq_step = 1 [375.407326] (kms_flip:7266) DEBUG: Vblank took 52us [375.423917] (kms_flip:7266) DEBUG: name = flip last_ts = 376.814911 last_received_ts = 376.814148 last_seq = 3474 current_ts = 376.831573 current_received_ts = 376.830811 current_seq = 3475 count = 314 seq_step = 1 [375.424014] (kms_flip:7266) DEBUG: Vblank took 86us [375.440559] (kms_flip:7266) DEBUG: name = flip last_ts = 376.831573 last_received_ts = 376.830811 last_seq = 3475 current_ts = 376.848236 current_received_ts = 376.847473 current_seq = 3476 count = 315 seq_step = 1 [375.440643] (kms_flip:7266) DEBUG: Vblank took 77us [375.457202] (kms_flip:7266) DEBUG: name = flip last_ts = 376.848236 last_received_ts = 376.847473 last_seq = 3476 current_ts = 376.864899 current_received_ts = 376.864105 current_seq = 3477 count = 316 seq_step = 1 [375.457272] (kms_flip:7266) DEBUG: Vblank took 65us [375.473854] (kms_flip:7266) DEBUG: name = flip last_ts = 376.864899 last_received_ts = 376.864105 last_seq = 3477 current_ts = 376.881561 current_received_ts = 376.880768 current_seq = 3478 count = 317 seq_step = 1 [375.473918] (kms_flip:7266) DEBUG: Vblank took 60us [375.490525] (kms_flip:7266) DEBUG: name = flip last_ts = 376.881561 last_received_ts = 376.880768 last_seq = 3478 current_ts = 376.898224 current_received_ts = 376.897430 current_seq = 3479 count = 318 seq_step = 1 [375.490597] (kms_flip:7266) DEBUG: Vblank took 67us [375.507191] (kms_flip:7266) DEBUG: name = flip last_ts = 376.898224 last_received_ts = 376.897430 last_seq = 3479 current_ts = 376.914886 current_received_ts = 376.914093 current_seq = 3480 count = 319 seq_step = 1 [375.507261] (kms_flip:7266) DEBUG: Vblank took 63us [375.523856] (kms_flip:7266) DEBUG: name = flip last_ts = 376.914886 last_received_ts = 376.914093 last_seq = 3480 current_ts = 376.931549 current_received_ts = 376.930756 current_seq = 3481 count = 320 seq_step = 1 [375.523926] (kms_flip:7266) DEBUG: Vblank took 64us [375.540509] (kms_flip:7266) DEBUG: name = flip last_ts = 376.931549 last_received_ts = 376.930756 last_seq = 3481 current_ts = 376.948242 current_received_ts = 376.947418 current_seq = 3482 count = 321 seq_step = 1 [375.540578] (kms_flip:7266) DEBUG: Vblank took 62us [375.557182] (kms_flip:7266) DEBUG: name = flip last_ts = 376.948242 last_received_ts = 376.947418 last_seq = 3482 current_ts = 376.964905 current_received_ts = 376.964081 current_seq = 3483 count = 322 seq_step = 1 [375.557252] (kms_flip:7266) DEBUG: Vblank took 64us [375.573847] (kms_flip:7266) DEBUG: name = flip last_ts = 376.964905 last_received_ts = 376.964081 last_seq = 3483 current_ts = 376.981567 current_received_ts = 376.980743 current_seq = 3484 count = 323 seq_step = 1 [375.573916] (kms_flip:7266) DEBUG: Vblank took 63us [375.590500] (kms_flip:7266) DEBUG: name = flip last_ts = 376.981567 last_received_ts = 376.980743 last_seq = 3484 current_ts = 376.998230 current_received_ts = 376.997406 current_seq = 3485 count = 324 seq_step = 1 [375.590569] (kms_flip:7266) DEBUG: Vblank took 63us [375.607173] (kms_flip:7266) DEBUG: name = flip last_ts = 376.998230 last_received_ts = 376.997406 last_seq = 3485 current_ts = 377.014893 current_received_ts = 377.014069 current_seq = 3486 count = 325 seq_step = 1 [375.607243] (kms_flip:7266) DEBUG: Vblank took 64us [375.623835] (kms_flip:7266) DEBUG: name = flip last_ts = 377.014893 last_received_ts = 377.014069 last_seq = 3486 current_ts = 377.031555 current_received_ts = 377.030731 current_seq = 3487 count = 326 seq_step = 1 [375.623903] (kms_flip:7266) DEBUG: Vblank took 62us [375.640491] (kms_flip:7266) DEBUG: name = flip last_ts = 377.031555 last_received_ts = 377.030731 last_seq = 3487 current_ts = 377.048218 current_received_ts = 377.047394 current_seq = 3488 count = 327 seq_step = 1 [375.640559] (kms_flip:7266) DEBUG: Vblank took 62us [375.657168] (kms_flip:7266) DEBUG: name = flip last_ts = 377.048218 last_received_ts = 377.047394 last_seq = 3488 current_ts = 377.064880 current_received_ts = 377.064087 current_seq = 3489 count = 328 seq_step = 1 [375.657237] (kms_flip:7266) DEBUG: Vblank took 64us [375.673830] (kms_flip:7266) DEBUG: name = flip last_ts = 377.064880 last_received_ts = 377.064087 last_seq = 3489 current_ts = 377.081543 current_received_ts = 377.080750 current_seq = 3490 count = 329 seq_step = 1 [375.673898] (kms_flip:7266) DEBUG: Vblank took 62us [375.690485] (kms_flip:7266) DEBUG: name = flip last_ts = 377.081543 last_received_ts = 377.080750 last_seq = 3490 current_ts = 377.098206 current_received_ts = 377.097382 current_seq = 3491 count = 330 seq_step = 1 [375.690554] (kms_flip:7266) DEBUG: Vblank took 63us [375.707166] (kms_flip:7266) DEBUG: name = flip last_ts = 377.098206 last_received_ts = 377.097382 last_seq = 3491 current_ts = 377.114868 current_received_ts = 377.114075 current_seq = 3492 count = 331 seq_step = 1 [375.707236] (kms_flip:7266) DEBUG: Vblank took 64us [375.723824] (kms_flip:7266) DEBUG: name = flip last_ts = 377.114868 last_received_ts = 377.114075 last_seq = 3492 current_ts = 377.131531 current_received_ts = 377.130737 current_seq = 3493 count = 332 seq_step = 1 [375.723896] (kms_flip:7266) DEBUG: Vblank took 66us [375.740480] (kms_flip:7266) DEBUG: name = flip last_ts = 377.131531 last_received_ts = 377.130737 last_seq = 3493 current_ts = 377.148193 current_received_ts = 377.147400 current_seq = 3494 count = 333 seq_step = 1 [375.740549] (kms_flip:7266) DEBUG: Vblank took 63us [375.757151] (kms_flip:7266) DEBUG: name = flip last_ts = 377.148193 last_received_ts = 377.147400 last_seq = 3494 current_ts = 377.164856 current_received_ts = 377.164062 current_seq = 3495 count = 334 seq_step = 1 [375.757220] (kms_flip:7266) DEBUG: Vblank took 64us [375.773818] (kms_flip:7266) DEBUG: name = flip last_ts = 377.164856 last_received_ts = 377.164062 last_seq = 3495 current_ts = 377.181519 current_received_ts = 377.180725 current_seq = 3496 count = 335 seq_step = 1 [375.773887] (kms_flip:7266) DEBUG: Vblank took 63us [375.790471] (kms_flip:7266) DEBUG: name = flip last_ts = 377.181519 last_received_ts = 377.180725 last_seq = 3496 current_ts = 377.198181 current_received_ts = 377.197388 current_seq = 3497 count = 336 seq_step = 1 [375.790540] (kms_flip:7266) DEBUG: Vblank took 63us [375.807139] (kms_flip:7266) DEBUG: name = flip last_ts = 377.198181 last_received_ts = 377.197388 last_seq = 3497 current_ts = 377.214874 current_received_ts = 377.214050 current_seq = 3498 count = 337 seq_step = 1 [375.807208] (kms_flip:7266) DEBUG: Vblank took 63us [375.823805] (kms_flip:7266) DEBUG: name = flip last_ts = 377.214874 last_received_ts = 377.214050 last_seq = 3498 current_ts = 377.231506 current_received_ts = 377.230713 current_seq = 3499 count = 338 seq_step = 1 [375.823874] (kms_flip:7266) DEBUG: Vblank took 63us [375.840464] (kms_flip:7266) DEBUG: name = flip last_ts = 377.231506 last_received_ts = 377.230713 last_seq = 3499 current_ts = 377.248199 current_received_ts = 377.247375 current_seq = 3500 count = 339 seq_step = 1 [375.840515] (kms_flip:7266) DEBUG: Vblank took 45us [375.857141] (kms_flip:7266) DEBUG: name = flip last_ts = 377.248199 last_received_ts = 377.247375 last_seq = 3500 current_ts = 377.264862 current_received_ts = 377.264038 current_seq = 3501 count = 340 seq_step = 1 [375.857210] (kms_flip:7266) DEBUG: Vblank took 62us [375.873796] (kms_flip:7266) DEBUG: name = flip last_ts = 377.264862 last_received_ts = 377.264038 last_seq = 3501 current_ts = 377.281525 current_received_ts = 377.280701 current_seq = 3502 count = 341 seq_step = 1 [375.873866] (kms_flip:7266) DEBUG: Vblank took 63us [375.890454] (kms_flip:7266) DEBUG: name = flip last_ts = 377.281525 last_received_ts = 377.280701 last_seq = 3502 current_ts = 377.298187 current_received_ts = 377.297363 current_seq = 3503 count = 342 seq_step = 1 [375.890523] (kms_flip:7266) DEBUG: Vblank took 64us [375.907141] (kms_flip:7266) DEBUG: name = flip last_ts = 377.298187 last_received_ts = 377.297363 last_seq = 3503 current_ts = 377.314850 current_received_ts = 377.314056 current_seq = 3504 count = 343 seq_step = 1 [375.907217] (kms_flip:7266) DEBUG: Vblank took 69us [375.923807] (kms_flip:7266) DEBUG: name = flip last_ts = 377.314850 last_received_ts = 377.314056 last_seq = 3504 current_ts = 377.331512 current_received_ts = 377.330719 current_seq = 3505 count = 344 seq_step = 1 [375.923887] (kms_flip:7266) DEBUG: Vblank took 70us [375.940455] (kms_flip:7266) DEBUG: name = flip last_ts = 377.331512 last_received_ts = 377.330719 last_seq = 3505 current_ts = 377.348175 current_received_ts = 377.347382 current_seq = 3506 count = 345 seq_step = 1 [375.940530] (kms_flip:7266) DEBUG: Vblank took 68us [375.957121] (kms_flip:7266) DEBUG: name = flip last_ts = 377.348175 last_received_ts = 377.347382 last_seq = 3506 current_ts = 377.364838 current_received_ts = 377.364044 current_seq = 3507 count = 346 seq_step = 1 [375.957194] (kms_flip:7266) DEBUG: Vblank took 66us [375.973798] (kms_flip:7266) DEBUG: name = flip last_ts = 377.364838 last_received_ts = 377.364044 last_seq = 3507 current_ts = 377.381500 current_received_ts = 377.380707 current_seq = 3508 count = 347 seq_step = 1 [375.973872] (kms_flip:7266) DEBUG: Vblank took 69us [375.990438] (kms_flip:7266) DEBUG: name = flip last_ts = 377.381500 last_received_ts = 377.380707 last_seq = 3508 current_ts = 377.398163 current_received_ts = 377.397339 current_seq = 3509 count = 348 seq_step = 1 [375.990508] (kms_flip:7266) DEBUG: Vblank took 64us [376.007123] (kms_flip:7266) DEBUG: name = flip last_ts = 377.398163 last_received_ts = 377.397339 last_seq = 3509 current_ts = 377.414825 current_received_ts = 377.414032 current_seq = 3510 count = 349 seq_step = 1 [376.007196] (kms_flip:7266) DEBUG: Vblank took 65us [376.023771] (kms_flip:7266) DEBUG: name = flip last_ts = 377.414825 last_received_ts = 377.414032 last_seq = 3510 current_ts = 377.431488 current_received_ts = 377.430695 current_seq = 3511 count = 350 seq_step = 1 [376.023840] (kms_flip:7266) DEBUG: Vblank took 63us [376.040447] (kms_flip:7266) DEBUG: name = flip last_ts = 377.431488 last_received_ts = 377.430695 last_seq = 3511 current_ts = 377.448151 current_received_ts = 377.447357 current_seq = 3512 count = 351 seq_step = 1 [376.040523] (kms_flip:7266) DEBUG: Vblank took 69us [376.057119] (kms_flip:7266) DEBUG: name = flip last_ts = 377.448151 last_received_ts = 377.447357 last_seq = 3512 current_ts = 377.464813 current_received_ts = 377.464020 current_seq = 3513 count = 352 seq_step = 1 [376.057190] (kms_flip:7266) DEBUG: Vblank took 65us [376.073773] (kms_flip:7266) DEBUG: name = flip last_ts = 377.464813 last_received_ts = 377.464020 last_seq = 3513 current_ts = 377.481476 current_received_ts = 377.480682 current_seq = 3514 count = 353 seq_step = 1 [376.073843] (kms_flip:7266) DEBUG: Vblank took 63us [376.090418] (kms_flip:7266) DEBUG: name = flip last_ts = 377.481476 last_received_ts = 377.480682 last_seq = 3514 current_ts = 377.498138 current_received_ts = 377.497345 current_seq = 3515 count = 354 seq_step = 1 [376.090487] (kms_flip:7266) DEBUG: Vblank took 63us [376.107128] (kms_flip:7266) DEBUG: name = flip last_ts = 377.498138 last_received_ts = 377.497345 last_seq = 3515 current_ts = 377.514801 current_received_ts = 377.514038 current_seq = 3516 count = 355 seq_step = 1 [376.108228] (kms_flip:7266) DEBUG: Vblank took 1074us [376.108249] (kms_flip:7266) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [376.108400] (kms_flip:7266) CRITICAL: Failed assertion: end - start < 500 [376.130236] (kms_flip:7266) igt_core-INFO: Stack trace: [376.144440] (kms_flip:7266) igt_core-INFO: #0 ../lib/igt_core.c:2106 __igt_fail_assert() [376.145578] (kms_flip:7266) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [376.145641] (kms_flip:7266) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [376.145685] (kms_flip:7266) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() [376.145712] (kms_flip:7266) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [376.149775] (kms_flip:7266) igt_core-INFO: #5 [__libc_init_first+0x8a] [376.150459] (kms_flip:7266) igt_core-INFO: #6 [__libc_start_main+0x8b] [376.150653] (kms_flip:7266) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-eDP1: FAIL (7.278s)
Dmesg	<6> [385.326312] Console: switching to colour dummy device 80x25 <6> [385.326622] [IGT] kms_flip: executing <7> [385.333451] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [385.333460] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [385.333610] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [385.333704] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [385.333972] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [385.333976] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [385.334103] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [385.334191] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [385.334413] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [385.334416] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [385.334532] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [385.334616] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <7> [385.334823] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] <7> [385.334826] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:393:eDP-1] <7> [385.335287] xe 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [xe]] DSC DPCD: 00 11 00 76 0b 01 01 80 00 01 06 66 08 00 00 00 <7> [385.335607] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000 <7> [385.335720] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [385.335884] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [385.336014] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Supported Monitor Refresh rate range is 40 Hz - 120 Hz <5> [385.336021] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [385.336022] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [385.336023] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00 <7> [385.336026] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc. <5> [385.336027] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [385.336029] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor <5> [385.336031] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [385.336032] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0 <5> [385.336034] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [385.336053] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes <7> [385.336150] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps <7> [385.336300] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no <5> [385.336855] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [385.336863] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [385.336867] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [385.336981] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes: <7> [385.336993] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [385.337003] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 120 695310 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [385.337037] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [385.337047] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [385.337254] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [385.337263] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [385.337265] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [385.337384] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [385.337393] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [385.337395] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [385.337511] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <6> [385.338013] [IGT] kms_flip: starting subtest flip-vs-expired-vblank <6> [385.339524] [IGT] kms_flip: starting dynamic subtest A-eDP1 <7> [385.340559] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430] <7> [385.340934] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [385.423915] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [385.424178] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [385.424549] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [385.424869] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [385.425128] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [385.425378] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [385.425618] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [385.425862] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [385.426082] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [385.426333] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [385.426610] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [385.427010] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [385.427287] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [385.427561] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [385.427905] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [385.428182] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [385.428455] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [385.428790] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [385.429061] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [385.429381] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [385.429645] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [385.429945] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [385.430224] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [385.430405] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [385.430587] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [385.430775] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [385.430969] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [385.431142] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [385.431314] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [385.431476] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [385.431646] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [385.431835] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [385.431999] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [385.432158] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [385.432319] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [385.432473] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [385.432622] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [385.432778] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [385.432924] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [385.433075] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [385.433246] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [385.433471] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [385.433606] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [385.433785] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0 <7> [385.433892] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [385.433999] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm <7> [385.434103] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 1, 13, 13, 13, 13, 13, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [385.434206] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 24, 313, 313, 313, 313, 313, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [385.434303] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 28, 346, 346, 346, 346, 346, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [385.434449] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [385.434616] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 34060 required 0 qgv_peak_bw: 38400 <7> [385.434755] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [385.434913] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [385.435044] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [385.435177] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [385.435310] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [385.435466] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [385.435611] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [385.435750] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [385.435896] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [385.436048] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [385.436162] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [385.436275] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [385.436389] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [385.436496] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [385.436604] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [385.436712] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [385.436884] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [385.437015] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [385.437185] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [385.437916] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [385.438069] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [385.646080] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [385.646548] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [385.656267] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [385.656686] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [385.657102] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [385.708175] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [385.708513] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [385.709326] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [385.709763] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [385.709915] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [385.710163] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [385.710292] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [385.710664] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [385.710987] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [385.711229] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [385.711460] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [385.711686] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [385.711962] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [385.712200] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [385.712439] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [385.712670] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [385.712950] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [385.713205] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [385.713447] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [385.713686] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [385.713965] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [385.714307] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [385.714550] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [385.714794] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [385.715254] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [385.715602] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [385.716039] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [385.716332] 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> [385.716675] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [385.716983] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [385.717799] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [385.718163] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [385.718436] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [385.718496] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [385.718659] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [385.719086] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:151:pipe A] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [385.719462] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [385.719803] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [385.720133] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:151:pipe A] <7> [385.720481] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [385.720842] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [385.721148] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [385.721471] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [385.721779] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [385.722044] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [385.722303] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [385.722590] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [385.722834] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [385.723091] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [385.723309] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [385.723517] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [385.723715] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [385.723948] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [385.724146] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [385.724340] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [385.724522] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [385.724724] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [385.724950] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [385.725146] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [385.725315] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [385.725472] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [385.725629] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [385.725784] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [385.725945] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [385.726090] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [385.726232] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [385.726370] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [385.726507] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [385.726639] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [385.726779] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [385.726923] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [385.727062] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [385.727195] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [385.727328] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [385.727447] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [385.727565] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [385.727681] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 0, found 432000) <7> [385.727836] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [385.728020] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [385.728124] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x1 <7> [385.728243] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [385.728330] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [385.728409] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [385.728487] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [385.728564] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [385.728641] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [385.728738] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1 <7> [385.728902] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23529 required 1461 qgv_peak_bw: 38400 <7> [385.729029] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36259 required 1461 qgv_peak_bw: 38400 <7> [385.729142] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [385.729248] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [385.729348] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [385.729446] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 0 kHz -> 173855 kHz <7> [385.729564] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [385.729674] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [385.729784] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [385.729890] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [385.729998] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0 <7> [385.730095] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0 <7> [385.730185] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: yes [modeset] <7> [385.730276] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [385.730362] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: A, pipe bpp: 30, dithering: 0 <7> [385.730448] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [385.730531] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [385.730618] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [385.730702] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [385.730786] 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> [385.730878] 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> [385.730986] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [385.731062] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [385.731136] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [385.731209] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [385.731282] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [385.731357] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [385.731430] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [385.731505] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [385.731578] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [385.731653] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [385.731727] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [385.731810] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [385.731897] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [385.731976] 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: 37 vsync start: 103, vsync end: 97 <7> [385.732051] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1869, vmax vblank: 1869, vmin vtotal: 1906, vmax vtotal: 1906 <7> [385.732123] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [385.732196] 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> [385.732269] 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> [385.732342] 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> [385.732417] 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> [385.732497] 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> [385.732574] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0 <7> [385.732652] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [385.732727] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [385.732826] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [385.732918] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [385.732996] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [385.733077] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [385.733155] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [385.733230] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [385.733303] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [385.733375] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [385.733448] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [385.733524] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [385.733603] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [385.733677] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [385.733749] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [385.733894] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [385.733981] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [385.734055] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [385.734128] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [385.734202] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [385.734274] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [385.734346] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [385.734417] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [385.734490] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [385.734562] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [385.734633] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [385.734705] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [385.734785] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [385.734890] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [FB:430] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [385.734970] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [385.735049] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [385.735125] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [385.735200] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [385.735274] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [385.735347] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [385.735419] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [385.735714] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A <7> [385.735900] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xa8000000) <7> [385.736011] 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> [385.736102] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [385.736191] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [385.736274] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [385.736343] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [385.736410] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [385.736478] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [385.736546] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [385.736613] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [385.736679] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [385.736744] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [385.736822] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [385.736904] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [385.736968] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [385.737030] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [385.737090] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [385.737173] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [385.737331] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [385.737394] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [385.737500] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [385.738868] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A] <7> [385.739027] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [385.741026] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [385.741123] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (468 ms remaining) <7> [385.748662] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [385.748803] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [385.748899] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [385.749003] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [386.213990] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [386.234688] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [386.235172] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [386.235523] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [386.271910] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [386.272277] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [386.272569] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [386.272867] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [386.350038] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [386.350182] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [386.350307] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [386.450104] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [386.450522] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [386.450933] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [386.453032] 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> [386.454583] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [386.455485] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [386.456766] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [386.458204] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [386.459363] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [386.459795] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [386.461314] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [386.461751] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [386.462561] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A <7> [386.463094] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [386.463469] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A <7> [386.463949] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [386.496685] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [386.498351] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [386.498697] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [389.038803] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off <7> [389.039208] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [392.465649] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [392.466426] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [392.467076] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [392.618714] [IGT] kms_flip: finished subtest A-eDP1, FAIL

Detail

Value

Duration

7.28 seconds

Hostname

shard-lnl-3

Igt-Version

IGT-Version: 2.4-gd34395a7e (x86_64) (Linux: 7.1.0-rc6-lgci-xe-xe-pw-167724v1-debug+ x86_64)

Out

Using IGT_SRANDOM=1780413070 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2106 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (7.278s)

Err

Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
[376.108249] (kms_flip:7266) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[376.108400] (kms_flip:7266) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
[374.090747] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.481750
last_received_ts = 375.480957
last_seq = 3394
current_ts = 375.498413
current_received_ts = 375.497620
current_seq = 3395
count = 234
seq_step = 1
[374.090815] (kms_flip:7266) DEBUG: Vblank took 62us
[374.107408] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.498413
last_received_ts = 375.497620
last_seq = 3395
current_ts = 375.515106
current_received_ts = 375.514282
current_seq = 3396
count = 235
seq_step = 1
[374.107479] (kms_flip:7266) DEBUG: Vblank took 64us
[374.124076] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.515106
last_received_ts = 375.514282
last_seq = 3396
current_ts = 375.531769
current_received_ts = 375.530945
current_seq = 3397
count = 236
seq_step = 1
[374.124164] (kms_flip:7266) DEBUG: Vblank took 83us
[374.140741] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.531769
last_received_ts = 375.530945
last_seq = 3397
current_ts = 375.548431
current_received_ts = 375.547607
current_seq = 3398
count = 237
seq_step = 1
[374.140809] (kms_flip:7266) DEBUG: Vblank took 63us
[374.157397] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.548431
last_received_ts = 375.547607
last_seq = 3398
current_ts = 375.565094
current_received_ts = 375.564270
current_seq = 3399
count = 238
seq_step = 1
[374.157465] (kms_flip:7266) DEBUG: Vblank took 61us
[374.174071] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.565094
last_received_ts = 375.564270
last_seq = 3399
current_ts = 375.581757
current_received_ts = 375.580963
current_seq = 3400
count = 239
seq_step = 1
[374.174157] (kms_flip:7266) DEBUG: Vblank took 79us
[374.190734] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.581757
last_received_ts = 375.580963
last_seq = 3400
current_ts = 375.598419
current_received_ts = 375.597626
current_seq = 3401
count = 240
seq_step = 1
[374.190802] (kms_flip:7266) DEBUG: Vblank took 62us
[374.207399] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.598419
last_received_ts = 375.597626
last_seq = 3401
current_ts = 375.615082
current_received_ts = 375.614288
current_seq = 3402
count = 241
seq_step = 1
[374.207469] (kms_flip:7266) DEBUG: Vblank took 65us
[374.224061] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.615082
last_received_ts = 375.614288
last_seq = 3402
current_ts = 375.631744
current_received_ts = 375.630951
current_seq = 3403
count = 242
seq_step = 1
[374.224149] (kms_flip:7266) DEBUG: Vblank took 82us
[374.240726] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.631744
last_received_ts = 375.630951
last_seq = 3403
current_ts = 375.648407
current_received_ts = 375.647614
current_seq = 3404
count = 243
seq_step = 1
[374.240795] (kms_flip:7266) DEBUG: Vblank took 63us
[374.257385] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.648407
last_received_ts = 375.647614
last_seq = 3404
current_ts = 375.665070
current_received_ts = 375.664276
current_seq = 3405
count = 244
seq_step = 1
[374.257454] (kms_flip:7266) DEBUG: Vblank took 63us
[374.274053] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.665070
last_received_ts = 375.664276
last_seq = 3405
current_ts = 375.681732
current_received_ts = 375.680939
current_seq = 3406
count = 245
seq_step = 1
[374.274141] (kms_flip:7266) DEBUG: Vblank took 82us
[374.290720] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.681732
last_received_ts = 375.680939
last_seq = 3406
current_ts = 375.698395
current_received_ts = 375.697601
current_seq = 3407
count = 246
seq_step = 1
[374.290789] (kms_flip:7266) DEBUG: Vblank took 64us
[374.307377] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.698395
last_received_ts = 375.697601
last_seq = 3407
current_ts = 375.715057
current_received_ts = 375.714264
current_seq = 3408
count = 247
seq_step = 1
[374.307445] (kms_flip:7266) DEBUG: Vblank took 63us
[374.324050] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.715057
last_received_ts = 375.714264
last_seq = 3408
current_ts = 375.731720
current_received_ts = 375.730927
current_seq = 3409
count = 248
seq_step = 1
[374.324145] (kms_flip:7266) DEBUG: Vblank took 89us
[374.340712] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.731720
last_received_ts = 375.730927
last_seq = 3409
current_ts = 375.748383
current_received_ts = 375.747589
current_seq = 3410
count = 249
seq_step = 1
[374.340779] (kms_flip:7266) DEBUG: Vblank took 63us
[374.357365] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.748383
last_received_ts = 375.747589
last_seq = 3410
current_ts = 375.765045
current_received_ts = 375.764252
current_seq = 3411
count = 250
seq_step = 1
[374.357435] (kms_flip:7266) DEBUG: Vblank took 65us
[374.374055] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.765045
last_received_ts = 375.764252
last_seq = 3411
current_ts = 375.781738
current_received_ts = 375.780945
current_seq = 3412
count = 251
seq_step = 1
[374.374155] (kms_flip:7266) DEBUG: Vblank took 94us
[374.390700] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.781738
last_received_ts = 375.780945
last_seq = 3412
current_ts = 375.798401
current_received_ts = 375.797577
current_seq = 3413
count = 252
seq_step = 1
[374.390768] (kms_flip:7266) DEBUG: Vblank took 62us
[374.407370] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.798401
last_received_ts = 375.797577
last_seq = 3413
current_ts = 375.815063
current_received_ts = 375.814240
current_seq = 3414
count = 253
seq_step = 1
[374.407441] (kms_flip:7266) DEBUG: Vblank took 65us
[374.424026] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.815063
last_received_ts = 375.814240
last_seq = 3414
current_ts = 375.831726
current_received_ts = 375.830902
current_seq = 3415
count = 254
seq_step = 1
[374.424094] (kms_flip:7266) DEBUG: Vblank took 62us
[374.440696] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.831726
last_received_ts = 375.830902
last_seq = 3415
current_ts = 375.848389
current_received_ts = 375.847595
current_seq = 3416
count = 255
seq_step = 1
[374.440764] (kms_flip:7266) DEBUG: Vblank took 63us
[374.457348] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.848389
last_received_ts = 375.847595
last_seq = 3416
current_ts = 375.865051
current_received_ts = 375.864227
current_seq = 3417
count = 256
seq_step = 1
[374.457416] (kms_flip:7266) DEBUG: Vblank took 62us
[374.474019] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.865051
last_received_ts = 375.864227
last_seq = 3417
current_ts = 375.881714
current_received_ts = 375.880890
current_seq = 3418
count = 257
seq_step = 1
[374.474087] (kms_flip:7266) DEBUG: Vblank took 62us
[374.490687] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.881714
last_received_ts = 375.880890
last_seq = 3418
current_ts = 375.898376
current_received_ts = 375.897583
current_seq = 3419
count = 258
seq_step = 1
[374.490756] (kms_flip:7266) DEBUG: Vblank took 63us
[374.507342] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.898376
last_received_ts = 375.897583
last_seq = 3419
current_ts = 375.915039
current_received_ts = 375.914215
current_seq = 3420
count = 259
seq_step = 1
[374.507411] (kms_flip:7266) DEBUG: Vblank took 64us
[374.524013] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.915039
last_received_ts = 375.914215
last_seq = 3420
current_ts = 375.931702
current_received_ts = 375.930908
current_seq = 3421
count = 260
seq_step = 1
[374.524081] (kms_flip:7266) DEBUG: Vblank took 62us
[374.540679] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.931702
last_received_ts = 375.930908
last_seq = 3421
current_ts = 375.948364
current_received_ts = 375.947571
current_seq = 3422
count = 261
seq_step = 1
[374.540747] (kms_flip:7266) DEBUG: Vblank took 62us
[374.557333] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.948364
last_received_ts = 375.947571
last_seq = 3422
current_ts = 375.965027
current_received_ts = 375.964233
current_seq = 3423
count = 262
seq_step = 1
[374.557401] (kms_flip:7266) DEBUG: Vblank took 62us
[374.574004] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.965027
last_received_ts = 375.964233
last_seq = 3423
current_ts = 375.981689
current_received_ts = 375.980896
current_seq = 3424
count = 263
seq_step = 1
[374.574073] (kms_flip:7266) DEBUG: Vblank took 63us
[374.590671] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.981689
last_received_ts = 375.980896
last_seq = 3424
current_ts = 375.998352
current_received_ts = 375.997559
current_seq = 3425
count = 264
seq_step = 1
[374.590740] (kms_flip:7266) DEBUG: Vblank took 62us
[374.607326] (kms_flip:7266) DEBUG: name = flip
last_ts = 375.998352
last_received_ts = 375.997559
last_seq = 3425
current_ts = 376.015015
current_received_ts = 376.014221
current_seq = 3426
count = 265
seq_step = 1
[374.607394] (kms_flip:7266) DEBUG: Vblank took 62us
[374.623996] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.015015
last_received_ts = 376.014221
last_seq = 3426
current_ts = 376.031677
current_received_ts = 376.030884
current_seq = 3427
count = 266
seq_step = 1
[374.624063] (kms_flip:7266) DEBUG: Vblank took 62us
[374.640659] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.031677
last_received_ts = 376.030884
last_seq = 3427
current_ts = 376.048340
current_received_ts = 376.047546
current_seq = 3428
count = 267
seq_step = 1
[374.640728] (kms_flip:7266) DEBUG: Vblank took 62us
[374.657325] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.048340
last_received_ts = 376.047546
last_seq = 3428
current_ts = 376.065033
current_received_ts = 376.064209
current_seq = 3429
count = 268
seq_step = 1
[374.657392] (kms_flip:7266) DEBUG: Vblank took 62us
[374.673983] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.065033
last_received_ts = 376.064209
last_seq = 3429
current_ts = 376.081665
current_received_ts = 376.080872
current_seq = 3430
count = 269
seq_step = 1
[374.674050] (kms_flip:7266) DEBUG: Vblank took 61us
[374.690653] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.081665
last_received_ts = 376.080872
last_seq = 3430
current_ts = 376.098358
current_received_ts = 376.097534
current_seq = 3431
count = 270
seq_step = 1
[374.690722] (kms_flip:7266) DEBUG: Vblank took 62us
[374.707306] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.098358
last_received_ts = 376.097534
last_seq = 3431
current_ts = 376.115021
current_received_ts = 376.114197
current_seq = 3432
count = 271
seq_step = 1
[374.707376] (kms_flip:7266) DEBUG: Vblank took 63us
[374.723984] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.115021
last_received_ts = 376.114197
last_seq = 3432
current_ts = 376.131683
current_received_ts = 376.130859
current_seq = 3433
count = 272
seq_step = 1
[374.724053] (kms_flip:7266) DEBUG: Vblank took 64us
[374.740655] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.131683
last_received_ts = 376.130859
last_seq = 3433
current_ts = 376.148346
current_received_ts = 376.147552
current_seq = 3434
count = 273
seq_step = 1
[374.740731] (kms_flip:7266) DEBUG: Vblank took 70us
[374.757314] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.148346
last_received_ts = 376.147552
last_seq = 3434
current_ts = 376.165009
current_received_ts = 376.164215
current_seq = 3435
count = 274
seq_step = 1
[374.757389] (kms_flip:7266) DEBUG: Vblank took 69us
[374.773975] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.165009
last_received_ts = 376.164215
last_seq = 3435
current_ts = 376.181671
current_received_ts = 376.180878
current_seq = 3436
count = 275
seq_step = 1
[374.774043] (kms_flip:7266) DEBUG: Vblank took 63us
[374.790636] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.181671
last_received_ts = 376.180878
last_seq = 3436
current_ts = 376.198334
current_received_ts = 376.197540
current_seq = 3437
count = 276
seq_step = 1
[374.790704] (kms_flip:7266) DEBUG: Vblank took 63us
[374.807294] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.198334
last_received_ts = 376.197540
last_seq = 3437
current_ts = 376.214996
current_received_ts = 376.214172
current_seq = 3438
count = 277
seq_step = 1
[374.807362] (kms_flip:7266) DEBUG: Vblank took 63us
[374.823963] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.214996
last_received_ts = 376.214172
last_seq = 3438
current_ts = 376.231659
current_received_ts = 376.230865
current_seq = 3439
count = 278
seq_step = 1
[374.824032] (kms_flip:7266) DEBUG: Vblank took 62us
[374.840630] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.231659
last_received_ts = 376.230865
last_seq = 3439
current_ts = 376.248322
current_received_ts = 376.247528
current_seq = 3440
count = 279
seq_step = 1
[374.840699] (kms_flip:7266) DEBUG: Vblank took 63us
[374.857286] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.248322
last_received_ts = 376.247528
last_seq = 3440
current_ts = 376.264984
current_received_ts = 376.264191
current_seq = 3441
count = 280
seq_step = 1
[374.857355] (kms_flip:7266) DEBUG: Vblank took 63us
[374.873956] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.264984
last_received_ts = 376.264191
last_seq = 3441
current_ts = 376.281647
current_received_ts = 376.280853
current_seq = 3442
count = 281
seq_step = 1
[374.874026] (kms_flip:7266) DEBUG: Vblank took 65us
[374.890631] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.281647
last_received_ts = 376.280853
last_seq = 3442
current_ts = 376.298309
current_received_ts = 376.297516
current_seq = 3443
count = 282
seq_step = 1
[374.890687] (kms_flip:7266) DEBUG: Vblank took 50us
[374.907293] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.298309
last_received_ts = 376.297516
last_seq = 3443
current_ts = 376.314972
current_received_ts = 376.314178
current_seq = 3444
count = 283
seq_step = 1
[374.907370] (kms_flip:7266) DEBUG: Vblank took 69us
[374.923958] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.314972
last_received_ts = 376.314178
last_seq = 3444
current_ts = 376.331635
current_received_ts = 376.330841
current_seq = 3445
count = 284
seq_step = 1
[374.924036] (kms_flip:7266) DEBUG: Vblank took 72us
[374.940622] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.331635
last_received_ts = 376.330841
last_seq = 3445
current_ts = 376.348297
current_received_ts = 376.347504
current_seq = 3446
count = 285
seq_step = 1
[374.940696] (kms_flip:7266) DEBUG: Vblank took 68us
[374.957272] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.348297
last_received_ts = 376.347504
last_seq = 3446
current_ts = 376.364990
current_received_ts = 376.364166
current_seq = 3447
count = 286
seq_step = 1
[374.957341] (kms_flip:7266) DEBUG: Vblank took 63us
[374.973942] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.364990
last_received_ts = 376.364166
last_seq = 3447
current_ts = 376.381653
current_received_ts = 376.380829
current_seq = 3448
count = 287
seq_step = 1
[374.974009] (kms_flip:7266) DEBUG: Vblank took 62us
[374.990602] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.381653
last_received_ts = 376.380829
last_seq = 3448
current_ts = 376.398315
current_received_ts = 376.397491
current_seq = 3449
count = 288
seq_step = 1
[374.990669] (kms_flip:7266) DEBUG: Vblank took 62us
[375.007264] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.398315
last_received_ts = 376.397491
last_seq = 3449
current_ts = 376.414978
current_received_ts = 376.414154
current_seq = 3450
count = 289
seq_step = 1
[375.007332] (kms_flip:7266) DEBUG: Vblank took 62us
[375.023933] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.414978
last_received_ts = 376.414154
last_seq = 3450
current_ts = 376.431641
current_received_ts = 376.430817
current_seq = 3451
count = 290
seq_step = 1
[375.024001] (kms_flip:7266) DEBUG: Vblank took 63us
[375.040609] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.431641
last_received_ts = 376.430817
last_seq = 3451
current_ts = 376.448303
current_received_ts = 376.447510
current_seq = 3452
count = 291
seq_step = 1
[375.040684] (kms_flip:7266) DEBUG: Vblank took 68us
[375.057264] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.448303
last_received_ts = 376.447510
last_seq = 3452
current_ts = 376.464966
current_received_ts = 376.464172
current_seq = 3453
count = 292
seq_step = 1
[375.057339] (kms_flip:7266) DEBUG: Vblank took 68us
[375.073925] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.464966
last_received_ts = 376.464172
last_seq = 3453
current_ts = 376.481628
current_received_ts = 376.480835
current_seq = 3454
count = 293
seq_step = 1
[375.073992] (kms_flip:7266) DEBUG: Vblank took 62us
[375.090589] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.481628
last_received_ts = 376.480835
last_seq = 3454
current_ts = 376.498291
current_received_ts = 376.497498
current_seq = 3455
count = 294
seq_step = 1
[375.090657] (kms_flip:7266) DEBUG: Vblank took 63us
[375.107251] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.498291
last_received_ts = 376.497498
last_seq = 3455
current_ts = 376.514954
current_received_ts = 376.514160
current_seq = 3456
count = 295
seq_step = 1
[375.107318] (kms_flip:7266) DEBUG: Vblank took 61us
[375.123926] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.514954
last_received_ts = 376.514160
last_seq = 3456
current_ts = 376.531616
current_received_ts = 376.530823
current_seq = 3457
count = 296
seq_step = 1
[375.124001] (kms_flip:7266) DEBUG: Vblank took 69us
[375.140592] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.531616
last_received_ts = 376.530823
last_seq = 3457
current_ts = 376.548279
current_received_ts = 376.547485
current_seq = 3458
count = 297
seq_step = 1
[375.140666] (kms_flip:7266) DEBUG: Vblank took 67us
[375.157243] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.548279
last_received_ts = 376.547485
last_seq = 3458
current_ts = 376.564941
current_received_ts = 376.564148
current_seq = 3459
count = 298
seq_step = 1
[375.157312] (kms_flip:7266) DEBUG: Vblank took 63us
[375.173906] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.564941
last_received_ts = 376.564148
last_seq = 3459
current_ts = 376.581604
current_received_ts = 376.580811
current_seq = 3460
count = 299
seq_step = 1
[375.173976] (kms_flip:7266) DEBUG: Vblank took 64us
[375.190584] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.581604
last_received_ts = 376.580811
last_seq = 3460
current_ts = 376.598267
current_received_ts = 376.597473
current_seq = 3461
count = 300
seq_step = 1
[375.190657] (kms_flip:7266) DEBUG: Vblank took 68us
[375.207241] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.598267
last_received_ts = 376.597473
last_seq = 3461
current_ts = 376.614960
current_received_ts = 376.614136
current_seq = 3462
count = 301
seq_step = 1
[375.207315] (kms_flip:7266) DEBUG: Vblank took 67us
[375.223908] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.614960
last_received_ts = 376.614136
last_seq = 3462
current_ts = 376.631592
current_received_ts = 376.630798
current_seq = 3463
count = 302
seq_step = 1
[375.223983] (kms_flip:7266) DEBUG: Vblank took 68us
[375.240571] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.631592
last_received_ts = 376.630798
last_seq = 3463
current_ts = 376.648254
current_received_ts = 376.647461
current_seq = 3464
count = 303
seq_step = 1
[375.240645] (kms_flip:7266) DEBUG: Vblank took 69us
[375.257227] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.648254
last_received_ts = 376.647461
last_seq = 3464
current_ts = 376.664917
current_received_ts = 376.664124
current_seq = 3465
count = 304
seq_step = 1
[375.257295] (kms_flip:7266) DEBUG: Vblank took 62us
[375.273901] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.664917
last_received_ts = 376.664124
last_seq = 3465
current_ts = 376.681610
current_received_ts = 376.680786
current_seq = 3466
count = 305
seq_step = 1
[375.273976] (kms_flip:7266) DEBUG: Vblank took 68us
[375.290565] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.681610
last_received_ts = 376.680786
last_seq = 3466
current_ts = 376.698273
current_received_ts = 376.697479
current_seq = 3467
count = 306
seq_step = 1
[375.290639] (kms_flip:7266) DEBUG: Vblank took 68us
[375.307234] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.698273
last_received_ts = 376.697479
last_seq = 3467
current_ts = 376.714935
current_received_ts = 376.714142
current_seq = 3468
count = 307
seq_step = 1
[375.307309] (kms_flip:7266) DEBUG: Vblank took 69us
[375.323896] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.714935
last_received_ts = 376.714142
last_seq = 3468
current_ts = 376.731598
current_received_ts = 376.730804
current_seq = 3469
count = 308
seq_step = 1
[375.323971] (kms_flip:7266) DEBUG: Vblank took 69us
[375.340558] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.731598
last_received_ts = 376.730804
last_seq = 3469
current_ts = 376.748260
current_received_ts = 376.747467
current_seq = 3470
count = 309
seq_step = 1
[375.340632] (kms_flip:7266) DEBUG: Vblank took 67us
[375.357223] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.748260
last_received_ts = 376.747467
last_seq = 3470
current_ts = 376.764923
current_received_ts = 376.764130
current_seq = 3471
count = 310
seq_step = 1
[375.357297] (kms_flip:7266) DEBUG: Vblank took 69us
[375.373887] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.764923
last_received_ts = 376.764130
last_seq = 3471
current_ts = 376.781586
current_received_ts = 376.780792
current_seq = 3472
count = 311
seq_step = 1
[375.373961] (kms_flip:7266) DEBUG: Vblank took 68us
[375.390672] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.781586
last_received_ts = 376.780792
last_seq = 3472
current_ts = 376.798248
current_received_ts = 376.797546
current_seq = 3473
count = 312
seq_step = 1
[375.390757] (kms_flip:7266) DEBUG: Vblank took 61us
[375.407263] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.798248
last_received_ts = 376.797546
last_seq = 3473
current_ts = 376.814911
current_received_ts = 376.814148
current_seq = 3474
count = 313
seq_step = 1
[375.407326] (kms_flip:7266) DEBUG: Vblank took 52us
[375.423917] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.814911
last_received_ts = 376.814148
last_seq = 3474
current_ts = 376.831573
current_received_ts = 376.830811
current_seq = 3475
count = 314
seq_step = 1
[375.424014] (kms_flip:7266) DEBUG: Vblank took 86us
[375.440559] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.831573
last_received_ts = 376.830811
last_seq = 3475
current_ts = 376.848236
current_received_ts = 376.847473
current_seq = 3476
count = 315
seq_step = 1
[375.440643] (kms_flip:7266) DEBUG: Vblank took 77us
[375.457202] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.848236
last_received_ts = 376.847473
last_seq = 3476
current_ts = 376.864899
current_received_ts = 376.864105
current_seq = 3477
count = 316
seq_step = 1
[375.457272] (kms_flip:7266) DEBUG: Vblank took 65us
[375.473854] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.864899
last_received_ts = 376.864105
last_seq = 3477
current_ts = 376.881561
current_received_ts = 376.880768
current_seq = 3478
count = 317
seq_step = 1
[375.473918] (kms_flip:7266) DEBUG: Vblank took 60us
[375.490525] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.881561
last_received_ts = 376.880768
last_seq = 3478
current_ts = 376.898224
current_received_ts = 376.897430
current_seq = 3479
count = 318
seq_step = 1
[375.490597] (kms_flip:7266) DEBUG: Vblank took 67us
[375.507191] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.898224
last_received_ts = 376.897430
last_seq = 3479
current_ts = 376.914886
current_received_ts = 376.914093
current_seq = 3480
count = 319
seq_step = 1
[375.507261] (kms_flip:7266) DEBUG: Vblank took 63us
[375.523856] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.914886
last_received_ts = 376.914093
last_seq = 3480
current_ts = 376.931549
current_received_ts = 376.930756
current_seq = 3481
count = 320
seq_step = 1
[375.523926] (kms_flip:7266) DEBUG: Vblank took 64us
[375.540509] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.931549
last_received_ts = 376.930756
last_seq = 3481
current_ts = 376.948242
current_received_ts = 376.947418
current_seq = 3482
count = 321
seq_step = 1
[375.540578] (kms_flip:7266) DEBUG: Vblank took 62us
[375.557182] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.948242
last_received_ts = 376.947418
last_seq = 3482
current_ts = 376.964905
current_received_ts = 376.964081
current_seq = 3483
count = 322
seq_step = 1
[375.557252] (kms_flip:7266) DEBUG: Vblank took 64us
[375.573847] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.964905
last_received_ts = 376.964081
last_seq = 3483
current_ts = 376.981567
current_received_ts = 376.980743
current_seq = 3484
count = 323
seq_step = 1
[375.573916] (kms_flip:7266) DEBUG: Vblank took 63us
[375.590500] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.981567
last_received_ts = 376.980743
last_seq = 3484
current_ts = 376.998230
current_received_ts = 376.997406
current_seq = 3485
count = 324
seq_step = 1
[375.590569] (kms_flip:7266) DEBUG: Vblank took 63us
[375.607173] (kms_flip:7266) DEBUG: name = flip
last_ts = 376.998230
last_received_ts = 376.997406
last_seq = 3485
current_ts = 377.014893
current_received_ts = 377.014069
current_seq = 3486
count = 325
seq_step = 1
[375.607243] (kms_flip:7266) DEBUG: Vblank took 64us
[375.623835] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.014893
last_received_ts = 377.014069
last_seq = 3486
current_ts = 377.031555
current_received_ts = 377.030731
current_seq = 3487
count = 326
seq_step = 1
[375.623903] (kms_flip:7266) DEBUG: Vblank took 62us
[375.640491] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.031555
last_received_ts = 377.030731
last_seq = 3487
current_ts = 377.048218
current_received_ts = 377.047394
current_seq = 3488
count = 327
seq_step = 1
[375.640559] (kms_flip:7266) DEBUG: Vblank took 62us
[375.657168] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.048218
last_received_ts = 377.047394
last_seq = 3488
current_ts = 377.064880
current_received_ts = 377.064087
current_seq = 3489
count = 328
seq_step = 1
[375.657237] (kms_flip:7266) DEBUG: Vblank took 64us
[375.673830] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.064880
last_received_ts = 377.064087
last_seq = 3489
current_ts = 377.081543
current_received_ts = 377.080750
current_seq = 3490
count = 329
seq_step = 1
[375.673898] (kms_flip:7266) DEBUG: Vblank took 62us
[375.690485] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.081543
last_received_ts = 377.080750
last_seq = 3490
current_ts = 377.098206
current_received_ts = 377.097382
current_seq = 3491
count = 330
seq_step = 1
[375.690554] (kms_flip:7266) DEBUG: Vblank took 63us
[375.707166] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.098206
last_received_ts = 377.097382
last_seq = 3491
current_ts = 377.114868
current_received_ts = 377.114075
current_seq = 3492
count = 331
seq_step = 1
[375.707236] (kms_flip:7266) DEBUG: Vblank took 64us
[375.723824] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.114868
last_received_ts = 377.114075
last_seq = 3492
current_ts = 377.131531
current_received_ts = 377.130737
current_seq = 3493
count = 332
seq_step = 1
[375.723896] (kms_flip:7266) DEBUG: Vblank took 66us
[375.740480] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.131531
last_received_ts = 377.130737
last_seq = 3493
current_ts = 377.148193
current_received_ts = 377.147400
current_seq = 3494
count = 333
seq_step = 1
[375.740549] (kms_flip:7266) DEBUG: Vblank took 63us
[375.757151] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.148193
last_received_ts = 377.147400
last_seq = 3494
current_ts = 377.164856
current_received_ts = 377.164062
current_seq = 3495
count = 334
seq_step = 1
[375.757220] (kms_flip:7266) DEBUG: Vblank took 64us
[375.773818] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.164856
last_received_ts = 377.164062
last_seq = 3495
current_ts = 377.181519
current_received_ts = 377.180725
current_seq = 3496
count = 335
seq_step = 1
[375.773887] (kms_flip:7266) DEBUG: Vblank took 63us
[375.790471] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.181519
last_received_ts = 377.180725
last_seq = 3496
current_ts = 377.198181
current_received_ts = 377.197388
current_seq = 3497
count = 336
seq_step = 1
[375.790540] (kms_flip:7266) DEBUG: Vblank took 63us
[375.807139] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.198181
last_received_ts = 377.197388
last_seq = 3497
current_ts = 377.214874
current_received_ts = 377.214050
current_seq = 3498
count = 337
seq_step = 1
[375.807208] (kms_flip:7266) DEBUG: Vblank took 63us
[375.823805] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.214874
last_received_ts = 377.214050
last_seq = 3498
current_ts = 377.231506
current_received_ts = 377.230713
current_seq = 3499
count = 338
seq_step = 1
[375.823874] (kms_flip:7266) DEBUG: Vblank took 63us
[375.840464] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.231506
last_received_ts = 377.230713
last_seq = 3499
current_ts = 377.248199
current_received_ts = 377.247375
current_seq = 3500
count = 339
seq_step = 1
[375.840515] (kms_flip:7266) DEBUG: Vblank took 45us
[375.857141] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.248199
last_received_ts = 377.247375
last_seq = 3500
current_ts = 377.264862
current_received_ts = 377.264038
current_seq = 3501
count = 340
seq_step = 1
[375.857210] (kms_flip:7266) DEBUG: Vblank took 62us
[375.873796] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.264862
last_received_ts = 377.264038
last_seq = 3501
current_ts = 377.281525
current_received_ts = 377.280701
current_seq = 3502
count = 341
seq_step = 1
[375.873866] (kms_flip:7266) DEBUG: Vblank took 63us
[375.890454] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.281525
last_received_ts = 377.280701
last_seq = 3502
current_ts = 377.298187
current_received_ts = 377.297363
current_seq = 3503
count = 342
seq_step = 1
[375.890523] (kms_flip:7266) DEBUG: Vblank took 64us
[375.907141] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.298187
last_received_ts = 377.297363
last_seq = 3503
current_ts = 377.314850
current_received_ts = 377.314056
current_seq = 3504
count = 343
seq_step = 1
[375.907217] (kms_flip:7266) DEBUG: Vblank took 69us
[375.923807] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.314850
last_received_ts = 377.314056
last_seq = 3504
current_ts = 377.331512
current_received_ts = 377.330719
current_seq = 3505
count = 344
seq_step = 1
[375.923887] (kms_flip:7266) DEBUG: Vblank took 70us
[375.940455] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.331512
last_received_ts = 377.330719
last_seq = 3505
current_ts = 377.348175
current_received_ts = 377.347382
current_seq = 3506
count = 345
seq_step = 1
[375.940530] (kms_flip:7266) DEBUG: Vblank took 68us
[375.957121] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.348175
last_received_ts = 377.347382
last_seq = 3506
current_ts = 377.364838
current_received_ts = 377.364044
current_seq = 3507
count = 346
seq_step = 1
[375.957194] (kms_flip:7266) DEBUG: Vblank took 66us
[375.973798] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.364838
last_received_ts = 377.364044
last_seq = 3507
current_ts = 377.381500
current_received_ts = 377.380707
current_seq = 3508
count = 347
seq_step = 1
[375.973872] (kms_flip:7266) DEBUG: Vblank took 69us
[375.990438] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.381500
last_received_ts = 377.380707
last_seq = 3508
current_ts = 377.398163
current_received_ts = 377.397339
current_seq = 3509
count = 348
seq_step = 1
[375.990508] (kms_flip:7266) DEBUG: Vblank took 64us
[376.007123] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.398163
last_received_ts = 377.397339
last_seq = 3509
current_ts = 377.414825
current_received_ts = 377.414032
current_seq = 3510
count = 349
seq_step = 1
[376.007196] (kms_flip:7266) DEBUG: Vblank took 65us
[376.023771] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.414825
last_received_ts = 377.414032
last_seq = 3510
current_ts = 377.431488
current_received_ts = 377.430695
current_seq = 3511
count = 350
seq_step = 1
[376.023840] (kms_flip:7266) DEBUG: Vblank took 63us
[376.040447] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.431488
last_received_ts = 377.430695
last_seq = 3511
current_ts = 377.448151
current_received_ts = 377.447357
current_seq = 3512
count = 351
seq_step = 1
[376.040523] (kms_flip:7266) DEBUG: Vblank took 69us
[376.057119] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.448151
last_received_ts = 377.447357
last_seq = 3512
current_ts = 377.464813
current_received_ts = 377.464020
current_seq = 3513
count = 352
seq_step = 1
[376.057190] (kms_flip:7266) DEBUG: Vblank took 65us
[376.073773] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.464813
last_received_ts = 377.464020
last_seq = 3513
current_ts = 377.481476
current_received_ts = 377.480682
current_seq = 3514
count = 353
seq_step = 1
[376.073843] (kms_flip:7266) DEBUG: Vblank took 63us
[376.090418] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.481476
last_received_ts = 377.480682
last_seq = 3514
current_ts = 377.498138
current_received_ts = 377.497345
current_seq = 3515
count = 354
seq_step = 1
[376.090487] (kms_flip:7266) DEBUG: Vblank took 63us
[376.107128] (kms_flip:7266) DEBUG: name = flip
last_ts = 377.498138
last_received_ts = 377.497345
last_seq = 3515
current_ts = 377.514801
current_received_ts = 377.514038
current_seq = 3516
count = 355
seq_step = 1
[376.108228] (kms_flip:7266) DEBUG: Vblank took 1074us
[376.108249] (kms_flip:7266) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[376.108400] (kms_flip:7266) CRITICAL: Failed assertion: end - start < 500
[376.130236] (kms_flip:7266) igt_core-INFO: Stack trace:
[376.144440] (kms_flip:7266) igt_core-INFO:   #0 ../lib/igt_core.c:2106 __igt_fail_assert()
[376.145578] (kms_flip:7266) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[376.145641] (kms_flip:7266) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[376.145685] (kms_flip:7266) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
[376.145712] (kms_flip:7266) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[376.149775] (kms_flip:7266) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[376.150459] (kms_flip:7266) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[376.150653] (kms_flip:7266) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (7.278s)

Dmesg

<6> [385.326312] Console: switching to colour dummy device 80x25

<6> [385.326622] [IGT] kms_flip: executing

<7> [385.333451] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

<7> [385.333460] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1]

<7> [385.333610] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [385.333704] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

<7> [385.333972] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2]

<7> [385.333976] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2]

<7> [385.334103] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [385.334191] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

<7> [385.334413] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3]

<7> [385.334416] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3]

<7> [385.334532] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [385.334616] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

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

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

<7> [385.335287] xe 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [xe]] DSC DPCD: 00 11 00 76 0b 01 01 80 00 01 06 66 08 00 00 00

<7> [385.335607] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000

<7> [385.335720] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000

<7> [385.335884] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000

<7> [385.336014] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Supported Monitor Refresh rate range is 40 Hz - 120 Hz

<5> [385.336021] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [385.336022] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [385.336023] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00

<7> [385.336026] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc.

<5> [385.336027] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [385.336029] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor

<5> [385.336031] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [385.336032] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0

<5> [385.336034] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [385.336053] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes

<7> [385.336150] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps

<7> [385.336300] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no

<5> [385.336855] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [385.336863] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [385.336867] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [385.336981] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes:

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

<7> [385.337003] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 120 695310 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa

<7> [385.337037] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

<7> [385.337047] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1]

<7> [385.337254] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

<7> [385.337263] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2]

<7> [385.337265] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2]

<7> [385.337384] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

<7> [385.337393] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3]

<7> [385.337395] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3]

<7> [385.337511] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

<6> [385.338013] [IGT] kms_flip: starting subtest flip-vs-expired-vblank

<6> [385.339524] [IGT] kms_flip: starting dynamic subtest A-eDP1

<7> [385.340559] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [385.433785] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0

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

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

<7> [385.434103] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 1, 13, 13, 13, 13, 13, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [385.434206] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 24, 313, 313, 313, 313, 313, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [385.434303] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 28, 346, 346, 346, 346, 346, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [385.434449] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0

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

<7> [385.434755] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 38400

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

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

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

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

<7> [385.435466] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz

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

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

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

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

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

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

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

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

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

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

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

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

<7> [385.437185] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [385.719803] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [385.728243] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

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

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

<7> [385.728487] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0

<7> [385.728564] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197

<7> [385.728641] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198

<7> [385.728738] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1

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

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

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

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

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

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

<7> [385.729564] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz

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

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

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

<7> [385.729998] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0

<7> [385.730095] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0

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

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

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

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

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

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

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

<7> [385.730786] 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> [385.730878] 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> [385.730986] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [385.732196] 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> [385.732269] 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> [385.732342] 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> [385.732417] 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> [385.732497] 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> [385.732574] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [385.735714] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A

<7> [385.735900] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xa8000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [385.738868] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [386.350038] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

<7> [386.350182] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

<7> [386.350307] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

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

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

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

<7> [386.453032] 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> [386.454583] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates

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

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

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

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

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

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

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

<7> [386.462561] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A

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

<7> [386.463469] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A

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

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

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

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

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

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

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

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

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

<6> [392.618714] [IGT] kms_flip: finished subtest A-eDP1, FAIL

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