igt@kms_flip@flip-vs-expired-vblank@b-edp1 on shard-lnl@IGTPW

Detail	Value
Duration	9.76 seconds
Hostname	shard-lnl-1
Igt-Version	IGT-Version: 2.3-g9e52dea68 (x86_64) (Linux: 7.0.0-rc2-lgci-xe-xe-4662-e4b36c44f536abdf7-debug+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1887 run_test() #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043() #4 ../tests/kms_flip.c:2043 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (9.764s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:7027) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:7027) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:7027) DEBUG: name = flip last_ts = 434.315216 last_received_ts = 434.314514 last_seq = 1440 current_ts = 434.331909 current_received_ts = 434.331146 current_seq = 1441 count = 383 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 41us (kms_flip:7027) DEBUG: name = flip last_ts = 434.331909 last_received_ts = 434.331146 last_seq = 1441 current_ts = 434.348572 current_received_ts = 434.347961 current_seq = 1442 count = 384 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 83us (kms_flip:7027) DEBUG: name = flip last_ts = 434.348572 last_received_ts = 434.347961 last_seq = 1442 current_ts = 434.365234 current_received_ts = 434.364532 current_seq = 1443 count = 385 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 434.365234 last_received_ts = 434.364532 last_seq = 1443 current_ts = 434.381897 current_received_ts = 434.381226 current_seq = 1444 count = 386 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 103us (kms_flip:7027) DEBUG: name = flip last_ts = 434.381897 last_received_ts = 434.381226 last_seq = 1444 current_ts = 434.398560 current_received_ts = 434.397888 current_seq = 1445 count = 387 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 57us (kms_flip:7027) DEBUG: name = flip last_ts = 434.398560 last_received_ts = 434.397888 last_seq = 1445 current_ts = 434.415222 current_received_ts = 434.414581 current_seq = 1446 count = 388 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 65us (kms_flip:7027) DEBUG: name = flip last_ts = 434.415222 last_received_ts = 434.414581 last_seq = 1446 current_ts = 434.431885 current_received_ts = 434.431244 current_seq = 1447 count = 389 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 96us (kms_flip:7027) DEBUG: name = flip last_ts = 434.431885 last_received_ts = 434.431244 last_seq = 1447 current_ts = 434.448578 current_received_ts = 434.447998 current_seq = 1448 count = 390 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 64us (kms_flip:7027) DEBUG: name = flip last_ts = 434.448578 last_received_ts = 434.447998 last_seq = 1448 current_ts = 434.465240 current_received_ts = 434.464661 current_seq = 1449 count = 391 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 67us (kms_flip:7027) DEBUG: name = flip last_ts = 434.465240 last_received_ts = 434.464661 last_seq = 1449 current_ts = 434.481903 current_received_ts = 434.481232 current_seq = 1450 count = 392 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 69us (kms_flip:7027) DEBUG: name = flip last_ts = 434.481903 last_received_ts = 434.481232 last_seq = 1450 current_ts = 434.498566 current_received_ts = 434.497986 current_seq = 1451 count = 393 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 85us (kms_flip:7027) DEBUG: name = flip last_ts = 434.498566 last_received_ts = 434.497986 last_seq = 1451 current_ts = 434.515228 current_received_ts = 434.514648 current_seq = 1452 count = 394 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 62us (kms_flip:7027) DEBUG: name = flip last_ts = 434.515228 last_received_ts = 434.514648 last_seq = 1452 current_ts = 434.531891 current_received_ts = 434.531342 current_seq = 1453 count = 395 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 111us (kms_flip:7027) DEBUG: name = flip last_ts = 434.531891 last_received_ts = 434.531342 last_seq = 1453 current_ts = 434.548584 current_received_ts = 434.548004 current_seq = 1454 count = 396 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 56us (kms_flip:7027) DEBUG: name = flip last_ts = 434.548584 last_received_ts = 434.548004 last_seq = 1454 current_ts = 434.565247 current_received_ts = 434.564667 current_seq = 1455 count = 397 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 434.565247 last_received_ts = 434.564667 last_seq = 1455 current_ts = 434.581909 current_received_ts = 434.581329 current_seq = 1456 count = 398 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 105us (kms_flip:7027) DEBUG: name = flip last_ts = 434.581909 last_received_ts = 434.581329 last_seq = 1456 current_ts = 434.598572 current_received_ts = 434.597992 current_seq = 1457 count = 399 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 56us (kms_flip:7027) DEBUG: name = flip last_ts = 434.598572 last_received_ts = 434.597992 last_seq = 1457 current_ts = 434.615234 current_received_ts = 434.614655 current_seq = 1458 count = 400 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 55us (kms_flip:7027) DEBUG: name = flip last_ts = 434.615234 last_received_ts = 434.614655 last_seq = 1458 current_ts = 434.631927 current_received_ts = 434.631348 current_seq = 1459 count = 401 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 104us (kms_flip:7027) DEBUG: name = flip last_ts = 434.631927 last_received_ts = 434.631348 last_seq = 1459 current_ts = 434.648590 current_received_ts = 434.648041 current_seq = 1460 count = 402 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 56us (kms_flip:7027) DEBUG: name = flip last_ts = 434.648590 last_received_ts = 434.648041 last_seq = 1460 current_ts = 434.665253 current_received_ts = 434.664673 current_seq = 1461 count = 403 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 60us (kms_flip:7027) DEBUG: name = flip last_ts = 434.665253 last_received_ts = 434.664673 last_seq = 1461 current_ts = 434.681915 current_received_ts = 434.681335 current_seq = 1462 count = 404 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 111us (kms_flip:7027) DEBUG: name = flip last_ts = 434.681915 last_received_ts = 434.681335 last_seq = 1462 current_ts = 434.698578 current_received_ts = 434.697998 current_seq = 1463 count = 405 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 57us (kms_flip:7027) DEBUG: name = flip last_ts = 434.698578 last_received_ts = 434.697998 last_seq = 1463 current_ts = 434.715240 current_received_ts = 434.714661 current_seq = 1464 count = 406 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 434.715240 last_received_ts = 434.714661 last_seq = 1464 current_ts = 434.731903 current_received_ts = 434.731354 current_seq = 1465 count = 407 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 81us (kms_flip:7027) DEBUG: name = flip last_ts = 434.731903 last_received_ts = 434.731354 last_seq = 1465 current_ts = 434.748596 current_received_ts = 434.747986 current_seq = 1466 count = 408 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 57us (kms_flip:7027) DEBUG: name = flip last_ts = 434.748596 last_received_ts = 434.747986 last_seq = 1466 current_ts = 434.765259 current_received_ts = 434.764679 current_seq = 1467 count = 409 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 62us (kms_flip:7027) DEBUG: name = flip last_ts = 434.765259 last_received_ts = 434.764679 last_seq = 1467 current_ts = 434.781921 current_received_ts = 434.781342 current_seq = 1468 count = 410 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 117us (kms_flip:7027) DEBUG: name = flip last_ts = 434.781921 last_received_ts = 434.781342 last_seq = 1468 current_ts = 434.798584 current_received_ts = 434.798035 current_seq = 1469 count = 411 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 63us (kms_flip:7027) DEBUG: name = flip last_ts = 434.798584 last_received_ts = 434.798035 last_seq = 1469 current_ts = 434.815247 current_received_ts = 434.814697 current_seq = 1470 count = 412 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 434.815247 last_received_ts = 434.814697 last_seq = 1470 current_ts = 434.831940 current_received_ts = 434.831360 current_seq = 1471 count = 413 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 95us (kms_flip:7027) DEBUG: name = flip last_ts = 434.831940 last_received_ts = 434.831360 last_seq = 1471 current_ts = 434.848602 current_received_ts = 434.848022 current_seq = 1472 count = 414 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 434.848602 last_received_ts = 434.848022 last_seq = 1472 current_ts = 434.865265 current_received_ts = 434.864685 current_seq = 1473 count = 415 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 434.865265 last_received_ts = 434.864685 last_seq = 1473 current_ts = 434.881927 current_received_ts = 434.881348 current_seq = 1474 count = 416 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 112us (kms_flip:7027) DEBUG: name = flip last_ts = 434.881927 last_received_ts = 434.881348 last_seq = 1474 current_ts = 434.898590 current_received_ts = 434.898041 current_seq = 1475 count = 417 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 434.898590 last_received_ts = 434.898041 last_seq = 1475 current_ts = 434.915253 current_received_ts = 434.914703 current_seq = 1476 count = 418 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 434.915253 last_received_ts = 434.914703 last_seq = 1476 current_ts = 434.931915 current_received_ts = 434.931366 current_seq = 1477 count = 419 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 107us (kms_flip:7027) DEBUG: name = flip last_ts = 434.931915 last_received_ts = 434.931366 last_seq = 1477 current_ts = 434.948608 current_received_ts = 434.948059 current_seq = 1478 count = 420 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 57us (kms_flip:7027) DEBUG: name = flip last_ts = 434.948608 last_received_ts = 434.948059 last_seq = 1478 current_ts = 434.965271 current_received_ts = 434.964661 current_seq = 1479 count = 421 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 44us (kms_flip:7027) DEBUG: name = flip last_ts = 434.965271 last_received_ts = 434.964661 last_seq = 1479 current_ts = 434.981934 current_received_ts = 434.981384 current_seq = 1480 count = 422 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 103us (kms_flip:7027) DEBUG: name = flip last_ts = 434.981934 last_received_ts = 434.981384 last_seq = 1480 current_ts = 434.998596 current_received_ts = 434.998016 current_seq = 1481 count = 423 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 434.998596 last_received_ts = 434.998016 last_seq = 1481 current_ts = 435.015259 current_received_ts = 435.014679 current_seq = 1482 count = 424 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.015259 last_received_ts = 435.014679 last_seq = 1482 current_ts = 435.031952 current_received_ts = 435.031372 current_seq = 1483 count = 425 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 106us (kms_flip:7027) DEBUG: name = flip last_ts = 435.031952 last_received_ts = 435.031372 last_seq = 1483 current_ts = 435.048615 current_received_ts = 435.048065 current_seq = 1484 count = 426 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 57us (kms_flip:7027) DEBUG: name = flip last_ts = 435.048615 last_received_ts = 435.048065 last_seq = 1484 current_ts = 435.065277 current_received_ts = 435.064697 current_seq = 1485 count = 427 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 435.065277 last_received_ts = 435.064697 last_seq = 1485 current_ts = 435.081940 current_received_ts = 435.081360 current_seq = 1486 count = 428 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 108us (kms_flip:7027) DEBUG: name = flip last_ts = 435.081940 last_received_ts = 435.081360 last_seq = 1486 current_ts = 435.098602 current_received_ts = 435.098022 current_seq = 1487 count = 429 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 63us (kms_flip:7027) DEBUG: name = flip last_ts = 435.098602 last_received_ts = 435.098022 last_seq = 1487 current_ts = 435.115265 current_received_ts = 435.114685 current_seq = 1488 count = 430 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.115265 last_received_ts = 435.114685 last_seq = 1488 current_ts = 435.131927 current_received_ts = 435.131378 current_seq = 1489 count = 431 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 103us (kms_flip:7027) DEBUG: name = flip last_ts = 435.131927 last_received_ts = 435.131378 last_seq = 1489 current_ts = 435.148590 current_received_ts = 435.148041 current_seq = 1490 count = 432 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 435.148590 last_received_ts = 435.148041 last_seq = 1490 current_ts = 435.165283 current_received_ts = 435.164703 current_seq = 1491 count = 433 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.165283 last_received_ts = 435.164703 last_seq = 1491 current_ts = 435.181946 current_received_ts = 435.181396 current_seq = 1492 count = 434 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 74us (kms_flip:7027) DEBUG: name = flip last_ts = 435.181946 last_received_ts = 435.181396 last_seq = 1492 current_ts = 435.198608 current_received_ts = 435.198059 current_seq = 1493 count = 435 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 435.198608 last_received_ts = 435.198059 last_seq = 1493 current_ts = 435.215271 current_received_ts = 435.214691 current_seq = 1494 count = 436 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.215271 last_received_ts = 435.214691 last_seq = 1494 current_ts = 435.231934 current_received_ts = 435.231384 current_seq = 1495 count = 437 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 116us (kms_flip:7027) DEBUG: name = flip last_ts = 435.231934 last_received_ts = 435.231384 last_seq = 1495 current_ts = 435.248596 current_received_ts = 435.248016 current_seq = 1496 count = 438 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 62us (kms_flip:7027) DEBUG: name = flip last_ts = 435.248596 last_received_ts = 435.248016 last_seq = 1496 current_ts = 435.265289 current_received_ts = 435.264709 current_seq = 1497 count = 439 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 435.265289 last_received_ts = 435.264709 last_seq = 1497 current_ts = 435.281952 current_received_ts = 435.281372 current_seq = 1498 count = 440 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 106us (kms_flip:7027) DEBUG: name = flip last_ts = 435.281952 last_received_ts = 435.281372 last_seq = 1498 current_ts = 435.298615 current_received_ts = 435.298065 current_seq = 1499 count = 441 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 60us (kms_flip:7027) DEBUG: name = flip last_ts = 435.298615 last_received_ts = 435.298065 last_seq = 1499 current_ts = 435.315277 current_received_ts = 435.314728 current_seq = 1500 count = 442 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 435.315277 last_received_ts = 435.314728 last_seq = 1500 current_ts = 435.331940 current_received_ts = 435.331390 current_seq = 1501 count = 443 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 97us (kms_flip:7027) DEBUG: name = flip last_ts = 435.331940 last_received_ts = 435.331390 last_seq = 1501 current_ts = 435.348602 current_received_ts = 435.348053 current_seq = 1502 count = 444 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 435.348602 last_received_ts = 435.348053 last_seq = 1502 current_ts = 435.365295 current_received_ts = 435.364716 current_seq = 1503 count = 445 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 435.365295 last_received_ts = 435.364716 last_seq = 1503 current_ts = 435.381958 current_received_ts = 435.381378 current_seq = 1504 count = 446 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 83us (kms_flip:7027) DEBUG: name = flip last_ts = 435.381958 last_received_ts = 435.381378 last_seq = 1504 current_ts = 435.398621 current_received_ts = 435.398071 current_seq = 1505 count = 447 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.398621 last_received_ts = 435.398071 last_seq = 1505 current_ts = 435.415283 current_received_ts = 435.414703 current_seq = 1506 count = 448 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 435.415283 last_received_ts = 435.414703 last_seq = 1506 current_ts = 435.431946 current_received_ts = 435.431366 current_seq = 1507 count = 449 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 107us (kms_flip:7027) DEBUG: name = flip last_ts = 435.431946 last_received_ts = 435.431366 last_seq = 1507 current_ts = 435.448639 current_received_ts = 435.448059 current_seq = 1508 count = 450 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.448639 last_received_ts = 435.448059 last_seq = 1508 current_ts = 435.465302 current_received_ts = 435.464691 current_seq = 1509 count = 451 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 435.465302 last_received_ts = 435.464691 last_seq = 1509 current_ts = 435.481964 current_received_ts = 435.481354 current_seq = 1510 count = 452 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 100us (kms_flip:7027) DEBUG: name = flip last_ts = 435.481964 last_received_ts = 435.481354 last_seq = 1510 current_ts = 435.498627 current_received_ts = 435.498047 current_seq = 1511 count = 453 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.498627 last_received_ts = 435.498047 last_seq = 1511 current_ts = 435.515289 current_received_ts = 435.514709 current_seq = 1512 count = 454 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.515289 last_received_ts = 435.514709 last_seq = 1512 current_ts = 435.531952 current_received_ts = 435.531372 current_seq = 1513 count = 455 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 115us (kms_flip:7027) DEBUG: name = flip last_ts = 435.531952 last_received_ts = 435.531372 last_seq = 1513 current_ts = 435.548615 current_received_ts = 435.548065 current_seq = 1514 count = 456 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 60us (kms_flip:7027) DEBUG: name = flip last_ts = 435.548615 last_received_ts = 435.548065 last_seq = 1514 current_ts = 435.565277 current_received_ts = 435.564697 current_seq = 1515 count = 457 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 65us (kms_flip:7027) DEBUG: name = flip last_ts = 435.565277 last_received_ts = 435.564697 last_seq = 1515 current_ts = 435.581970 current_received_ts = 435.581390 current_seq = 1516 count = 458 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 109us (kms_flip:7027) DEBUG: name = flip last_ts = 435.581970 last_received_ts = 435.581390 last_seq = 1516 current_ts = 435.598633 current_received_ts = 435.598083 current_seq = 1517 count = 459 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 435.598633 last_received_ts = 435.598083 last_seq = 1517 current_ts = 435.615295 current_received_ts = 435.614746 current_seq = 1518 count = 460 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 435.615295 last_received_ts = 435.614746 last_seq = 1518 current_ts = 435.631958 current_received_ts = 435.631409 current_seq = 1519 count = 461 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 109us (kms_flip:7027) DEBUG: name = flip last_ts = 435.631958 last_received_ts = 435.631409 last_seq = 1519 current_ts = 435.648621 current_received_ts = 435.648071 current_seq = 1520 count = 462 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.648621 last_received_ts = 435.648071 last_seq = 1520 current_ts = 435.665283 current_received_ts = 435.664734 current_seq = 1521 count = 463 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 62us (kms_flip:7027) DEBUG: name = flip last_ts = 435.665283 last_received_ts = 435.664734 last_seq = 1521 current_ts = 435.681976 current_received_ts = 435.681396 current_seq = 1522 count = 464 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 115us (kms_flip:7027) DEBUG: name = flip last_ts = 435.681976 last_received_ts = 435.681396 last_seq = 1522 current_ts = 435.698639 current_received_ts = 435.698059 current_seq = 1523 count = 465 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 435.698639 last_received_ts = 435.698059 last_seq = 1523 current_ts = 435.715302 current_received_ts = 435.714722 current_seq = 1524 count = 466 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 66us (kms_flip:7027) DEBUG: name = flip last_ts = 435.715302 last_received_ts = 435.714722 last_seq = 1524 current_ts = 435.731964 current_received_ts = 435.731415 current_seq = 1525 count = 467 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 79us (kms_flip:7027) DEBUG: name = flip last_ts = 435.731964 last_received_ts = 435.731415 last_seq = 1525 current_ts = 435.748627 current_received_ts = 435.748077 current_seq = 1526 count = 468 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.748627 last_received_ts = 435.748077 last_seq = 1526 current_ts = 435.765289 current_received_ts = 435.764740 current_seq = 1527 count = 469 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 435.765289 last_received_ts = 435.764740 last_seq = 1527 current_ts = 435.781982 current_received_ts = 435.781403 current_seq = 1528 count = 470 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 104us (kms_flip:7027) DEBUG: name = flip last_ts = 435.781982 last_received_ts = 435.781403 last_seq = 1528 current_ts = 435.798645 current_received_ts = 435.798065 current_seq = 1529 count = 471 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 435.798645 last_received_ts = 435.798065 last_seq = 1529 current_ts = 435.815308 current_received_ts = 435.814728 current_seq = 1530 count = 472 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 63us (kms_flip:7027) DEBUG: name = flip last_ts = 435.815308 last_received_ts = 435.814728 last_seq = 1530 current_ts = 435.831970 current_received_ts = 435.831421 current_seq = 1531 count = 473 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 105us (kms_flip:7027) DEBUG: name = flip last_ts = 435.831970 last_received_ts = 435.831421 last_seq = 1531 current_ts = 435.848633 current_received_ts = 435.848083 current_seq = 1532 count = 474 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 63us (kms_flip:7027) DEBUG: name = flip last_ts = 435.848633 last_received_ts = 435.848083 last_seq = 1532 current_ts = 435.865326 current_received_ts = 435.864746 current_seq = 1533 count = 475 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 68us (kms_flip:7027) DEBUG: name = flip last_ts = 435.865326 last_received_ts = 435.864746 last_seq = 1533 current_ts = 435.881958 current_received_ts = 435.881409 current_seq = 1534 count = 476 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 93us (kms_flip:7027) DEBUG: name = flip last_ts = 435.881958 last_received_ts = 435.881409 last_seq = 1534 current_ts = 435.898651 current_received_ts = 435.898071 current_seq = 1535 count = 477 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 435.898651 last_received_ts = 435.898071 last_seq = 1535 current_ts = 435.915314 current_received_ts = 435.914734 current_seq = 1536 count = 478 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.915314 last_received_ts = 435.914734 last_seq = 1536 current_ts = 435.931976 current_received_ts = 435.931427 current_seq = 1537 count = 479 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 116us (kms_flip:7027) DEBUG: name = flip last_ts = 435.931976 last_received_ts = 435.931427 last_seq = 1537 current_ts = 435.948639 current_received_ts = 435.948059 current_seq = 1538 count = 480 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 60us (kms_flip:7027) DEBUG: name = flip last_ts = 435.948639 last_received_ts = 435.948059 last_seq = 1538 current_ts = 435.965302 current_received_ts = 435.964752 current_seq = 1539 count = 481 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 435.965302 last_received_ts = 435.964752 last_seq = 1539 current_ts = 435.981995 current_received_ts = 435.981415 current_seq = 1540 count = 482 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 114us (kms_flip:7027) DEBUG: name = flip last_ts = 435.981995 last_received_ts = 435.981415 last_seq = 1540 current_ts = 435.998657 current_received_ts = 435.998077 current_seq = 1541 count = 483 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 435.998657 last_received_ts = 435.998077 last_seq = 1541 current_ts = 436.015320 current_received_ts = 436.014740 current_seq = 1542 count = 484 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 62us (kms_flip:7027) DEBUG: name = flip last_ts = 436.015320 last_received_ts = 436.014740 last_seq = 1542 current_ts = 436.031982 current_received_ts = 436.031433 current_seq = 1543 count = 485 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 107us (kms_flip:7027) DEBUG: name = flip last_ts = 436.031982 last_received_ts = 436.031433 last_seq = 1543 current_ts = 436.048645 current_received_ts = 436.048096 current_seq = 1544 count = 486 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 436.048645 last_received_ts = 436.048096 last_seq = 1544 current_ts = 436.065308 current_received_ts = 436.064758 current_seq = 1545 count = 487 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 436.065308 last_received_ts = 436.064758 last_seq = 1545 current_ts = 436.081970 current_received_ts = 436.081421 current_seq = 1546 count = 488 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 98us (kms_flip:7027) DEBUG: name = flip last_ts = 436.081970 last_received_ts = 436.081421 last_seq = 1546 current_ts = 436.098633 current_received_ts = 436.098053 current_seq = 1547 count = 489 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 436.098633 last_received_ts = 436.098053 last_seq = 1547 current_ts = 436.115326 current_received_ts = 436.114746 current_seq = 1548 count = 490 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 436.115326 last_received_ts = 436.114746 last_seq = 1548 current_ts = 436.131989 current_received_ts = 436.131439 current_seq = 1549 count = 491 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 93us (kms_flip:7027) DEBUG: name = flip last_ts = 436.131989 last_received_ts = 436.131439 last_seq = 1549 current_ts = 436.148651 current_received_ts = 436.148102 current_seq = 1550 count = 492 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 436.148651 last_received_ts = 436.148102 last_seq = 1550 current_ts = 436.165314 current_received_ts = 436.164734 current_seq = 1551 count = 493 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 436.165314 last_received_ts = 436.164734 last_seq = 1551 current_ts = 436.181976 current_received_ts = 436.181427 current_seq = 1552 count = 494 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 106us (kms_flip:7027) DEBUG: name = flip last_ts = 436.181976 last_received_ts = 436.181427 last_seq = 1552 current_ts = 436.198639 current_received_ts = 436.198090 current_seq = 1553 count = 495 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 436.198639 last_received_ts = 436.198090 last_seq = 1553 current_ts = 436.215332 current_received_ts = 436.214752 current_seq = 1554 count = 496 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 58us (kms_flip:7027) DEBUG: name = flip last_ts = 436.215332 last_received_ts = 436.214752 last_seq = 1554 current_ts = 436.231995 current_received_ts = 436.231323 current_seq = 1555 count = 497 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 64us (kms_flip:7027) DEBUG: name = flip last_ts = 436.231995 last_received_ts = 436.231323 last_seq = 1555 current_ts = 436.248657 current_received_ts = 436.248077 current_seq = 1556 count = 498 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 64us (kms_flip:7027) DEBUG: name = flip last_ts = 436.248657 last_received_ts = 436.248077 last_seq = 1556 current_ts = 436.265320 current_received_ts = 436.264740 current_seq = 1557 count = 499 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 436.265320 last_received_ts = 436.264740 last_seq = 1557 current_ts = 436.281982 current_received_ts = 436.281433 current_seq = 1558 count = 500 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 113us (kms_flip:7027) DEBUG: name = flip last_ts = 436.281982 last_received_ts = 436.281433 last_seq = 1558 current_ts = 436.298645 current_received_ts = 436.298126 current_seq = 1559 count = 501 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 69us (kms_flip:7027) DEBUG: name = flip last_ts = 436.298645 last_received_ts = 436.298126 last_seq = 1559 current_ts = 436.315338 current_received_ts = 436.314758 current_seq = 1560 count = 502 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 61us (kms_flip:7027) DEBUG: name = flip last_ts = 436.315338 last_received_ts = 436.314758 last_seq = 1560 current_ts = 436.332001 current_received_ts = 436.331329 current_seq = 1561 count = 503 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 59us (kms_flip:7027) DEBUG: name = flip last_ts = 436.332001 last_received_ts = 436.331329 last_seq = 1561 current_ts = 436.348663 current_received_ts = 436.348114 current_seq = 1562 count = 504 seq_step = 1 (kms_flip:7027) DEBUG: Vblank took 1364us (kms_flip:7027) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926: (kms_flip:7027) CRITICAL: Failed assertion: end - start < 500 (kms_flip:7027) igt_core-INFO: Stack trace: (kms_flip:7027) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:7027) igt_core-INFO: #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0() (kms_flip:7027) igt_core-INFO: #2 ../tests/kms_flip.c:1887 run_test() (kms_flip:7027) igt_core-INFO: #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043() (kms_flip:7027) igt_core-INFO: #4 ../tests/kms_flip.c:2043 main() (kms_flip:7027) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:7027) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:7027) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (9.764s)
Dmesg	<6> [472.882179] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [472.898226] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [472.898355] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [472.898450] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [472.898595] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:429] <7> [472.899005] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:433] <7> [472.979630] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:150:pipe A] <7> [472.979880] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [472.980236] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [472.980540] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [472.980808] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [472.981062] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150: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> [472.981312] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [472.981588] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [472.981829] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [472.982064] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [472.982350] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [472.982676] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [472.982954] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [472.983213] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [472.983424] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [472.983670] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [472.983879] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [472.984094] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [472.984289] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [472.984490] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [472.984677] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [472.984892] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [472.985086] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [472.985262] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [472.985432] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [472.985635] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [472.985799] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [472.985987] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [472.986152] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [472.986305] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [472.986466] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [472.986647] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [472.986800] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [472.986946] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [472.987092] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [472.987241] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [472.987390] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [472.987554] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [472.987700] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:150:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [472.987842] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:150:pipe A] fastset requirement not met, forcing full modeset <7> [472.987981] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:150:pipe A] releasing DPLL 0 <7> [472.988192] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [472.988324] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:150:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [472.988506] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:144:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [472.988650] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:150:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [472.988795] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [472.988930] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [472.989060] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [472.989226] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:150:pipe A] enable: no [modeset] <7> [472.989373] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:34:plane 1A] fb: [NOFB], visible: no <7> [472.989514] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:64:plane 2A] fb: [NOFB], visible: no <7> [472.989641] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:94:plane 3A] fb: [NOFB], visible: no <7> [472.989761] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:124:plane 4A] fb: [NOFB], visible: no <7> [472.989879] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:134:plane 5A] fb: [NOFB], visible: no <7> [472.989994] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:144:cursor A] fb: [NOFB], visible: no <7> [472.990177] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [472.990326] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [472.990610] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [472.990756] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [473.197683] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:392:eDP-1] set backlight PWM = 0 <7> [473.198240] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [473.219595] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 turn panel power off <7> [473.220042] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 wait for panel power off time <7> [473.220023] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [473.220493] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [473.220552] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:391:DDI A/PHY A] - short <7> [473.272758] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [473.273176] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:391:DDI A/PHY A] - short <7> [473.279708] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [473.280092] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:150:pipe A] <7> [473.280232] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:391:DDI A/PHY A] <7> [473.280730] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:391:DDI A/PHY A] <7> [473.281590] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [473.282108] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [473.282660] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:391:DDI A/PHY A] <7> [473.283063] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:400:DDI TC1/PHY TC1] <7> [473.283451] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:402:DP-MST A] <7> [473.283775] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST B] <7> [473.284107] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST C] <7> [473.284470] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:412:DDI TC2/PHY TC2] <7> [473.284804] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:414:DP-MST A] <7> [473.285153] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST B] <7> [473.285471] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST C] <7> [473.285763] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:420:DDI TC3/PHY TC3] <7> [473.286049] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:422:DP-MST A] <7> [473.286330] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST B] <7> [473.286694] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST C] <7> [473.287000] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:392:eDP-1] <7> [473.287399] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [473.287693] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [473.287967] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [473.288471] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [473.288907] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [473.289394] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:150:pipe A] <7> [473.289802] 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> [473.290229] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [473.290578] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [473.292640] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [473.293035] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:388:pipe C] <7> [473.293315] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [473.293422] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:392:eDP-1] <7> [473.293594] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:392:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [473.293967] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:391:DDI A/PHY A][CRTC:269:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [473.294255] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [473.294592] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [473.294864] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:391:DDI A/PHY A] [CRTC:269:pipe B] <7> [473.295157] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [473.295425] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [473.295691] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [473.295925] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [473.296152] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269: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> [473.296420] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [473.296646] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [473.296843] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [473.297058] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [473.297240] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [473.297437] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [473.297618] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [473.297786] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [473.297948] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [473.298109] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [473.298263] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [473.298440] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [473.298609] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [473.298752] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [473.298888] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [473.299025] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [473.299176] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [473.299329] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [473.299481] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [473.299627] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [473.299756] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [473.299875] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [473.299991] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [473.300104] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [473.300216] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [473.300327] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [473.300452] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [473.300561] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [473.300669] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [473.300779] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [473.300881] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [473.300979] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [473.301078] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [473.301174] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe B] fastset requirement not met, forcing full modeset <7> [473.301317] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [473.301445] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:269:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [473.301553] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:153:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [473.301632] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:263:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [473.301706] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [473.301775] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [473.301842] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [473.301907] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [473.301999] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:269:pipe B] data rate 1390840 num active planes 1 <7> [473.302095] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [473.302188] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [473.302282] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [473.302392] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [473.302495] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [473.302584] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:269:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [473.302686] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [473.302776] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [473.302856] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [473.302950] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:269:pipe B] allocated DPLL 0 <7> [473.303029] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:269:pipe B] reserving DPLL 0 <7> [473.303116] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:269:pipe B] enable: yes [modeset] <7> [473.303208] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [473.303294] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [473.303389] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [473.303483] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [473.303568] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [473.303649] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [473.303728] 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> [473.303809] 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> [473.303888] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [473.303966] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [473.304046] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [473.304125] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [473.304203] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [473.304283] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [473.304368] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [473.304460] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [473.304550] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [473.304628] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [473.304706] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [473.304783] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [473.304860] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [473.304933] 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> [473.305004] 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> [473.305074] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [473.305144] 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> [473.305215] 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> [473.305285] 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> [473.305362] 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> [473.305447] 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> [473.305527] 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> [473.305603] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [473.305678] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [473.305754] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [473.305829] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [473.305905] 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> [473.305981] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [473.306055] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [473.306132] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [473.306210] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [473.306288] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [473.306418] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [473.306502] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [473.306575] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [473.306652] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [473.306728] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [473.306804] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [473.306879] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [473.306955] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [473.307030] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [473.307114] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [473.307203] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [473.307292] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [473.307395] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [473.307471] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [473.307539] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [473.307606] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [473.307673] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [473.307741] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:153:plane 1B] fb: [FB:429] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [473.307817] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [473.307891] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [473.307965] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:183:plane 2B] fb: [NOFB], visible: no <7> [473.308039] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:213:plane 3B] fb: [NOFB], visible: no <7> [473.308112] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:243:plane 4B] fb: [NOFB], visible: no <7> [473.308185] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:253:plane 5B] fb: [NOFB], visible: no <7> [473.308258] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:263:cursor B] fb: [NOFB], visible: no <7> [473.308684] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [473.308842] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [473.308982] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [473.309076] 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> [473.309169] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [473.309260] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [473.309342] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:391:DDI A/PHY A] <7> [473.309304] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [473.309431] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:400:DDI TC1/PHY TC1] <7> [473.309467] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:391:DDI A/PHY A] - long <7> [473.309520] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:402:DP-MST A] <7> [473.309590] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST B] <7> [473.309660] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST C] <7> [473.309627] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [473.309728] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:412:DDI TC2/PHY TC2] <7> [473.309796] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:414:DP-MST A] <7> [473.309862] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST B] <7> [473.309884] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:391:DDI A/PHY A] <7> [473.309951] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST C] <7> [473.310024] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:420:DDI TC3/PHY TC3] <7> [473.310096] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:422:DP-MST A] <7> [473.310166] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST B] <7> [473.310235] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST C] <7> [473.310326] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [473.310502] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [473.310569] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [473.310676] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [473.311480] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:269:pipe B] <7> [473.311584] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [473.313497] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 turn panel power on <7> [473.313578] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 wait for panel power cycle (467 ms remaining) <7> [473.789538] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [473.820227] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [473.820540] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 wait for panel power on <7> [473.820832] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [473.857111] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [473.857658] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:391:DDI A/PHY A] - long <7> [473.858174] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [473.858926] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:391:DDI A/PHY A] <7> [474.027886] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [474.028269] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 turning VDD on <7> [474.028536] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [474.030514] 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> [474.032014] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [474.032746] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [474.033824] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [474.035152] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [474.036258] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Clock recovery OK <7> [474.036642] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [474.038335] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [474.038780] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:392:eDP-1][ENCODER:391:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [474.039625] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [474.040143] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [474.040540] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [474.040942] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:392:eDP-1] set backlight PWM = 192000 <7> [474.057029] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [474.058743] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:392:eDP-1] <7> [474.059107] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe B] <7> [476.613524] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 turning VDD off <7> [476.613854] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:391:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [482.507306] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [482.507611] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [482.507828] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [482.647388] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

