igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1 on shard-lnl@xe-4155-e41f42483c6f784fce3deb5eca0931bcbffb01df Test details

Detail	Value
Duration	9.93 seconds
Hostname	shard-lnl-4
Igt-Version	IGT-Version: 2.2-g2ce563031 (x86_64) (Linux: 6.18.0-rc7-lgci-xe-xe-4155-e41f42483c6f784fc+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1889 run_test() #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045() #4 ../tests/kms_flip.c:2045 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (9.928s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:7171) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:7171) CRITICAL: Failed assertion: end - start < 500 (kms_flip:7171) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:7171) DEBUG: Vblank took 56us (kms_flip:7171) DEBUG: name = flip last_ts = 327.311340 last_received_ts = 327.310547 last_seq = 1296 current_ts = 327.328003 current_received_ts = 327.327209 current_seq = 1297 count = 400 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 327.328003 last_received_ts = 327.327209 last_seq = 1297 current_ts = 327.344666 current_received_ts = 327.343872 current_seq = 1298 count = 401 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 57us (kms_flip:7171) DEBUG: name = flip last_ts = 327.344666 last_received_ts = 327.343872 last_seq = 1298 current_ts = 327.361328 current_received_ts = 327.360565 current_seq = 1299 count = 402 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 105us (kms_flip:7171) DEBUG: name = flip last_ts = 327.361328 last_received_ts = 327.360565 last_seq = 1299 current_ts = 327.377991 current_received_ts = 327.377197 current_seq = 1300 count = 403 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 67us (kms_flip:7171) DEBUG: name = flip last_ts = 327.377991 last_received_ts = 327.377197 last_seq = 1300 current_ts = 327.394653 current_received_ts = 327.393860 current_seq = 1301 count = 404 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 64us (kms_flip:7171) DEBUG: name = flip last_ts = 327.394653 last_received_ts = 327.393860 last_seq = 1301 current_ts = 327.411316 current_received_ts = 327.410522 current_seq = 1302 count = 405 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 83us (kms_flip:7171) DEBUG: name = flip last_ts = 327.411316 last_received_ts = 327.410522 last_seq = 1302 current_ts = 327.427979 current_received_ts = 327.427185 current_seq = 1303 count = 406 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 58us (kms_flip:7171) DEBUG: name = flip last_ts = 327.427979 last_received_ts = 327.427185 last_seq = 1303 current_ts = 327.444641 current_received_ts = 327.443878 current_seq = 1304 count = 407 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 57us (kms_flip:7171) DEBUG: name = flip last_ts = 327.444641 last_received_ts = 327.443878 last_seq = 1304 current_ts = 327.461334 current_received_ts = 327.460541 current_seq = 1305 count = 408 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 63us (kms_flip:7171) DEBUG: name = flip last_ts = 327.461334 last_received_ts = 327.460541 last_seq = 1305 current_ts = 327.477997 current_received_ts = 327.477173 current_seq = 1306 count = 409 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 327.477997 last_received_ts = 327.477173 last_seq = 1306 current_ts = 327.494659 current_received_ts = 327.493866 current_seq = 1307 count = 410 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 53us (kms_flip:7171) DEBUG: name = flip last_ts = 327.494659 last_received_ts = 327.493866 last_seq = 1307 current_ts = 327.511322 current_received_ts = 327.510529 current_seq = 1308 count = 411 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 58us (kms_flip:7171) DEBUG: name = flip last_ts = 327.511322 last_received_ts = 327.510529 last_seq = 1308 current_ts = 327.527985 current_received_ts = 327.527161 current_seq = 1309 count = 412 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 45us (kms_flip:7171) DEBUG: name = flip last_ts = 327.527985 last_received_ts = 327.527161 last_seq = 1309 current_ts = 327.544647 current_received_ts = 327.543823 current_seq = 1310 count = 413 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 327.544647 last_received_ts = 327.543823 last_seq = 1310 current_ts = 327.561310 current_received_ts = 327.560547 current_seq = 1311 count = 414 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 45us (kms_flip:7171) DEBUG: name = flip last_ts = 327.561310 last_received_ts = 327.560547 last_seq = 1311 current_ts = 327.577972 current_received_ts = 327.577179 current_seq = 1312 count = 415 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 60us (kms_flip:7171) DEBUG: name = flip last_ts = 327.577972 last_received_ts = 327.577179 last_seq = 1312 current_ts = 327.594635 current_received_ts = 327.593842 current_seq = 1313 count = 416 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 57us (kms_flip:7171) DEBUG: name = flip last_ts = 327.594635 last_received_ts = 327.593842 last_seq = 1313 current_ts = 327.611298 current_received_ts = 327.610504 current_seq = 1314 count = 417 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 56us (kms_flip:7171) DEBUG: name = flip last_ts = 327.611298 last_received_ts = 327.610504 last_seq = 1314 current_ts = 327.627960 current_received_ts = 327.627167 current_seq = 1315 count = 418 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 52us (kms_flip:7171) DEBUG: name = flip last_ts = 327.627960 last_received_ts = 327.627167 last_seq = 1315 current_ts = 327.644623 current_received_ts = 327.643860 current_seq = 1316 count = 419 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 56us (kms_flip:7171) DEBUG: name = flip last_ts = 327.644623 last_received_ts = 327.643860 last_seq = 1316 current_ts = 327.661285 current_received_ts = 327.660492 current_seq = 1317 count = 420 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 56us (kms_flip:7171) DEBUG: name = flip last_ts = 327.661285 last_received_ts = 327.660492 last_seq = 1317 current_ts = 327.677948 current_received_ts = 327.677155 current_seq = 1318 count = 421 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 46us (kms_flip:7171) DEBUG: name = flip last_ts = 327.677948 last_received_ts = 327.677155 last_seq = 1318 current_ts = 327.694611 current_received_ts = 327.693817 current_seq = 1319 count = 422 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 58us (kms_flip:7171) DEBUG: name = flip last_ts = 327.694611 last_received_ts = 327.693817 last_seq = 1319 current_ts = 327.711273 current_received_ts = 327.710510 current_seq = 1320 count = 423 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 119us (kms_flip:7171) DEBUG: name = flip last_ts = 327.711273 last_received_ts = 327.710510 last_seq = 1320 current_ts = 327.727966 current_received_ts = 327.727142 current_seq = 1321 count = 424 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 327.727966 last_received_ts = 327.727142 last_seq = 1321 current_ts = 327.744629 current_received_ts = 327.743835 current_seq = 1322 count = 425 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 59us (kms_flip:7171) DEBUG: name = flip last_ts = 327.744629 last_received_ts = 327.743835 last_seq = 1322 current_ts = 327.761292 current_received_ts = 327.760498 current_seq = 1323 count = 426 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 58us (kms_flip:7171) DEBUG: name = flip last_ts = 327.761292 last_received_ts = 327.760498 last_seq = 1323 current_ts = 327.777954 current_received_ts = 327.777161 current_seq = 1324 count = 427 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 107us (kms_flip:7171) DEBUG: name = flip last_ts = 327.777954 last_received_ts = 327.777161 last_seq = 1324 current_ts = 327.794617 current_received_ts = 327.793823 current_seq = 1325 count = 428 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 68us (kms_flip:7171) DEBUG: name = flip last_ts = 327.794617 last_received_ts = 327.793823 last_seq = 1325 current_ts = 327.811279 current_received_ts = 327.810486 current_seq = 1326 count = 429 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 64us (kms_flip:7171) DEBUG: name = flip last_ts = 327.811279 last_received_ts = 327.810486 last_seq = 1326 current_ts = 327.827942 current_received_ts = 327.827148 current_seq = 1327 count = 430 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 47us (kms_flip:7171) DEBUG: name = flip last_ts = 327.827942 last_received_ts = 327.827148 last_seq = 1327 current_ts = 327.844604 current_received_ts = 327.843842 current_seq = 1328 count = 431 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 123us (kms_flip:7171) DEBUG: name = flip last_ts = 327.844604 last_received_ts = 327.843842 last_seq = 1328 current_ts = 327.861267 current_received_ts = 327.860474 current_seq = 1329 count = 432 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 59us (kms_flip:7171) DEBUG: name = flip last_ts = 327.861267 last_received_ts = 327.860474 last_seq = 1329 current_ts = 327.877930 current_received_ts = 327.877136 current_seq = 1330 count = 433 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 43us (kms_flip:7171) DEBUG: name = flip last_ts = 327.877930 last_received_ts = 327.877136 last_seq = 1330 current_ts = 327.894592 current_received_ts = 327.893799 current_seq = 1331 count = 434 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 62us (kms_flip:7171) DEBUG: name = flip last_ts = 327.894592 last_received_ts = 327.893799 last_seq = 1331 current_ts = 327.911255 current_received_ts = 327.910492 current_seq = 1332 count = 435 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 58us (kms_flip:7171) DEBUG: name = flip last_ts = 327.911255 last_received_ts = 327.910492 last_seq = 1332 current_ts = 327.927917 current_received_ts = 327.927124 current_seq = 1333 count = 436 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 57us (kms_flip:7171) DEBUG: name = flip last_ts = 327.927917 last_received_ts = 327.927124 last_seq = 1333 current_ts = 327.944580 current_received_ts = 327.943817 current_seq = 1334 count = 437 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 53us (kms_flip:7171) DEBUG: name = flip last_ts = 327.944580 last_received_ts = 327.943817 last_seq = 1334 current_ts = 327.961243 current_received_ts = 327.960449 current_seq = 1335 count = 438 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 327.961243 last_received_ts = 327.960449 last_seq = 1335 current_ts = 327.977905 current_received_ts = 327.977203 current_seq = 1336 count = 439 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 101us (kms_flip:7171) DEBUG: name = flip last_ts = 327.977905 last_received_ts = 327.977203 last_seq = 1336 current_ts = 327.994568 current_received_ts = 327.993805 current_seq = 1337 count = 440 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 75us (kms_flip:7171) DEBUG: name = flip last_ts = 327.994568 last_received_ts = 327.993805 last_seq = 1337 current_ts = 328.011230 current_received_ts = 328.010468 current_seq = 1338 count = 441 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 45us (kms_flip:7171) DEBUG: name = flip last_ts = 328.011230 last_received_ts = 328.010468 last_seq = 1338 current_ts = 328.027924 current_received_ts = 328.027100 current_seq = 1339 count = 442 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 67us (kms_flip:7171) DEBUG: name = flip last_ts = 328.027924 last_received_ts = 328.027100 last_seq = 1339 current_ts = 328.044586 current_received_ts = 328.043793 current_seq = 1340 count = 443 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 328.044586 last_received_ts = 328.043793 last_seq = 1340 current_ts = 328.061249 current_received_ts = 328.060455 current_seq = 1341 count = 444 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 64us (kms_flip:7171) DEBUG: name = flip last_ts = 328.061249 last_received_ts = 328.060455 last_seq = 1341 current_ts = 328.077911 current_received_ts = 328.077087 current_seq = 1342 count = 445 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 328.077911 last_received_ts = 328.077087 last_seq = 1342 current_ts = 328.094574 current_received_ts = 328.093781 current_seq = 1343 count = 446 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 66us (kms_flip:7171) DEBUG: name = flip last_ts = 328.094574 last_received_ts = 328.093781 last_seq = 1343 current_ts = 328.111237 current_received_ts = 328.110443 current_seq = 1344 count = 447 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 57us (kms_flip:7171) DEBUG: name = flip last_ts = 328.111237 last_received_ts = 328.110443 last_seq = 1344 current_ts = 328.127899 current_received_ts = 328.127106 current_seq = 1345 count = 448 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 56us (kms_flip:7171) DEBUG: name = flip last_ts = 328.127899 last_received_ts = 328.127106 last_seq = 1345 current_ts = 328.144562 current_received_ts = 328.143768 current_seq = 1346 count = 449 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 328.144562 last_received_ts = 328.143768 last_seq = 1346 current_ts = 328.161224 current_received_ts = 328.160461 current_seq = 1347 count = 450 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 58us (kms_flip:7171) DEBUG: name = flip last_ts = 328.161224 last_received_ts = 328.160461 last_seq = 1347 current_ts = 328.177887 current_received_ts = 328.177094 current_seq = 1348 count = 451 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 67us (kms_flip:7171) DEBUG: name = flip last_ts = 328.177887 last_received_ts = 328.177094 last_seq = 1348 current_ts = 328.194550 current_received_ts = 328.193756 current_seq = 1349 count = 452 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 42us (kms_flip:7171) DEBUG: name = flip last_ts = 328.194550 last_received_ts = 328.193756 last_seq = 1349 current_ts = 328.211212 current_received_ts = 328.210419 current_seq = 1350 count = 453 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 42us (kms_flip:7171) DEBUG: name = flip last_ts = 328.211212 last_received_ts = 328.210419 last_seq = 1350 current_ts = 328.227875 current_received_ts = 328.227081 current_seq = 1351 count = 454 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 65us (kms_flip:7171) DEBUG: name = flip last_ts = 328.227875 last_received_ts = 328.227081 last_seq = 1351 current_ts = 328.244537 current_received_ts = 328.243774 current_seq = 1352 count = 455 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 57us (kms_flip:7171) DEBUG: name = flip last_ts = 328.244537 last_received_ts = 328.243774 last_seq = 1352 current_ts = 328.261200 current_received_ts = 328.260437 current_seq = 1353 count = 456 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 59us (kms_flip:7171) DEBUG: name = flip last_ts = 328.261200 last_received_ts = 328.260437 last_seq = 1353 current_ts = 328.277893 current_received_ts = 328.277130 current_seq = 1354 count = 457 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 58us (kms_flip:7171) DEBUG: name = flip last_ts = 328.277893 last_received_ts = 328.277130 last_seq = 1354 current_ts = 328.294525 current_received_ts = 328.293762 current_seq = 1355 count = 458 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 43us (kms_flip:7171) DEBUG: name = flip last_ts = 328.294525 last_received_ts = 328.293762 last_seq = 1355 current_ts = 328.311218 current_received_ts = 328.310394 current_seq = 1356 count = 459 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 58us (kms_flip:7171) DEBUG: name = flip last_ts = 328.311218 last_received_ts = 328.310394 last_seq = 1356 current_ts = 328.327881 current_received_ts = 328.327057 current_seq = 1357 count = 460 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 328.327881 last_received_ts = 328.327057 last_seq = 1357 current_ts = 328.344543 current_received_ts = 328.343750 current_seq = 1358 count = 461 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 328.344543 last_received_ts = 328.343750 last_seq = 1358 current_ts = 328.361206 current_received_ts = 328.360413 current_seq = 1359 count = 462 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 56us (kms_flip:7171) DEBUG: name = flip last_ts = 328.361206 last_received_ts = 328.360413 last_seq = 1359 current_ts = 328.377869 current_received_ts = 328.377075 current_seq = 1360 count = 463 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 328.377869 last_received_ts = 328.377075 last_seq = 1360 current_ts = 328.394531 current_received_ts = 328.393738 current_seq = 1361 count = 464 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 46us (kms_flip:7171) DEBUG: name = flip last_ts = 328.394531 last_received_ts = 328.393738 last_seq = 1361 current_ts = 328.411194 current_received_ts = 328.410400 current_seq = 1362 count = 465 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 328.411194 last_received_ts = 328.410400 last_seq = 1362 current_ts = 328.427856 current_received_ts = 328.427063 current_seq = 1363 count = 466 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 53us (kms_flip:7171) DEBUG: name = flip last_ts = 328.427856 last_received_ts = 328.427063 last_seq = 1363 current_ts = 328.444519 current_received_ts = 328.443726 current_seq = 1364 count = 467 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 109us (kms_flip:7171) DEBUG: name = flip last_ts = 328.444519 last_received_ts = 328.443726 last_seq = 1364 current_ts = 328.461182 current_received_ts = 328.460388 current_seq = 1365 count = 468 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 71us (kms_flip:7171) DEBUG: name = flip last_ts = 328.461182 last_received_ts = 328.460388 last_seq = 1365 current_ts = 328.477844 current_received_ts = 328.477051 current_seq = 1366 count = 469 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 328.477844 last_received_ts = 328.477051 last_seq = 1366 current_ts = 328.494507 current_received_ts = 328.493744 current_seq = 1367 count = 470 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 51us (kms_flip:7171) DEBUG: name = flip last_ts = 328.494507 last_received_ts = 328.493744 last_seq = 1367 current_ts = 328.511169 current_received_ts = 328.510376 current_seq = 1368 count = 471 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 44us (kms_flip:7171) DEBUG: name = flip last_ts = 328.511169 last_received_ts = 328.510376 last_seq = 1368 current_ts = 328.527832 current_received_ts = 328.527069 current_seq = 1369 count = 472 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 328.527832 last_received_ts = 328.527069 last_seq = 1369 current_ts = 328.544495 current_received_ts = 328.543732 current_seq = 1370 count = 473 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 52us (kms_flip:7171) DEBUG: name = flip last_ts = 328.544495 last_received_ts = 328.543732 last_seq = 1370 current_ts = 328.561188 current_received_ts = 328.560364 current_seq = 1371 count = 474 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 57us (kms_flip:7171) DEBUG: name = flip last_ts = 328.561188 last_received_ts = 328.560364 last_seq = 1371 current_ts = 328.577820 current_received_ts = 328.577057 current_seq = 1372 count = 475 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 59us (kms_flip:7171) DEBUG: name = flip last_ts = 328.577820 last_received_ts = 328.577057 last_seq = 1372 current_ts = 328.594513 current_received_ts = 328.593719 current_seq = 1373 count = 476 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 328.594513 last_received_ts = 328.593719 last_seq = 1373 current_ts = 328.611176 current_received_ts = 328.610382 current_seq = 1374 count = 477 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 44us (kms_flip:7171) DEBUG: name = flip last_ts = 328.611176 last_received_ts = 328.610382 last_seq = 1374 current_ts = 328.627838 current_received_ts = 328.627075 current_seq = 1375 count = 478 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 61us (kms_flip:7171) DEBUG: name = flip last_ts = 328.627838 last_received_ts = 328.627075 last_seq = 1375 current_ts = 328.644501 current_received_ts = 328.643707 current_seq = 1376 count = 479 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 328.644501 last_received_ts = 328.643707 last_seq = 1376 current_ts = 328.661163 current_received_ts = 328.660370 current_seq = 1377 count = 480 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 61us (kms_flip:7171) DEBUG: name = flip last_ts = 328.661163 last_received_ts = 328.660370 last_seq = 1377 current_ts = 328.677826 current_received_ts = 328.677032 current_seq = 1378 count = 481 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 59us (kms_flip:7171) DEBUG: name = flip last_ts = 328.677826 last_received_ts = 328.677032 last_seq = 1378 current_ts = 328.694489 current_received_ts = 328.693695 current_seq = 1379 count = 482 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 328.694489 last_received_ts = 328.693695 last_seq = 1379 current_ts = 328.711151 current_received_ts = 328.710358 current_seq = 1380 count = 483 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 42us (kms_flip:7171) DEBUG: name = flip last_ts = 328.711151 last_received_ts = 328.710358 last_seq = 1380 current_ts = 328.727814 current_received_ts = 328.727051 current_seq = 1381 count = 484 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 328.727814 last_received_ts = 328.727051 last_seq = 1381 current_ts = 328.744476 current_received_ts = 328.743683 current_seq = 1382 count = 485 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 61us (kms_flip:7171) DEBUG: name = flip last_ts = 328.744476 last_received_ts = 328.743683 last_seq = 1382 current_ts = 328.761139 current_received_ts = 328.760345 current_seq = 1383 count = 486 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 328.761139 last_received_ts = 328.760345 last_seq = 1383 current_ts = 328.777802 current_received_ts = 328.777039 current_seq = 1384 count = 487 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 43us (kms_flip:7171) DEBUG: name = flip last_ts = 328.777802 last_received_ts = 328.777039 last_seq = 1384 current_ts = 328.794464 current_received_ts = 328.793701 current_seq = 1385 count = 488 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 59us (kms_flip:7171) DEBUG: name = flip last_ts = 328.794464 last_received_ts = 328.793701 last_seq = 1385 current_ts = 328.811127 current_received_ts = 328.810364 current_seq = 1386 count = 489 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 43us (kms_flip:7171) DEBUG: name = flip last_ts = 328.811127 last_received_ts = 328.810364 last_seq = 1386 current_ts = 328.827789 current_received_ts = 328.826996 current_seq = 1387 count = 490 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 328.827789 last_received_ts = 328.826996 last_seq = 1387 current_ts = 328.844452 current_received_ts = 328.843689 current_seq = 1388 count = 491 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 58us (kms_flip:7171) DEBUG: name = flip last_ts = 328.844452 last_received_ts = 328.843689 last_seq = 1388 current_ts = 328.861145 current_received_ts = 328.860352 current_seq = 1389 count = 492 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 45us (kms_flip:7171) DEBUG: name = flip last_ts = 328.861145 last_received_ts = 328.860352 last_seq = 1389 current_ts = 328.877808 current_received_ts = 328.877014 current_seq = 1390 count = 493 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 58us (kms_flip:7171) DEBUG: name = flip last_ts = 328.877808 last_received_ts = 328.877014 last_seq = 1390 current_ts = 328.894470 current_received_ts = 328.893677 current_seq = 1391 count = 494 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 56us (kms_flip:7171) DEBUG: name = flip last_ts = 328.894470 last_received_ts = 328.893677 last_seq = 1391 current_ts = 328.911133 current_received_ts = 328.910339 current_seq = 1392 count = 495 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 328.911133 last_received_ts = 328.910339 last_seq = 1392 current_ts = 328.927795 current_received_ts = 328.927032 current_seq = 1393 count = 496 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 328.927795 last_received_ts = 328.927032 last_seq = 1393 current_ts = 328.944458 current_received_ts = 328.943665 current_seq = 1394 count = 497 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 43us (kms_flip:7171) DEBUG: name = flip last_ts = 328.944458 last_received_ts = 328.943665 last_seq = 1394 current_ts = 328.961121 current_received_ts = 328.960327 current_seq = 1395 count = 498 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 54us (kms_flip:7171) DEBUG: name = flip last_ts = 328.961121 last_received_ts = 328.960327 last_seq = 1395 current_ts = 328.977783 current_received_ts = 328.977020 current_seq = 1396 count = 499 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 61us (kms_flip:7171) DEBUG: name = flip last_ts = 328.977783 last_received_ts = 328.977020 last_seq = 1396 current_ts = 328.994446 current_received_ts = 328.993652 current_seq = 1397 count = 500 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 328.994446 last_received_ts = 328.993652 last_seq = 1397 current_ts = 329.011108 current_received_ts = 329.010315 current_seq = 1398 count = 501 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 56us (kms_flip:7171) DEBUG: name = flip last_ts = 329.011108 last_received_ts = 329.010315 last_seq = 1398 current_ts = 329.027771 current_received_ts = 329.027069 current_seq = 1399 count = 502 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 122us (kms_flip:7171) DEBUG: name = flip last_ts = 329.027771 last_received_ts = 329.027069 last_seq = 1399 current_ts = 329.044434 current_received_ts = 329.043671 current_seq = 1400 count = 503 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 61us (kms_flip:7171) DEBUG: name = flip last_ts = 329.044434 last_received_ts = 329.043671 last_seq = 1400 current_ts = 329.061096 current_received_ts = 329.060303 current_seq = 1401 count = 504 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 64us (kms_flip:7171) DEBUG: name = flip last_ts = 329.061096 last_received_ts = 329.060303 last_seq = 1401 current_ts = 329.077759 current_received_ts = 329.076996 current_seq = 1402 count = 505 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 89us (kms_flip:7171) DEBUG: name = flip last_ts = 329.077759 last_received_ts = 329.076996 last_seq = 1402 current_ts = 329.094421 current_received_ts = 329.093658 current_seq = 1403 count = 506 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 59us (kms_flip:7171) DEBUG: name = flip last_ts = 329.094421 last_received_ts = 329.093658 last_seq = 1403 current_ts = 329.111084 current_received_ts = 329.110291 current_seq = 1404 count = 507 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 47us (kms_flip:7171) DEBUG: name = flip last_ts = 329.111084 last_received_ts = 329.110291 last_seq = 1404 current_ts = 329.127747 current_received_ts = 329.126984 current_seq = 1405 count = 508 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 59us (kms_flip:7171) DEBUG: name = flip last_ts = 329.127747 last_received_ts = 329.126984 last_seq = 1405 current_ts = 329.144440 current_received_ts = 329.143646 current_seq = 1406 count = 509 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 64us (kms_flip:7171) DEBUG: name = flip last_ts = 329.144440 last_received_ts = 329.143646 last_seq = 1406 current_ts = 329.161102 current_received_ts = 329.160278 current_seq = 1407 count = 510 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 57us (kms_flip:7171) DEBUG: name = flip last_ts = 329.161102 last_received_ts = 329.160278 last_seq = 1407 current_ts = 329.177765 current_received_ts = 329.176971 current_seq = 1408 count = 511 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 71us (kms_flip:7171) DEBUG: name = flip last_ts = 329.177765 last_received_ts = 329.176971 last_seq = 1408 current_ts = 329.194427 current_received_ts = 329.193634 current_seq = 1409 count = 512 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 57us (kms_flip:7171) DEBUG: name = flip last_ts = 329.194427 last_received_ts = 329.193634 last_seq = 1409 current_ts = 329.211090 current_received_ts = 329.210266 current_seq = 1410 count = 513 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 55us (kms_flip:7171) DEBUG: name = flip last_ts = 329.211090 last_received_ts = 329.210266 last_seq = 1410 current_ts = 329.227753 current_received_ts = 329.226959 current_seq = 1411 count = 514 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 86us (kms_flip:7171) DEBUG: name = flip last_ts = 329.227753 last_received_ts = 329.226959 last_seq = 1411 current_ts = 329.244415 current_received_ts = 329.243622 current_seq = 1412 count = 515 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 62us (kms_flip:7171) DEBUG: name = flip last_ts = 329.244415 last_received_ts = 329.243622 last_seq = 1412 current_ts = 329.261078 current_received_ts = 329.260284 current_seq = 1413 count = 516 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 61us (kms_flip:7171) DEBUG: name = flip last_ts = 329.261078 last_received_ts = 329.260284 last_seq = 1413 current_ts = 329.277740 current_received_ts = 329.276947 current_seq = 1414 count = 517 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 67us (kms_flip:7171) DEBUG: name = flip last_ts = 329.277740 last_received_ts = 329.276947 last_seq = 1414 current_ts = 329.294403 current_received_ts = 329.293610 current_seq = 1415 count = 518 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 63us (kms_flip:7171) DEBUG: name = flip last_ts = 329.294403 last_received_ts = 329.293610 last_seq = 1415 current_ts = 329.311066 current_received_ts = 329.310272 current_seq = 1416 count = 519 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 53us (kms_flip:7171) DEBUG: name = flip last_ts = 329.311066 last_received_ts = 329.310272 last_seq = 1416 current_ts = 329.327728 current_received_ts = 329.326935 current_seq = 1417 count = 520 seq_step = 1 (kms_flip:7171) DEBUG: Vblank took 688us (kms_flip:7171) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:7171) CRITICAL: Failed assertion: end - start < 500 (kms_flip:7171) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:7171) igt_core-INFO: Stack trace: (kms_flip:7171) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:7171) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:7171) igt_core-INFO: #2 ../tests/kms_flip.c:1889 run_test() (kms_flip:7171) igt_core-INFO: #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045() (kms_flip:7171) igt_core-INFO: #4 ../tests/kms_flip.c:2045 main() (kms_flip:7171) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:7171) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:7171) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (9.928s)
Dmesg	<6> [319.478867] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [319.502050] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [319.502177] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [319.502273] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [319.502319] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:245] <7> [319.502681] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:247] <7> [319.558803] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:88:pipe A] <7> [319.558924] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [319.559079] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [319.559196] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [319.559305] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [319.559411] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [319.559517] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [319.559653] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [319.559760] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [319.559869] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [319.559976] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [319.560083] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [319.560187] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [319.560293] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [319.560400] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [319.560505] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [319.560616] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [319.560718] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [319.560819] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [319.560921] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [319.561021] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [319.561123] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [319.561227] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [319.561333] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [319.561441] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [319.561547] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [319.561660] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [319.561765] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [319.561868] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [319.561969] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [319.562068] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [319.562167] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [319.562267] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [319.562366] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [319.562467] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [319.562572] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [319.562683] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [319.562789] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [319.562890] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [319.562993] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:88:pipe A] fastset requirement not met, forcing full modeset <7> [319.563098] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:88:pipe A] releasing DPLL 0 <7> [319.563252] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [319.563341] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:88:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [319.563450] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:83:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [319.563549] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:88:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [319.563673] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [319.563786] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [319.563895] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [319.564034] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:88:pipe A] enable: no [modeset] <7> [319.564149] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:33:plane 1A] fb: [NOFB], visible: no <7> [319.564263] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:43:plane 2A] fb: [NOFB], visible: no <7> [319.564374] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:53:plane 3A] fb: [NOFB], visible: no <7> [319.564480] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:63:plane 4A] fb: [NOFB], visible: no <7> [319.564593] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:73:plane 5A] fb: [NOFB], visible: no <7> [319.564700] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:83:cursor A] fb: [NOFB], visible: no <7> [319.564862] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [319.564982] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [319.565250] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [319.565366] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [319.770655] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:208:eDP-1] set backlight PWM = 0 <7> [319.771341] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [319.776987] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 turn panel power off <7> [319.777320] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 wait for panel power off time <7> [319.777640] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [319.829752] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [319.830123] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:207:DDI A/PHY A] - short <7> [319.837639] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [319.838067] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:88:pipe A] <7> [319.838093] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:207:DDI A/PHY A] <7> [319.839364] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [319.839826] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [319.840296] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:207:DDI A/PHY A] <7> [319.840656] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DDI TC1/PHY TC1] <7> [319.840945] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:218:DP-MST A] <7> [319.841216] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:219:DP-MST B] <7> [319.841481] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:220:DP-MST C] <7> [319.841769] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DDI TC2/PHY TC2] <7> [319.842034] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:230:DP-MST A] <7> [319.842301] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:231:DP-MST B] <7> [319.842565] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:232:DP-MST C] <7> [319.842849] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DDI TC3/PHY TC3] <7> [319.843120] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:238:DP-MST A] <7> [319.843387] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:239:DP-MST B] <7> [319.843679] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:240:DP-MST C] <7> [319.843957] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:208:eDP-1] <7> [319.844316] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [319.844612] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [319.844868] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [319.845301] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [319.845764] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:88:pipe A] <7> [319.846090] 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> [319.846475] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [319.846785] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [319.847773] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:146:pipe B] <7> [319.848251] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:204:pipe C] <7> [319.848619] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:146:pipe B] <7> [319.848704] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:208:eDP-1] <7> [319.848941] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:208:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [319.849384] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:207:DDI A/PHY A][CRTC:146:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 max link_bpp 30.0000 <7> [319.849753] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 link rate required 1303913 available 1728000 <7> [319.850107] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:146:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [319.850434] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:207:DDI A/PHY A] [CRTC:146:pipe B] <7> [319.850783] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [319.851084] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [319.851367] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [319.851674] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [319.851945] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [319.852200] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [319.852455] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [319.852718] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [319.852958] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [319.853182] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [319.853397] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [319.853617] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [319.853822] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [319.854022] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [319.854218] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [319.854406] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [319.854606] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [319.854792] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [319.854968] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [319.855138] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [319.855310] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [319.855474] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [319.855668] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [319.855825] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [319.855974] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [319.856119] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [319.856259] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [319.856396] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [319.856536] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [319.856689] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [319.856828] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [319.856962] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [319.857099] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [319.857226] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [319.857359] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [319.857485] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [319.857617] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [319.857741] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [319.857863] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:146:pipe B] fastset requirement not met, forcing full modeset <7> [319.858086] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [319.858185] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:146:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [319.858314] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:91:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [319.858396] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:141:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [319.858474] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:91:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [319.858554] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:91:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [319.858740] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:91:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [319.858837] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:91:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [319.858953] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:146:pipe B] data rate 1390840 num active planes 1 <7> [319.859080] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [319.859210] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [319.859321] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [319.859440] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [319.859553] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [319.859682] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:146:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [319.859833] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [319.859941] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [319.860046] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [319.860172] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:146:pipe B] allocated DPLL 0 <7> [319.860270] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:146:pipe B] reserving DPLL 0 <7> [319.860376] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:146:pipe B] enable: yes [modeset] <7> [319.860489] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [319.860615] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [319.860728] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [319.860839] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [319.860950] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [319.861064] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [319.861177] 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> [319.861286] 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> [319.861398] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [319.861507] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [319.861624] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [319.861732] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [319.861841] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [319.861950] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [319.862062] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [319.862171] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [319.862284] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [319.862396] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [319.862506] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [319.862632] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [319.862742] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [319.862847] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [319.862954] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [319.863059] 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> [319.863165] 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> [319.863276] 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> [319.863384] 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> [319.863493] 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> [319.863618] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855 <7> [319.863729] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [319.863838] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [319.863947] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [319.864055] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [319.864161] 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> [319.864266] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: clock: 432000, fracen: no, <7> [319.864371] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [319.864475] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [319.864592] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [319.864700] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [319.864810] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [319.864917] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [319.865026] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [319.865135] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [319.865245] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [319.865353] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [319.865458] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [319.865563] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [319.865690] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [319.865693] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [319.865799] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [319.865831] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [319.865906] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [319.865949] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [319.866012] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [319.866083] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [319.866119] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [319.866178] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:207:DDI A/PHY A] - long <7> [319.866227] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [319.866273] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [319.866334] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [319.866411] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [319.866444] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [319.866417] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:207:DDI A/PHY A] <7> [319.866551] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [319.866671] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:91:plane 1B] fb: [FB:245] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [319.866779] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [319.866884] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [319.866990] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:101:plane 2B] fb: [NOFB], visible: no <7> [319.867095] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:111:plane 3B] fb: [NOFB], visible: no <7> [319.867201] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:121:plane 4B] fb: [NOFB], visible: no <7> [319.867307] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:131:plane 5B] fb: [NOFB], visible: no <7> [319.867413] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:141:cursor B] fb: [NOFB], visible: no <7> [319.867966] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [319.868081] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [319.868342] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [319.868495] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [319.868660] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [319.868829] 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> [319.868948] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [319.869052] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [319.869160] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:207:DDI A/PHY A] <7> [319.869246] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DDI TC1/PHY TC1] <7> [319.869329] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:218:DP-MST A] <7> [319.869410] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:219:DP-MST B] <7> [319.869492] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:220:DP-MST C] <7> [319.869576] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DDI TC2/PHY TC2] <7> [319.869672] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:230:DP-MST A] <7> [319.869757] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:231:DP-MST B] <7> [319.869841] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:232:DP-MST C] <7> [319.869925] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DDI TC3/PHY TC3] <7> [319.870011] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:238:DP-MST A] <7> [319.870095] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:239:DP-MST B] <7> [319.870178] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:240:DP-MST C] <7> [319.870284] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [319.870463] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [319.870550] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [319.870689] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [319.871603] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:146:pipe B] <7> [319.871713] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [319.873412] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 turn panel power on <7> [319.873510] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 wait for panel power cycle (465 ms remaining) <7> [320.346684] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [320.387317] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [320.387845] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 wait for panel power on <7> [320.388331] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [320.424073] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [320.424533] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:207:DDI A/PHY A] - long <7> [320.424966] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [320.425419] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:207:DDI A/PHY A] <7> [320.600930] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [320.601770] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 turning VDD on <7> [320.602357] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [320.605100] 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> [320.606495] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [320.607646] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [320.608991] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [320.610311] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [320.611607] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Clock recovery OK <7> [320.612093] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [320.613749] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [320.614229] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [320.615204] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [320.615878] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [320.616366] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [320.616958] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:208:eDP-1] set backlight PWM = 4518 <7> [320.632679] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [320.634929] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:208:eDP-1] <7> [320.635522] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:146:pipe B] <7> [323.147561] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 turning VDD off <7> [323.148132] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [329.348508] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [329.349162] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [329.349906] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [329.409825] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

9.93 seconds

Hostname

shard-lnl-4

Igt-Version

IGT-Version: 2.2-g2ce563031 (x86_64) (Linux: 6.18.0-rc7-lgci-xe-xe-4155-e41f42483c6f784fc+ x86_64)

Out

Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1889 run_test()
  #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
  #4 ../tests/kms_flip.c:2045 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (9.928s)

Err

Starting dynamic subtest: B-eDP1
(kms_flip:7171) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:7171) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7171) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:7171) DEBUG: Vblank took 56us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.311340
last_received_ts = 327.310547
last_seq = 1296
current_ts = 327.328003
current_received_ts = 327.327209
current_seq = 1297
count = 400
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.328003
last_received_ts = 327.327209
last_seq = 1297
current_ts = 327.344666
current_received_ts = 327.343872
current_seq = 1298
count = 401
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 57us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.344666
last_received_ts = 327.343872
last_seq = 1298
current_ts = 327.361328
current_received_ts = 327.360565
current_seq = 1299
count = 402
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 105us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.361328
last_received_ts = 327.360565
last_seq = 1299
current_ts = 327.377991
current_received_ts = 327.377197
current_seq = 1300
count = 403
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 67us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.377991
last_received_ts = 327.377197
last_seq = 1300
current_ts = 327.394653
current_received_ts = 327.393860
current_seq = 1301
count = 404
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 64us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.394653
last_received_ts = 327.393860
last_seq = 1301
current_ts = 327.411316
current_received_ts = 327.410522
current_seq = 1302
count = 405
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 83us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.411316
last_received_ts = 327.410522
last_seq = 1302
current_ts = 327.427979
current_received_ts = 327.427185
current_seq = 1303
count = 406
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 58us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.427979
last_received_ts = 327.427185
last_seq = 1303
current_ts = 327.444641
current_received_ts = 327.443878
current_seq = 1304
count = 407
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 57us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.444641
last_received_ts = 327.443878
last_seq = 1304
current_ts = 327.461334
current_received_ts = 327.460541
current_seq = 1305
count = 408
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 63us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.461334
last_received_ts = 327.460541
last_seq = 1305
current_ts = 327.477997
current_received_ts = 327.477173
current_seq = 1306
count = 409
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.477997
last_received_ts = 327.477173
last_seq = 1306
current_ts = 327.494659
current_received_ts = 327.493866
current_seq = 1307
count = 410
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 53us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.494659
last_received_ts = 327.493866
last_seq = 1307
current_ts = 327.511322
current_received_ts = 327.510529
current_seq = 1308
count = 411
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 58us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.511322
last_received_ts = 327.510529
last_seq = 1308
current_ts = 327.527985
current_received_ts = 327.527161
current_seq = 1309
count = 412
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 45us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.527985
last_received_ts = 327.527161
last_seq = 1309
current_ts = 327.544647
current_received_ts = 327.543823
current_seq = 1310
count = 413
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.544647
last_received_ts = 327.543823
last_seq = 1310
current_ts = 327.561310
current_received_ts = 327.560547
current_seq = 1311
count = 414
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 45us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.561310
last_received_ts = 327.560547
last_seq = 1311
current_ts = 327.577972
current_received_ts = 327.577179
current_seq = 1312
count = 415
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 60us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.577972
last_received_ts = 327.577179
last_seq = 1312
current_ts = 327.594635
current_received_ts = 327.593842
current_seq = 1313
count = 416
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 57us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.594635
last_received_ts = 327.593842
last_seq = 1313
current_ts = 327.611298
current_received_ts = 327.610504
current_seq = 1314
count = 417
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 56us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.611298
last_received_ts = 327.610504
last_seq = 1314
current_ts = 327.627960
current_received_ts = 327.627167
current_seq = 1315
count = 418
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 52us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.627960
last_received_ts = 327.627167
last_seq = 1315
current_ts = 327.644623
current_received_ts = 327.643860
current_seq = 1316
count = 419
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 56us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.644623
last_received_ts = 327.643860
last_seq = 1316
current_ts = 327.661285
current_received_ts = 327.660492
current_seq = 1317
count = 420
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 56us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.661285
last_received_ts = 327.660492
last_seq = 1317
current_ts = 327.677948
current_received_ts = 327.677155
current_seq = 1318
count = 421
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 46us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.677948
last_received_ts = 327.677155
last_seq = 1318
current_ts = 327.694611
current_received_ts = 327.693817
current_seq = 1319
count = 422
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 58us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.694611
last_received_ts = 327.693817
last_seq = 1319
current_ts = 327.711273
current_received_ts = 327.710510
current_seq = 1320
count = 423
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 119us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.711273
last_received_ts = 327.710510
last_seq = 1320
current_ts = 327.727966
current_received_ts = 327.727142
current_seq = 1321
count = 424
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.727966
last_received_ts = 327.727142
last_seq = 1321
current_ts = 327.744629
current_received_ts = 327.743835
current_seq = 1322
count = 425
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 59us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.744629
last_received_ts = 327.743835
last_seq = 1322
current_ts = 327.761292
current_received_ts = 327.760498
current_seq = 1323
count = 426
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 58us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.761292
last_received_ts = 327.760498
last_seq = 1323
current_ts = 327.777954
current_received_ts = 327.777161
current_seq = 1324
count = 427
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 107us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.777954
last_received_ts = 327.777161
last_seq = 1324
current_ts = 327.794617
current_received_ts = 327.793823
current_seq = 1325
count = 428
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 68us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.794617
last_received_ts = 327.793823
last_seq = 1325
current_ts = 327.811279
current_received_ts = 327.810486
current_seq = 1326
count = 429
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 64us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.811279
last_received_ts = 327.810486
last_seq = 1326
current_ts = 327.827942
current_received_ts = 327.827148
current_seq = 1327
count = 430
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 47us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.827942
last_received_ts = 327.827148
last_seq = 1327
current_ts = 327.844604
current_received_ts = 327.843842
current_seq = 1328
count = 431
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 123us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.844604
last_received_ts = 327.843842
last_seq = 1328
current_ts = 327.861267
current_received_ts = 327.860474
current_seq = 1329
count = 432
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 59us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.861267
last_received_ts = 327.860474
last_seq = 1329
current_ts = 327.877930
current_received_ts = 327.877136
current_seq = 1330
count = 433
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 43us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.877930
last_received_ts = 327.877136
last_seq = 1330
current_ts = 327.894592
current_received_ts = 327.893799
current_seq = 1331
count = 434
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 62us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.894592
last_received_ts = 327.893799
last_seq = 1331
current_ts = 327.911255
current_received_ts = 327.910492
current_seq = 1332
count = 435
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 58us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.911255
last_received_ts = 327.910492
last_seq = 1332
current_ts = 327.927917
current_received_ts = 327.927124
current_seq = 1333
count = 436
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 57us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.927917
last_received_ts = 327.927124
last_seq = 1333
current_ts = 327.944580
current_received_ts = 327.943817
current_seq = 1334
count = 437
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 53us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.944580
last_received_ts = 327.943817
last_seq = 1334
current_ts = 327.961243
current_received_ts = 327.960449
current_seq = 1335
count = 438
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.961243
last_received_ts = 327.960449
last_seq = 1335
current_ts = 327.977905
current_received_ts = 327.977203
current_seq = 1336
count = 439
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 101us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.977905
last_received_ts = 327.977203
last_seq = 1336
current_ts = 327.994568
current_received_ts = 327.993805
current_seq = 1337
count = 440
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 75us
(kms_flip:7171) DEBUG: name = flip
last_ts = 327.994568
last_received_ts = 327.993805
last_seq = 1337
current_ts = 328.011230
current_received_ts = 328.010468
current_seq = 1338
count = 441
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 45us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.011230
last_received_ts = 328.010468
last_seq = 1338
current_ts = 328.027924
current_received_ts = 328.027100
current_seq = 1339
count = 442
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 67us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.027924
last_received_ts = 328.027100
last_seq = 1339
current_ts = 328.044586
current_received_ts = 328.043793
current_seq = 1340
count = 443
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.044586
last_received_ts = 328.043793
last_seq = 1340
current_ts = 328.061249
current_received_ts = 328.060455
current_seq = 1341
count = 444
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 64us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.061249
last_received_ts = 328.060455
last_seq = 1341
current_ts = 328.077911
current_received_ts = 328.077087
current_seq = 1342
count = 445
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.077911
last_received_ts = 328.077087
last_seq = 1342
current_ts = 328.094574
current_received_ts = 328.093781
current_seq = 1343
count = 446
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 66us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.094574
last_received_ts = 328.093781
last_seq = 1343
current_ts = 328.111237
current_received_ts = 328.110443
current_seq = 1344
count = 447
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 57us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.111237
last_received_ts = 328.110443
last_seq = 1344
current_ts = 328.127899
current_received_ts = 328.127106
current_seq = 1345
count = 448
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 56us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.127899
last_received_ts = 328.127106
last_seq = 1345
current_ts = 328.144562
current_received_ts = 328.143768
current_seq = 1346
count = 449
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.144562
last_received_ts = 328.143768
last_seq = 1346
current_ts = 328.161224
current_received_ts = 328.160461
current_seq = 1347
count = 450
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 58us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.161224
last_received_ts = 328.160461
last_seq = 1347
current_ts = 328.177887
current_received_ts = 328.177094
current_seq = 1348
count = 451
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 67us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.177887
last_received_ts = 328.177094
last_seq = 1348
current_ts = 328.194550
current_received_ts = 328.193756
current_seq = 1349
count = 452
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 42us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.194550
last_received_ts = 328.193756
last_seq = 1349
current_ts = 328.211212
current_received_ts = 328.210419
current_seq = 1350
count = 453
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 42us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.211212
last_received_ts = 328.210419
last_seq = 1350
current_ts = 328.227875
current_received_ts = 328.227081
current_seq = 1351
count = 454
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 65us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.227875
last_received_ts = 328.227081
last_seq = 1351
current_ts = 328.244537
current_received_ts = 328.243774
current_seq = 1352
count = 455
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 57us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.244537
last_received_ts = 328.243774
last_seq = 1352
current_ts = 328.261200
current_received_ts = 328.260437
current_seq = 1353
count = 456
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 59us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.261200
last_received_ts = 328.260437
last_seq = 1353
current_ts = 328.277893
current_received_ts = 328.277130
current_seq = 1354
count = 457
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 58us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.277893
last_received_ts = 328.277130
last_seq = 1354
current_ts = 328.294525
current_received_ts = 328.293762
current_seq = 1355
count = 458
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 43us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.294525
last_received_ts = 328.293762
last_seq = 1355
current_ts = 328.311218
current_received_ts = 328.310394
current_seq = 1356
count = 459
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 58us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.311218
last_received_ts = 328.310394
last_seq = 1356
current_ts = 328.327881
current_received_ts = 328.327057
current_seq = 1357
count = 460
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.327881
last_received_ts = 328.327057
last_seq = 1357
current_ts = 328.344543
current_received_ts = 328.343750
current_seq = 1358
count = 461
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.344543
last_received_ts = 328.343750
last_seq = 1358
current_ts = 328.361206
current_received_ts = 328.360413
current_seq = 1359
count = 462
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 56us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.361206
last_received_ts = 328.360413
last_seq = 1359
current_ts = 328.377869
current_received_ts = 328.377075
current_seq = 1360
count = 463
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.377869
last_received_ts = 328.377075
last_seq = 1360
current_ts = 328.394531
current_received_ts = 328.393738
current_seq = 1361
count = 464
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 46us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.394531
last_received_ts = 328.393738
last_seq = 1361
current_ts = 328.411194
current_received_ts = 328.410400
current_seq = 1362
count = 465
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.411194
last_received_ts = 328.410400
last_seq = 1362
current_ts = 328.427856
current_received_ts = 328.427063
current_seq = 1363
count = 466
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 53us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.427856
last_received_ts = 328.427063
last_seq = 1363
current_ts = 328.444519
current_received_ts = 328.443726
current_seq = 1364
count = 467
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 109us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.444519
last_received_ts = 328.443726
last_seq = 1364
current_ts = 328.461182
current_received_ts = 328.460388
current_seq = 1365
count = 468
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 71us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.461182
last_received_ts = 328.460388
last_seq = 1365
current_ts = 328.477844
current_received_ts = 328.477051
current_seq = 1366
count = 469
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.477844
last_received_ts = 328.477051
last_seq = 1366
current_ts = 328.494507
current_received_ts = 328.493744
current_seq = 1367
count = 470
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 51us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.494507
last_received_ts = 328.493744
last_seq = 1367
current_ts = 328.511169
current_received_ts = 328.510376
current_seq = 1368
count = 471
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 44us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.511169
last_received_ts = 328.510376
last_seq = 1368
current_ts = 328.527832
current_received_ts = 328.527069
current_seq = 1369
count = 472
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.527832
last_received_ts = 328.527069
last_seq = 1369
current_ts = 328.544495
current_received_ts = 328.543732
current_seq = 1370
count = 473
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 52us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.544495
last_received_ts = 328.543732
last_seq = 1370
current_ts = 328.561188
current_received_ts = 328.560364
current_seq = 1371
count = 474
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 57us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.561188
last_received_ts = 328.560364
last_seq = 1371
current_ts = 328.577820
current_received_ts = 328.577057
current_seq = 1372
count = 475
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 59us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.577820
last_received_ts = 328.577057
last_seq = 1372
current_ts = 328.594513
current_received_ts = 328.593719
current_seq = 1373
count = 476
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.594513
last_received_ts = 328.593719
last_seq = 1373
current_ts = 328.611176
current_received_ts = 328.610382
current_seq = 1374
count = 477
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 44us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.611176
last_received_ts = 328.610382
last_seq = 1374
current_ts = 328.627838
current_received_ts = 328.627075
current_seq = 1375
count = 478
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 61us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.627838
last_received_ts = 328.627075
last_seq = 1375
current_ts = 328.644501
current_received_ts = 328.643707
current_seq = 1376
count = 479
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.644501
last_received_ts = 328.643707
last_seq = 1376
current_ts = 328.661163
current_received_ts = 328.660370
current_seq = 1377
count = 480
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 61us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.661163
last_received_ts = 328.660370
last_seq = 1377
current_ts = 328.677826
current_received_ts = 328.677032
current_seq = 1378
count = 481
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 59us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.677826
last_received_ts = 328.677032
last_seq = 1378
current_ts = 328.694489
current_received_ts = 328.693695
current_seq = 1379
count = 482
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.694489
last_received_ts = 328.693695
last_seq = 1379
current_ts = 328.711151
current_received_ts = 328.710358
current_seq = 1380
count = 483
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 42us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.711151
last_received_ts = 328.710358
last_seq = 1380
current_ts = 328.727814
current_received_ts = 328.727051
current_seq = 1381
count = 484
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.727814
last_received_ts = 328.727051
last_seq = 1381
current_ts = 328.744476
current_received_ts = 328.743683
current_seq = 1382
count = 485
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 61us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.744476
last_received_ts = 328.743683
last_seq = 1382
current_ts = 328.761139
current_received_ts = 328.760345
current_seq = 1383
count = 486
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.761139
last_received_ts = 328.760345
last_seq = 1383
current_ts = 328.777802
current_received_ts = 328.777039
current_seq = 1384
count = 487
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 43us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.777802
last_received_ts = 328.777039
last_seq = 1384
current_ts = 328.794464
current_received_ts = 328.793701
current_seq = 1385
count = 488
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 59us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.794464
last_received_ts = 328.793701
last_seq = 1385
current_ts = 328.811127
current_received_ts = 328.810364
current_seq = 1386
count = 489
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 43us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.811127
last_received_ts = 328.810364
last_seq = 1386
current_ts = 328.827789
current_received_ts = 328.826996
current_seq = 1387
count = 490
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.827789
last_received_ts = 328.826996
last_seq = 1387
current_ts = 328.844452
current_received_ts = 328.843689
current_seq = 1388
count = 491
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 58us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.844452
last_received_ts = 328.843689
last_seq = 1388
current_ts = 328.861145
current_received_ts = 328.860352
current_seq = 1389
count = 492
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 45us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.861145
last_received_ts = 328.860352
last_seq = 1389
current_ts = 328.877808
current_received_ts = 328.877014
current_seq = 1390
count = 493
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 58us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.877808
last_received_ts = 328.877014
last_seq = 1390
current_ts = 328.894470
current_received_ts = 328.893677
current_seq = 1391
count = 494
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 56us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.894470
last_received_ts = 328.893677
last_seq = 1391
current_ts = 328.911133
current_received_ts = 328.910339
current_seq = 1392
count = 495
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.911133
last_received_ts = 328.910339
last_seq = 1392
current_ts = 328.927795
current_received_ts = 328.927032
current_seq = 1393
count = 496
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.927795
last_received_ts = 328.927032
last_seq = 1393
current_ts = 328.944458
current_received_ts = 328.943665
current_seq = 1394
count = 497
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 43us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.944458
last_received_ts = 328.943665
last_seq = 1394
current_ts = 328.961121
current_received_ts = 328.960327
current_seq = 1395
count = 498
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 54us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.961121
last_received_ts = 328.960327
last_seq = 1395
current_ts = 328.977783
current_received_ts = 328.977020
current_seq = 1396
count = 499
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 61us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.977783
last_received_ts = 328.977020
last_seq = 1396
current_ts = 328.994446
current_received_ts = 328.993652
current_seq = 1397
count = 500
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 328.994446
last_received_ts = 328.993652
last_seq = 1397
current_ts = 329.011108
current_received_ts = 329.010315
current_seq = 1398
count = 501
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 56us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.011108
last_received_ts = 329.010315
last_seq = 1398
current_ts = 329.027771
current_received_ts = 329.027069
current_seq = 1399
count = 502
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 122us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.027771
last_received_ts = 329.027069
last_seq = 1399
current_ts = 329.044434
current_received_ts = 329.043671
current_seq = 1400
count = 503
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 61us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.044434
last_received_ts = 329.043671
last_seq = 1400
current_ts = 329.061096
current_received_ts = 329.060303
current_seq = 1401
count = 504
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 64us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.061096
last_received_ts = 329.060303
last_seq = 1401
current_ts = 329.077759
current_received_ts = 329.076996
current_seq = 1402
count = 505
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 89us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.077759
last_received_ts = 329.076996
last_seq = 1402
current_ts = 329.094421
current_received_ts = 329.093658
current_seq = 1403
count = 506
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 59us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.094421
last_received_ts = 329.093658
last_seq = 1403
current_ts = 329.111084
current_received_ts = 329.110291
current_seq = 1404
count = 507
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 47us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.111084
last_received_ts = 329.110291
last_seq = 1404
current_ts = 329.127747
current_received_ts = 329.126984
current_seq = 1405
count = 508
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 59us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.127747
last_received_ts = 329.126984
last_seq = 1405
current_ts = 329.144440
current_received_ts = 329.143646
current_seq = 1406
count = 509
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 64us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.144440
last_received_ts = 329.143646
last_seq = 1406
current_ts = 329.161102
current_received_ts = 329.160278
current_seq = 1407
count = 510
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 57us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.161102
last_received_ts = 329.160278
last_seq = 1407
current_ts = 329.177765
current_received_ts = 329.176971
current_seq = 1408
count = 511
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 71us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.177765
last_received_ts = 329.176971
last_seq = 1408
current_ts = 329.194427
current_received_ts = 329.193634
current_seq = 1409
count = 512
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 57us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.194427
last_received_ts = 329.193634
last_seq = 1409
current_ts = 329.211090
current_received_ts = 329.210266
current_seq = 1410
count = 513
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 55us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.211090
last_received_ts = 329.210266
last_seq = 1410
current_ts = 329.227753
current_received_ts = 329.226959
current_seq = 1411
count = 514
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 86us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.227753
last_received_ts = 329.226959
last_seq = 1411
current_ts = 329.244415
current_received_ts = 329.243622
current_seq = 1412
count = 515
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 62us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.244415
last_received_ts = 329.243622
last_seq = 1412
current_ts = 329.261078
current_received_ts = 329.260284
current_seq = 1413
count = 516
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 61us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.261078
last_received_ts = 329.260284
last_seq = 1413
current_ts = 329.277740
current_received_ts = 329.276947
current_seq = 1414
count = 517
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 67us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.277740
last_received_ts = 329.276947
last_seq = 1414
current_ts = 329.294403
current_received_ts = 329.293610
current_seq = 1415
count = 518
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 63us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.294403
last_received_ts = 329.293610
last_seq = 1415
current_ts = 329.311066
current_received_ts = 329.310272
current_seq = 1416
count = 519
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 53us
(kms_flip:7171) DEBUG: name = flip
last_ts = 329.311066
last_received_ts = 329.310272
last_seq = 1416
current_ts = 329.327728
current_received_ts = 329.326935
current_seq = 1417
count = 520
seq_step = 1
(kms_flip:7171) DEBUG: Vblank took 688us
(kms_flip:7171) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:7171) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7171) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:7171) igt_core-INFO: Stack trace:
(kms_flip:7171) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:7171) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:7171) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:7171) igt_core-INFO:   #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
(kms_flip:7171) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:7171) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7171) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7171) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (9.928s)

Dmesg

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

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

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

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

<7> [319.502319] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:245]

<7> [319.502681] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:247]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [319.847773] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:146:pipe B]

<7> [319.848251] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:204:pipe C]

<7> [319.848619] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:146:pipe B]

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

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

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

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

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

<7> [319.850434] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:207:DDI A/PHY A] [CRTC:146:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [319.858554] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:91:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [319.861177] 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> [319.861286] 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> [319.861398] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [319.863059] 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> [319.863165] 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> [319.863276] 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> [319.863384] 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> [319.863493] 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> [319.863618] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855

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

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

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

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

<7> [319.864161] 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> [319.864266] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: clock: 432000, fracen: no,

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [320.605100] 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> [320.606495] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Reloading eDP link rates

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [320.635522] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:146:pipe B]

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

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

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

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

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

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

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