9.76 seconds

Hostname

shard-lnl-1

Igt-Version

IGT-Version: 2.3-g9e52dea68 (x86_64) (Linux: 7.0.0-rc2-lgci-xe-xe-4662-e4b36c44f536abdf7-debug+ x86_64)

Out

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

Err

Starting dynamic subtest: B-eDP1
(kms_flip:7027) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:7027) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.315216
last_received_ts = 434.314514
last_seq = 1440
current_ts = 434.331909
current_received_ts = 434.331146
current_seq = 1441
count = 383
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 41us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.331909
last_received_ts = 434.331146
last_seq = 1441
current_ts = 434.348572
current_received_ts = 434.347961
current_seq = 1442
count = 384
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 83us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.348572
last_received_ts = 434.347961
last_seq = 1442
current_ts = 434.365234
current_received_ts = 434.364532
current_seq = 1443
count = 385
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.365234
last_received_ts = 434.364532
last_seq = 1443
current_ts = 434.381897
current_received_ts = 434.381226
current_seq = 1444
count = 386
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 103us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.381897
last_received_ts = 434.381226
last_seq = 1444
current_ts = 434.398560
current_received_ts = 434.397888
current_seq = 1445
count = 387
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 57us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.398560
last_received_ts = 434.397888
last_seq = 1445
current_ts = 434.415222
current_received_ts = 434.414581
current_seq = 1446
count = 388
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 65us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.415222
last_received_ts = 434.414581
last_seq = 1446
current_ts = 434.431885
current_received_ts = 434.431244
current_seq = 1447
count = 389
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 96us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.431885
last_received_ts = 434.431244
last_seq = 1447
current_ts = 434.448578
current_received_ts = 434.447998
current_seq = 1448
count = 390
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 64us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.448578
last_received_ts = 434.447998
last_seq = 1448
current_ts = 434.465240
current_received_ts = 434.464661
current_seq = 1449
count = 391
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 67us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.465240
last_received_ts = 434.464661
last_seq = 1449
current_ts = 434.481903
current_received_ts = 434.481232
current_seq = 1450
count = 392
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 69us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.481903
last_received_ts = 434.481232
last_seq = 1450
current_ts = 434.498566
current_received_ts = 434.497986
current_seq = 1451
count = 393
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 85us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.498566
last_received_ts = 434.497986
last_seq = 1451
current_ts = 434.515228
current_received_ts = 434.514648
current_seq = 1452
count = 394
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 62us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.515228
last_received_ts = 434.514648
last_seq = 1452
current_ts = 434.531891
current_received_ts = 434.531342
current_seq = 1453
count = 395
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 111us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.531891
last_received_ts = 434.531342
last_seq = 1453
current_ts = 434.548584
current_received_ts = 434.548004
current_seq = 1454
count = 396
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 56us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.548584
last_received_ts = 434.548004
last_seq = 1454
current_ts = 434.565247
current_received_ts = 434.564667
current_seq = 1455
count = 397
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.565247
last_received_ts = 434.564667
last_seq = 1455
current_ts = 434.581909
current_received_ts = 434.581329
current_seq = 1456
count = 398
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 105us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.581909
last_received_ts = 434.581329
last_seq = 1456
current_ts = 434.598572
current_received_ts = 434.597992
current_seq = 1457
count = 399
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 56us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.598572
last_received_ts = 434.597992
last_seq = 1457
current_ts = 434.615234
current_received_ts = 434.614655
current_seq = 1458
count = 400
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 55us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.615234
last_received_ts = 434.614655
last_seq = 1458
current_ts = 434.631927
current_received_ts = 434.631348
current_seq = 1459
count = 401
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 104us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.631927
last_received_ts = 434.631348
last_seq = 1459
current_ts = 434.648590
current_received_ts = 434.648041
current_seq = 1460
count = 402
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 56us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.648590
last_received_ts = 434.648041
last_seq = 1460
current_ts = 434.665253
current_received_ts = 434.664673
current_seq = 1461
count = 403
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 60us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.665253
last_received_ts = 434.664673
last_seq = 1461
current_ts = 434.681915
current_received_ts = 434.681335
current_seq = 1462
count = 404
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 111us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.681915
last_received_ts = 434.681335
last_seq = 1462
current_ts = 434.698578
current_received_ts = 434.697998
current_seq = 1463
count = 405
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 57us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.698578
last_received_ts = 434.697998
last_seq = 1463
current_ts = 434.715240
current_received_ts = 434.714661
current_seq = 1464
count = 406
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.715240
last_received_ts = 434.714661
last_seq = 1464
current_ts = 434.731903
current_received_ts = 434.731354
current_seq = 1465
count = 407
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 81us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.731903
last_received_ts = 434.731354
last_seq = 1465
current_ts = 434.748596
current_received_ts = 434.747986
current_seq = 1466
count = 408
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 57us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.748596
last_received_ts = 434.747986
last_seq = 1466
current_ts = 434.765259
current_received_ts = 434.764679
current_seq = 1467
count = 409
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 62us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.765259
last_received_ts = 434.764679
last_seq = 1467
current_ts = 434.781921
current_received_ts = 434.781342
current_seq = 1468
count = 410
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 117us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.781921
last_received_ts = 434.781342
last_seq = 1468
current_ts = 434.798584
current_received_ts = 434.798035
current_seq = 1469
count = 411
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 63us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.798584
last_received_ts = 434.798035
last_seq = 1469
current_ts = 434.815247
current_received_ts = 434.814697
current_seq = 1470
count = 412
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.815247
last_received_ts = 434.814697
last_seq = 1470
current_ts = 434.831940
current_received_ts = 434.831360
current_seq = 1471
count = 413
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 95us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.831940
last_received_ts = 434.831360
last_seq = 1471
current_ts = 434.848602
current_received_ts = 434.848022
current_seq = 1472
count = 414
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.848602
last_received_ts = 434.848022
last_seq = 1472
current_ts = 434.865265
current_received_ts = 434.864685
current_seq = 1473
count = 415
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.865265
last_received_ts = 434.864685
last_seq = 1473
current_ts = 434.881927
current_received_ts = 434.881348
current_seq = 1474
count = 416
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 112us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.881927
last_received_ts = 434.881348
last_seq = 1474
current_ts = 434.898590
current_received_ts = 434.898041
current_seq = 1475
count = 417
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.898590
last_received_ts = 434.898041
last_seq = 1475
current_ts = 434.915253
current_received_ts = 434.914703
current_seq = 1476
count = 418
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.915253
last_received_ts = 434.914703
last_seq = 1476
current_ts = 434.931915
current_received_ts = 434.931366
current_seq = 1477
count = 419
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 107us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.931915
last_received_ts = 434.931366
last_seq = 1477
current_ts = 434.948608
current_received_ts = 434.948059
current_seq = 1478
count = 420
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 57us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.948608
last_received_ts = 434.948059
last_seq = 1478
current_ts = 434.965271
current_received_ts = 434.964661
current_seq = 1479
count = 421
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 44us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.965271
last_received_ts = 434.964661
last_seq = 1479
current_ts = 434.981934
current_received_ts = 434.981384
current_seq = 1480
count = 422
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 103us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.981934
last_received_ts = 434.981384
last_seq = 1480
current_ts = 434.998596
current_received_ts = 434.998016
current_seq = 1481
count = 423
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 434.998596
last_received_ts = 434.998016
last_seq = 1481
current_ts = 435.015259
current_received_ts = 435.014679
current_seq = 1482
count = 424
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.015259
last_received_ts = 435.014679
last_seq = 1482
current_ts = 435.031952
current_received_ts = 435.031372
current_seq = 1483
count = 425
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 106us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.031952
last_received_ts = 435.031372
last_seq = 1483
current_ts = 435.048615
current_received_ts = 435.048065
current_seq = 1484
count = 426
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 57us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.048615
last_received_ts = 435.048065
last_seq = 1484
current_ts = 435.065277
current_received_ts = 435.064697
current_seq = 1485
count = 427
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.065277
last_received_ts = 435.064697
last_seq = 1485
current_ts = 435.081940
current_received_ts = 435.081360
current_seq = 1486
count = 428
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 108us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.081940
last_received_ts = 435.081360
last_seq = 1486
current_ts = 435.098602
current_received_ts = 435.098022
current_seq = 1487
count = 429
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 63us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.098602
last_received_ts = 435.098022
last_seq = 1487
current_ts = 435.115265
current_received_ts = 435.114685
current_seq = 1488
count = 430
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.115265
last_received_ts = 435.114685
last_seq = 1488
current_ts = 435.131927
current_received_ts = 435.131378
current_seq = 1489
count = 431
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 103us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.131927
last_received_ts = 435.131378
last_seq = 1489
current_ts = 435.148590
current_received_ts = 435.148041
current_seq = 1490
count = 432
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.148590
last_received_ts = 435.148041
last_seq = 1490
current_ts = 435.165283
current_received_ts = 435.164703
current_seq = 1491
count = 433
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.165283
last_received_ts = 435.164703
last_seq = 1491
current_ts = 435.181946
current_received_ts = 435.181396
current_seq = 1492
count = 434
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 74us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.181946
last_received_ts = 435.181396
last_seq = 1492
current_ts = 435.198608
current_received_ts = 435.198059
current_seq = 1493
count = 435
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.198608
last_received_ts = 435.198059
last_seq = 1493
current_ts = 435.215271
current_received_ts = 435.214691
current_seq = 1494
count = 436
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.215271
last_received_ts = 435.214691
last_seq = 1494
current_ts = 435.231934
current_received_ts = 435.231384
current_seq = 1495
count = 437
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 116us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.231934
last_received_ts = 435.231384
last_seq = 1495
current_ts = 435.248596
current_received_ts = 435.248016
current_seq = 1496
count = 438
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 62us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.248596
last_received_ts = 435.248016
last_seq = 1496
current_ts = 435.265289
current_received_ts = 435.264709
current_seq = 1497
count = 439
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.265289
last_received_ts = 435.264709
last_seq = 1497
current_ts = 435.281952
current_received_ts = 435.281372
current_seq = 1498
count = 440
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 106us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.281952
last_received_ts = 435.281372
last_seq = 1498
current_ts = 435.298615
current_received_ts = 435.298065
current_seq = 1499
count = 441
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 60us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.298615
last_received_ts = 435.298065
last_seq = 1499
current_ts = 435.315277
current_received_ts = 435.314728
current_seq = 1500
count = 442
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.315277
last_received_ts = 435.314728
last_seq = 1500
current_ts = 435.331940
current_received_ts = 435.331390
current_seq = 1501
count = 443
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 97us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.331940
last_received_ts = 435.331390
last_seq = 1501
current_ts = 435.348602
current_received_ts = 435.348053
current_seq = 1502
count = 444
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.348602
last_received_ts = 435.348053
last_seq = 1502
current_ts = 435.365295
current_received_ts = 435.364716
current_seq = 1503
count = 445
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.365295
last_received_ts = 435.364716
last_seq = 1503
current_ts = 435.381958
current_received_ts = 435.381378
current_seq = 1504
count = 446
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 83us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.381958
last_received_ts = 435.381378
last_seq = 1504
current_ts = 435.398621
current_received_ts = 435.398071
current_seq = 1505
count = 447
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.398621
last_received_ts = 435.398071
last_seq = 1505
current_ts = 435.415283
current_received_ts = 435.414703
current_seq = 1506
count = 448
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.415283
last_received_ts = 435.414703
last_seq = 1506
current_ts = 435.431946
current_received_ts = 435.431366
current_seq = 1507
count = 449
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 107us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.431946
last_received_ts = 435.431366
last_seq = 1507
current_ts = 435.448639
current_received_ts = 435.448059
current_seq = 1508
count = 450
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.448639
last_received_ts = 435.448059
last_seq = 1508
current_ts = 435.465302
current_received_ts = 435.464691
current_seq = 1509
count = 451
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.465302
last_received_ts = 435.464691
last_seq = 1509
current_ts = 435.481964
current_received_ts = 435.481354
current_seq = 1510
count = 452
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 100us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.481964
last_received_ts = 435.481354
last_seq = 1510
current_ts = 435.498627
current_received_ts = 435.498047
current_seq = 1511
count = 453
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.498627
last_received_ts = 435.498047
last_seq = 1511
current_ts = 435.515289
current_received_ts = 435.514709
current_seq = 1512
count = 454
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.515289
last_received_ts = 435.514709
last_seq = 1512
current_ts = 435.531952
current_received_ts = 435.531372
current_seq = 1513
count = 455
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 115us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.531952
last_received_ts = 435.531372
last_seq = 1513
current_ts = 435.548615
current_received_ts = 435.548065
current_seq = 1514
count = 456
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 60us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.548615
last_received_ts = 435.548065
last_seq = 1514
current_ts = 435.565277
current_received_ts = 435.564697
current_seq = 1515
count = 457
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 65us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.565277
last_received_ts = 435.564697
last_seq = 1515
current_ts = 435.581970
current_received_ts = 435.581390
current_seq = 1516
count = 458
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 109us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.581970
last_received_ts = 435.581390
last_seq = 1516
current_ts = 435.598633
current_received_ts = 435.598083
current_seq = 1517
count = 459
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.598633
last_received_ts = 435.598083
last_seq = 1517
current_ts = 435.615295
current_received_ts = 435.614746
current_seq = 1518
count = 460
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.615295
last_received_ts = 435.614746
last_seq = 1518
current_ts = 435.631958
current_received_ts = 435.631409
current_seq = 1519
count = 461
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 109us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.631958
last_received_ts = 435.631409
last_seq = 1519
current_ts = 435.648621
current_received_ts = 435.648071
current_seq = 1520
count = 462
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.648621
last_received_ts = 435.648071
last_seq = 1520
current_ts = 435.665283
current_received_ts = 435.664734
current_seq = 1521
count = 463
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 62us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.665283
last_received_ts = 435.664734
last_seq = 1521
current_ts = 435.681976
current_received_ts = 435.681396
current_seq = 1522
count = 464
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 115us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.681976
last_received_ts = 435.681396
last_seq = 1522
current_ts = 435.698639
current_received_ts = 435.698059
current_seq = 1523
count = 465
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.698639
last_received_ts = 435.698059
last_seq = 1523
current_ts = 435.715302
current_received_ts = 435.714722
current_seq = 1524
count = 466
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 66us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.715302
last_received_ts = 435.714722
last_seq = 1524
current_ts = 435.731964
current_received_ts = 435.731415
current_seq = 1525
count = 467
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 79us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.731964
last_received_ts = 435.731415
last_seq = 1525
current_ts = 435.748627
current_received_ts = 435.748077
current_seq = 1526
count = 468
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.748627
last_received_ts = 435.748077
last_seq = 1526
current_ts = 435.765289
current_received_ts = 435.764740
current_seq = 1527
count = 469
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.765289
last_received_ts = 435.764740
last_seq = 1527
current_ts = 435.781982
current_received_ts = 435.781403
current_seq = 1528
count = 470
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 104us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.781982
last_received_ts = 435.781403
last_seq = 1528
current_ts = 435.798645
current_received_ts = 435.798065
current_seq = 1529
count = 471
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.798645
last_received_ts = 435.798065
last_seq = 1529
current_ts = 435.815308
current_received_ts = 435.814728
current_seq = 1530
count = 472
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 63us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.815308
last_received_ts = 435.814728
last_seq = 1530
current_ts = 435.831970
current_received_ts = 435.831421
current_seq = 1531
count = 473
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 105us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.831970
last_received_ts = 435.831421
last_seq = 1531
current_ts = 435.848633
current_received_ts = 435.848083
current_seq = 1532
count = 474
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 63us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.848633
last_received_ts = 435.848083
last_seq = 1532
current_ts = 435.865326
current_received_ts = 435.864746
current_seq = 1533
count = 475
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 68us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.865326
last_received_ts = 435.864746
last_seq = 1533
current_ts = 435.881958
current_received_ts = 435.881409
current_seq = 1534
count = 476
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 93us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.881958
last_received_ts = 435.881409
last_seq = 1534
current_ts = 435.898651
current_received_ts = 435.898071
current_seq = 1535
count = 477
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.898651
last_received_ts = 435.898071
last_seq = 1535
current_ts = 435.915314
current_received_ts = 435.914734
current_seq = 1536
count = 478
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.915314
last_received_ts = 435.914734
last_seq = 1536
current_ts = 435.931976
current_received_ts = 435.931427
current_seq = 1537
count = 479
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 116us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.931976
last_received_ts = 435.931427
last_seq = 1537
current_ts = 435.948639
current_received_ts = 435.948059
current_seq = 1538
count = 480
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 60us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.948639
last_received_ts = 435.948059
last_seq = 1538
current_ts = 435.965302
current_received_ts = 435.964752
current_seq = 1539
count = 481
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.965302
last_received_ts = 435.964752
last_seq = 1539
current_ts = 435.981995
current_received_ts = 435.981415
current_seq = 1540
count = 482
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 114us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.981995
last_received_ts = 435.981415
last_seq = 1540
current_ts = 435.998657
current_received_ts = 435.998077
current_seq = 1541
count = 483
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 435.998657
last_received_ts = 435.998077
last_seq = 1541
current_ts = 436.015320
current_received_ts = 436.014740
current_seq = 1542
count = 484
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 62us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.015320
last_received_ts = 436.014740
last_seq = 1542
current_ts = 436.031982
current_received_ts = 436.031433
current_seq = 1543
count = 485
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 107us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.031982
last_received_ts = 436.031433
last_seq = 1543
current_ts = 436.048645
current_received_ts = 436.048096
current_seq = 1544
count = 486
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.048645
last_received_ts = 436.048096
last_seq = 1544
current_ts = 436.065308
current_received_ts = 436.064758
current_seq = 1545
count = 487
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.065308
last_received_ts = 436.064758
last_seq = 1545
current_ts = 436.081970
current_received_ts = 436.081421
current_seq = 1546
count = 488
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 98us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.081970
last_received_ts = 436.081421
last_seq = 1546
current_ts = 436.098633
current_received_ts = 436.098053
current_seq = 1547
count = 489
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.098633
last_received_ts = 436.098053
last_seq = 1547
current_ts = 436.115326
current_received_ts = 436.114746
current_seq = 1548
count = 490
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.115326
last_received_ts = 436.114746
last_seq = 1548
current_ts = 436.131989
current_received_ts = 436.131439
current_seq = 1549
count = 491
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 93us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.131989
last_received_ts = 436.131439
last_seq = 1549
current_ts = 436.148651
current_received_ts = 436.148102
current_seq = 1550
count = 492
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.148651
last_received_ts = 436.148102
last_seq = 1550
current_ts = 436.165314
current_received_ts = 436.164734
current_seq = 1551
count = 493
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.165314
last_received_ts = 436.164734
last_seq = 1551
current_ts = 436.181976
current_received_ts = 436.181427
current_seq = 1552
count = 494
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 106us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.181976
last_received_ts = 436.181427
last_seq = 1552
current_ts = 436.198639
current_received_ts = 436.198090
current_seq = 1553
count = 495
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.198639
last_received_ts = 436.198090
last_seq = 1553
current_ts = 436.215332
current_received_ts = 436.214752
current_seq = 1554
count = 496
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 58us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.215332
last_received_ts = 436.214752
last_seq = 1554
current_ts = 436.231995
current_received_ts = 436.231323
current_seq = 1555
count = 497
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 64us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.231995
last_received_ts = 436.231323
last_seq = 1555
current_ts = 436.248657
current_received_ts = 436.248077
current_seq = 1556
count = 498
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 64us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.248657
last_received_ts = 436.248077
last_seq = 1556
current_ts = 436.265320
current_received_ts = 436.264740
current_seq = 1557
count = 499
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.265320
last_received_ts = 436.264740
last_seq = 1557
current_ts = 436.281982
current_received_ts = 436.281433
current_seq = 1558
count = 500
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 113us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.281982
last_received_ts = 436.281433
last_seq = 1558
current_ts = 436.298645
current_received_ts = 436.298126
current_seq = 1559
count = 501
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 69us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.298645
last_received_ts = 436.298126
last_seq = 1559
current_ts = 436.315338
current_received_ts = 436.314758
current_seq = 1560
count = 502
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 61us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.315338
last_received_ts = 436.314758
last_seq = 1560
current_ts = 436.332001
current_received_ts = 436.331329
current_seq = 1561
count = 503
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 59us
(kms_flip:7027) DEBUG: name = flip
last_ts = 436.332001
last_received_ts = 436.331329
last_seq = 1561
current_ts = 436.348663
current_received_ts = 436.348114
current_seq = 1562
count = 504
seq_step = 1
(kms_flip:7027) DEBUG: Vblank took 1364us
(kms_flip:7027) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:926:
(kms_flip:7027) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7027) igt_core-INFO: Stack trace:
(kms_flip:7027) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:7027) igt_core-INFO:   #1 ../tests/kms_flip.c:921 run_test_on_crtc_set.constprop.0()
(kms_flip:7027) igt_core-INFO:   #2 ../tests/kms_flip.c:1887 run_test()
(kms_flip:7027) igt_core-INFO:   #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043()
(kms_flip:7027) igt_core-INFO:   #4 ../tests/kms_flip.c:2043 main()
(kms_flip:7027) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7027) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7027) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (9.764s)

Dmesg

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

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

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

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

<7> [472.898595] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:429]

<7> [472.899005] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:433]

<7> [472.979630] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:150:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [473.289394] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:150:pipe A]

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

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

<7> [473.292640] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]

<7> [473.293035] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:388:pipe C]

<7> [473.293315] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]

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

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

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

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

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

<7> [473.294864] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:391:DDI A/PHY A] [CRTC:269:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [473.301706] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [473.301775] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [473.301842] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [473.301907] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:153: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> [473.301999] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:269:pipe B] data rate 1390840 num active planes 1

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [473.303728] 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> [473.303809] 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> [473.303888] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

<7> [473.304933] 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> [473.305004] 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> [473.305074] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

<7> [473.305144] 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> [473.305215] 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> [473.305285] 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> [473.305362] 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> [473.305447] 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> [473.305527] 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> [473.305603] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

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

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

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

<7> [473.305905] 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> [473.305981] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [474.040942] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:392:eDP-1] set backlight PWM = 192000

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

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

<7> [474.059107] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe B]

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

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

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

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

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

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

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