igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1 on re-lnl-1@xe-3643-99f4b32d88cb9718c944d44ea96cb04f4f70a773 Test details

Detail	Value
Duration	8.52 seconds
Igt-Version	IGT-Version: 2.1-g8a840cd64 (x86_64) (Linux: 6.17.0-rc3-lgci-xe-xe-3643-99f4b32d88cb9718c+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2560x1600: 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1884 run_test() #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040() #4 ../tests/kms_flip.c:2040 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (8.518s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:3356) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:3356) CRITICAL: Failed assertion: end - start < 500 (kms_flip:3356) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:3356) DEBUG: Vblank took 99us (kms_flip:3356) DEBUG: name = flip last_ts = 823.281982 last_received_ts = 823.281677 last_seq = 29184 current_ts = 823.286133 current_received_ts = 823.285828 current_seq = 29185 count = 1578 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 102us (kms_flip:3356) DEBUG: name = flip last_ts = 823.286133 last_received_ts = 823.285828 last_seq = 29185 current_ts = 823.290344 current_received_ts = 823.289978 current_seq = 29186 count = 1579 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 55us (kms_flip:3356) DEBUG: name = flip last_ts = 823.290344 last_received_ts = 823.289978 last_seq = 29186 current_ts = 823.294495 current_received_ts = 823.294128 current_seq = 29187 count = 1580 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 108us (kms_flip:3356) DEBUG: name = flip last_ts = 823.294495 last_received_ts = 823.294128 last_seq = 29187 current_ts = 823.298645 current_received_ts = 823.298340 current_seq = 29188 count = 1581 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 111us (kms_flip:3356) DEBUG: name = flip last_ts = 823.298645 last_received_ts = 823.298340 last_seq = 29188 current_ts = 823.302795 current_received_ts = 823.302490 current_seq = 29189 count = 1582 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 101us (kms_flip:3356) DEBUG: name = flip last_ts = 823.302795 last_received_ts = 823.302490 last_seq = 29189 current_ts = 823.307007 current_received_ts = 823.306702 current_seq = 29190 count = 1583 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 118us (kms_flip:3356) DEBUG: name = flip last_ts = 823.307007 last_received_ts = 823.306702 last_seq = 29190 current_ts = 823.311157 current_received_ts = 823.310852 current_seq = 29191 count = 1584 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 35us (kms_flip:3356) DEBUG: name = flip last_ts = 823.311157 last_received_ts = 823.310852 last_seq = 29191 current_ts = 823.315308 current_received_ts = 823.315002 current_seq = 29192 count = 1585 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 107us (kms_flip:3356) DEBUG: name = flip last_ts = 823.315308 last_received_ts = 823.315002 last_seq = 29192 current_ts = 823.319458 current_received_ts = 823.319153 current_seq = 29193 count = 1586 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 108us (kms_flip:3356) DEBUG: name = flip last_ts = 823.319458 last_received_ts = 823.319153 last_seq = 29193 current_ts = 823.323669 current_received_ts = 823.323303 current_seq = 29194 count = 1587 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 115us (kms_flip:3356) DEBUG: name = flip last_ts = 823.323669 last_received_ts = 823.323303 last_seq = 29194 current_ts = 823.327820 current_received_ts = 823.327515 current_seq = 29195 count = 1588 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 89us (kms_flip:3356) DEBUG: name = flip last_ts = 823.327820 last_received_ts = 823.327515 last_seq = 29195 current_ts = 823.331970 current_received_ts = 823.331665 current_seq = 29196 count = 1589 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 105us (kms_flip:3356) DEBUG: name = flip last_ts = 823.331970 last_received_ts = 823.331665 last_seq = 29196 current_ts = 823.336182 current_received_ts = 823.335876 current_seq = 29197 count = 1590 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 123us (kms_flip:3356) DEBUG: name = flip last_ts = 823.336182 last_received_ts = 823.335876 last_seq = 29197 current_ts = 823.340332 current_received_ts = 823.340027 current_seq = 29198 count = 1591 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 98us (kms_flip:3356) DEBUG: name = flip last_ts = 823.340332 last_received_ts = 823.340027 last_seq = 29198 current_ts = 823.344482 current_received_ts = 823.344177 current_seq = 29199 count = 1592 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 108us (kms_flip:3356) DEBUG: name = flip last_ts = 823.344482 last_received_ts = 823.344177 last_seq = 29199 current_ts = 823.348633 current_received_ts = 823.348328 current_seq = 29200 count = 1593 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 34us (kms_flip:3356) DEBUG: name = flip last_ts = 823.348633 last_received_ts = 823.348328 last_seq = 29200 current_ts = 823.352844 current_received_ts = 823.352539 current_seq = 29201 count = 1594 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 114us (kms_flip:3356) DEBUG: name = flip last_ts = 823.352844 last_received_ts = 823.352539 last_seq = 29201 current_ts = 823.356995 current_received_ts = 823.356689 current_seq = 29202 count = 1595 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 104us (kms_flip:3356) DEBUG: name = flip last_ts = 823.356995 last_received_ts = 823.356689 last_seq = 29202 current_ts = 823.361145 current_received_ts = 823.360840 current_seq = 29203 count = 1596 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 102us (kms_flip:3356) DEBUG: name = flip last_ts = 823.361145 last_received_ts = 823.360840 last_seq = 29203 current_ts = 823.365295 current_received_ts = 823.365051 current_seq = 29204 count = 1597 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 76us (kms_flip:3356) DEBUG: name = flip last_ts = 823.365295 last_received_ts = 823.365051 last_seq = 29204 current_ts = 823.369507 current_received_ts = 823.369141 current_seq = 29205 count = 1598 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 51us (kms_flip:3356) DEBUG: name = flip last_ts = 823.369507 last_received_ts = 823.369141 last_seq = 29205 current_ts = 823.373657 current_received_ts = 823.373352 current_seq = 29206 count = 1599 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 131us (kms_flip:3356) DEBUG: name = flip last_ts = 823.373657 last_received_ts = 823.373352 last_seq = 29206 current_ts = 823.377808 current_received_ts = 823.377502 current_seq = 29207 count = 1600 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 97us (kms_flip:3356) DEBUG: name = flip last_ts = 823.377808 last_received_ts = 823.377502 last_seq = 29207 current_ts = 823.382019 current_received_ts = 823.381653 current_seq = 29208 count = 1601 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 102us (kms_flip:3356) DEBUG: name = flip last_ts = 823.382019 last_received_ts = 823.381653 last_seq = 29208 current_ts = 823.386169 current_received_ts = 823.385864 current_seq = 29209 count = 1602 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 142us (kms_flip:3356) DEBUG: name = flip last_ts = 823.386169 last_received_ts = 823.385864 last_seq = 29209 current_ts = 823.390320 current_received_ts = 823.390015 current_seq = 29210 count = 1603 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 32us (kms_flip:3356) DEBUG: name = flip last_ts = 823.390320 last_received_ts = 823.390015 last_seq = 29210 current_ts = 823.394470 current_received_ts = 823.394165 current_seq = 29211 count = 1604 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 34us (kms_flip:3356) DEBUG: name = flip last_ts = 823.394470 last_received_ts = 823.394165 last_seq = 29211 current_ts = 823.398682 current_received_ts = 823.398315 current_seq = 29212 count = 1605 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 112us (kms_flip:3356) DEBUG: name = flip last_ts = 823.398682 last_received_ts = 823.398315 last_seq = 29212 current_ts = 823.402832 current_received_ts = 823.402527 current_seq = 29213 count = 1606 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 100us (kms_flip:3356) DEBUG: name = flip last_ts = 823.402832 last_received_ts = 823.402527 last_seq = 29213 current_ts = 823.406982 current_received_ts = 823.406677 current_seq = 29214 count = 1607 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 100us (kms_flip:3356) DEBUG: name = flip last_ts = 823.406982 last_received_ts = 823.406677 last_seq = 29214 current_ts = 823.411133 current_received_ts = 823.410828 current_seq = 29215 count = 1608 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 116us (kms_flip:3356) DEBUG: name = flip last_ts = 823.411133 last_received_ts = 823.410828 last_seq = 29215 current_ts = 823.415344 current_received_ts = 823.415039 current_seq = 29216 count = 1609 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 104us (kms_flip:3356) DEBUG: name = flip last_ts = 823.415344 last_received_ts = 823.415039 last_seq = 29216 current_ts = 823.419495 current_received_ts = 823.419128 current_seq = 29217 count = 1610 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 33us (kms_flip:3356) DEBUG: name = flip last_ts = 823.419495 last_received_ts = 823.419128 last_seq = 29217 current_ts = 823.423645 current_received_ts = 823.423340 current_seq = 29218 count = 1611 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 108us (kms_flip:3356) DEBUG: name = flip last_ts = 823.423645 last_received_ts = 823.423340 last_seq = 29218 current_ts = 823.427856 current_received_ts = 823.427551 current_seq = 29219 count = 1612 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 114us (kms_flip:3356) DEBUG: name = flip last_ts = 823.427856 last_received_ts = 823.427551 last_seq = 29219 current_ts = 823.432007 current_received_ts = 823.431702 current_seq = 29220 count = 1613 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 112us (kms_flip:3356) DEBUG: name = flip last_ts = 823.432007 last_received_ts = 823.431702 last_seq = 29220 current_ts = 823.436157 current_received_ts = 823.435852 current_seq = 29221 count = 1614 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 100us (kms_flip:3356) DEBUG: name = flip last_ts = 823.436157 last_received_ts = 823.435852 last_seq = 29221 current_ts = 823.440308 current_received_ts = 823.440063 current_seq = 29222 count = 1615 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 89us (kms_flip:3356) DEBUG: name = flip last_ts = 823.440308 last_received_ts = 823.440063 last_seq = 29222 current_ts = 823.444519 current_received_ts = 823.444153 current_seq = 29223 count = 1616 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 50us (kms_flip:3356) DEBUG: name = flip last_ts = 823.444519 last_received_ts = 823.444153 last_seq = 29223 current_ts = 823.448669 current_received_ts = 823.448364 current_seq = 29224 count = 1617 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 49us (kms_flip:3356) DEBUG: name = flip last_ts = 823.448669 last_received_ts = 823.448364 last_seq = 29224 current_ts = 823.452820 current_received_ts = 823.452515 current_seq = 29225 count = 1618 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 109us (kms_flip:3356) DEBUG: name = flip last_ts = 823.452820 last_received_ts = 823.452515 last_seq = 29225 current_ts = 823.456970 current_received_ts = 823.456726 current_seq = 29226 count = 1619 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 133us (kms_flip:3356) DEBUG: name = flip last_ts = 823.456970 last_received_ts = 823.456726 last_seq = 29226 current_ts = 823.461182 current_received_ts = 823.460876 current_seq = 29227 count = 1620 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 124us (kms_flip:3356) DEBUG: name = flip last_ts = 823.461182 last_received_ts = 823.460876 last_seq = 29227 current_ts = 823.465332 current_received_ts = 823.465027 current_seq = 29228 count = 1621 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 114us (kms_flip:3356) DEBUG: name = flip last_ts = 823.465332 last_received_ts = 823.465027 last_seq = 29228 current_ts = 823.469482 current_received_ts = 823.469177 current_seq = 29229 count = 1622 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 33us (kms_flip:3356) DEBUG: name = flip last_ts = 823.469482 last_received_ts = 823.469177 last_seq = 29229 current_ts = 823.473694 current_received_ts = 823.473328 current_seq = 29230 count = 1623 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 133us (kms_flip:3356) DEBUG: name = flip last_ts = 823.473694 last_received_ts = 823.473328 last_seq = 29230 current_ts = 823.477844 current_received_ts = 823.477539 current_seq = 29231 count = 1624 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 108us (kms_flip:3356) DEBUG: name = flip last_ts = 823.477844 last_received_ts = 823.477539 last_seq = 29231 current_ts = 823.481995 current_received_ts = 823.481689 current_seq = 29232 count = 1625 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 131us (kms_flip:3356) DEBUG: name = flip last_ts = 823.481995 last_received_ts = 823.481689 last_seq = 29232 current_ts = 823.486145 current_received_ts = 823.485840 current_seq = 29233 count = 1626 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 86us (kms_flip:3356) DEBUG: name = flip last_ts = 823.486145 last_received_ts = 823.485840 last_seq = 29233 current_ts = 823.490356 current_received_ts = 823.490051 current_seq = 29234 count = 1627 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 100us (kms_flip:3356) DEBUG: name = flip last_ts = 823.490356 last_received_ts = 823.490051 last_seq = 29234 current_ts = 823.494507 current_received_ts = 823.494141 current_seq = 29235 count = 1628 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 111us (kms_flip:3356) DEBUG: name = flip last_ts = 823.494507 last_received_ts = 823.494141 last_seq = 29235 current_ts = 823.498657 current_received_ts = 823.498352 current_seq = 29236 count = 1629 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 116us (kms_flip:3356) DEBUG: name = flip last_ts = 823.498657 last_received_ts = 823.498352 last_seq = 29236 current_ts = 823.502808 current_received_ts = 823.502502 current_seq = 29237 count = 1630 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 128us (kms_flip:3356) DEBUG: name = flip last_ts = 823.502808 last_received_ts = 823.502502 last_seq = 29237 current_ts = 823.507019 current_received_ts = 823.506714 current_seq = 29238 count = 1631 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 115us (kms_flip:3356) DEBUG: name = flip last_ts = 823.507019 last_received_ts = 823.506714 last_seq = 29238 current_ts = 823.511169 current_received_ts = 823.510864 current_seq = 29239 count = 1632 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 96us (kms_flip:3356) DEBUG: name = flip last_ts = 823.511169 last_received_ts = 823.510864 last_seq = 29239 current_ts = 823.515320 current_received_ts = 823.515015 current_seq = 29240 count = 1633 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 104us (kms_flip:3356) DEBUG: name = flip last_ts = 823.515320 last_received_ts = 823.515015 last_seq = 29240 current_ts = 823.519531 current_received_ts = 823.519165 current_seq = 29241 count = 1634 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 35us (kms_flip:3356) DEBUG: name = flip last_ts = 823.519531 last_received_ts = 823.519165 last_seq = 29241 current_ts = 823.523682 current_received_ts = 823.523376 current_seq = 29242 count = 1635 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 97us (kms_flip:3356) DEBUG: name = flip last_ts = 823.523682 last_received_ts = 823.523376 last_seq = 29242 current_ts = 823.527832 current_received_ts = 823.527527 current_seq = 29243 count = 1636 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 128us (kms_flip:3356) DEBUG: name = flip last_ts = 823.527832 last_received_ts = 823.527527 last_seq = 29243 current_ts = 823.531982 current_received_ts = 823.531677 current_seq = 29244 count = 1637 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 113us (kms_flip:3356) DEBUG: name = flip last_ts = 823.531982 last_received_ts = 823.531677 last_seq = 29244 current_ts = 823.536194 current_received_ts = 823.535889 current_seq = 29245 count = 1638 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 90us (kms_flip:3356) DEBUG: name = flip last_ts = 823.536194 last_received_ts = 823.535889 last_seq = 29245 current_ts = 823.540344 current_received_ts = 823.540039 current_seq = 29246 count = 1639 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 106us (kms_flip:3356) DEBUG: name = flip last_ts = 823.540344 last_received_ts = 823.540039 last_seq = 29246 current_ts = 823.544495 current_received_ts = 823.544189 current_seq = 29247 count = 1640 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 33us (kms_flip:3356) DEBUG: name = flip last_ts = 823.544495 last_received_ts = 823.544189 last_seq = 29247 current_ts = 823.548645 current_received_ts = 823.548340 current_seq = 29248 count = 1641 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 104us (kms_flip:3356) DEBUG: name = flip last_ts = 823.548645 last_received_ts = 823.548340 last_seq = 29248 current_ts = 823.552856 current_received_ts = 823.552551 current_seq = 29249 count = 1642 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 103us (kms_flip:3356) DEBUG: name = flip last_ts = 823.552856 last_received_ts = 823.552551 last_seq = 29249 current_ts = 823.557007 current_received_ts = 823.556702 current_seq = 29250 count = 1643 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 117us (kms_flip:3356) DEBUG: name = flip last_ts = 823.557007 last_received_ts = 823.556702 last_seq = 29250 current_ts = 823.561157 current_received_ts = 823.560852 current_seq = 29251 count = 1644 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 110us (kms_flip:3356) DEBUG: name = flip last_ts = 823.561157 last_received_ts = 823.560852 last_seq = 29251 current_ts = 823.565369 current_received_ts = 823.565002 current_seq = 29252 count = 1645 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 32us (kms_flip:3356) DEBUG: name = flip last_ts = 823.565369 last_received_ts = 823.565002 last_seq = 29252 current_ts = 823.569519 current_received_ts = 823.569153 current_seq = 29253 count = 1646 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 31us (kms_flip:3356) DEBUG: name = flip last_ts = 823.569519 last_received_ts = 823.569153 last_seq = 29253 current_ts = 823.573669 current_received_ts = 823.573364 current_seq = 29254 count = 1647 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 128us (kms_flip:3356) DEBUG: name = flip last_ts = 823.573669 last_received_ts = 823.573364 last_seq = 29254 current_ts = 823.577820 current_received_ts = 823.577515 current_seq = 29255 count = 1648 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 101us (kms_flip:3356) DEBUG: name = flip last_ts = 823.577820 last_received_ts = 823.577515 last_seq = 29255 current_ts = 823.582031 current_received_ts = 823.581726 current_seq = 29256 count = 1649 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 116us (kms_flip:3356) DEBUG: name = flip last_ts = 823.582031 last_received_ts = 823.581726 last_seq = 29256 current_ts = 823.586182 current_received_ts = 823.585876 current_seq = 29257 count = 1650 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 119us (kms_flip:3356) DEBUG: name = flip last_ts = 823.586182 last_received_ts = 823.585876 last_seq = 29257 current_ts = 823.590332 current_received_ts = 823.590027 current_seq = 29258 count = 1651 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 111us (kms_flip:3356) DEBUG: name = flip last_ts = 823.590332 last_received_ts = 823.590027 last_seq = 29258 current_ts = 823.594543 current_received_ts = 823.594177 current_seq = 29259 count = 1652 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 105us (kms_flip:3356) DEBUG: name = flip last_ts = 823.594543 last_received_ts = 823.594177 last_seq = 29259 current_ts = 823.598694 current_received_ts = 823.598389 current_seq = 29260 count = 1653 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 129us (kms_flip:3356) DEBUG: name = flip last_ts = 823.598694 last_received_ts = 823.598389 last_seq = 29260 current_ts = 823.602844 current_received_ts = 823.602539 current_seq = 29261 count = 1654 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 120us (kms_flip:3356) DEBUG: name = flip last_ts = 823.602844 last_received_ts = 823.602539 last_seq = 29261 current_ts = 823.606995 current_received_ts = 823.606689 current_seq = 29262 count = 1655 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 96us (kms_flip:3356) DEBUG: name = flip last_ts = 823.606995 last_received_ts = 823.606689 last_seq = 29262 current_ts = 823.611206 current_received_ts = 823.610901 current_seq = 29263 count = 1656 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 119us (kms_flip:3356) DEBUG: name = flip last_ts = 823.611206 last_received_ts = 823.610901 last_seq = 29263 current_ts = 823.615356 current_received_ts = 823.615051 current_seq = 29264 count = 1657 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 49us (kms_flip:3356) DEBUG: name = flip last_ts = 823.615356 last_received_ts = 823.615051 last_seq = 29264 current_ts = 823.619507 current_received_ts = 823.619202 current_seq = 29265 count = 1658 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 34us (kms_flip:3356) DEBUG: name = flip last_ts = 823.619507 last_received_ts = 823.619202 last_seq = 29265 current_ts = 823.623657 current_received_ts = 823.623352 current_seq = 29266 count = 1659 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 117us (kms_flip:3356) DEBUG: name = flip last_ts = 823.623657 last_received_ts = 823.623352 last_seq = 29266 current_ts = 823.627869 current_received_ts = 823.627563 current_seq = 29267 count = 1660 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 114us (kms_flip:3356) DEBUG: name = flip last_ts = 823.627869 last_received_ts = 823.627563 last_seq = 29267 current_ts = 823.632019 current_received_ts = 823.631714 current_seq = 29268 count = 1661 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 106us (kms_flip:3356) DEBUG: name = flip last_ts = 823.632019 last_received_ts = 823.631714 last_seq = 29268 current_ts = 823.636169 current_received_ts = 823.635864 current_seq = 29269 count = 1662 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 126us (kms_flip:3356) DEBUG: name = flip last_ts = 823.636169 last_received_ts = 823.635864 last_seq = 29269 current_ts = 823.640381 current_received_ts = 823.640076 current_seq = 29270 count = 1663 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 35us (kms_flip:3356) DEBUG: name = flip last_ts = 823.640381 last_received_ts = 823.640076 last_seq = 29270 current_ts = 823.644531 current_received_ts = 823.644165 current_seq = 29271 count = 1664 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 33us (kms_flip:3356) DEBUG: name = flip last_ts = 823.644531 last_received_ts = 823.644165 last_seq = 29271 current_ts = 823.648682 current_received_ts = 823.648376 current_seq = 29272 count = 1665 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 115us (kms_flip:3356) DEBUG: name = flip last_ts = 823.648682 last_received_ts = 823.648376 last_seq = 29272 current_ts = 823.652832 current_received_ts = 823.652527 current_seq = 29273 count = 1666 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 114us (kms_flip:3356) DEBUG: name = flip last_ts = 823.652832 last_received_ts = 823.652527 last_seq = 29273 current_ts = 823.657043 current_received_ts = 823.656738 current_seq = 29274 count = 1667 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 108us (kms_flip:3356) DEBUG: name = flip last_ts = 823.657043 last_received_ts = 823.656738 last_seq = 29274 current_ts = 823.661194 current_received_ts = 823.660889 current_seq = 29275 count = 1668 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 88us (kms_flip:3356) DEBUG: name = flip last_ts = 823.661194 last_received_ts = 823.660889 last_seq = 29275 current_ts = 823.665344 current_received_ts = 823.665039 current_seq = 29276 count = 1669 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 103us (kms_flip:3356) DEBUG: name = flip last_ts = 823.665344 last_received_ts = 823.665039 last_seq = 29276 current_ts = 823.669495 current_received_ts = 823.669189 current_seq = 29277 count = 1670 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 32us (kms_flip:3356) DEBUG: name = flip last_ts = 823.669495 last_received_ts = 823.669189 last_seq = 29277 current_ts = 823.673706 current_received_ts = 823.673401 current_seq = 29278 count = 1671 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 125us (kms_flip:3356) DEBUG: name = flip last_ts = 823.673706 last_received_ts = 823.673401 last_seq = 29278 current_ts = 823.677856 current_received_ts = 823.677551 current_seq = 29279 count = 1672 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 117us (kms_flip:3356) DEBUG: name = flip last_ts = 823.677856 last_received_ts = 823.677551 last_seq = 29279 current_ts = 823.682007 current_received_ts = 823.681702 current_seq = 29280 count = 1673 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 101us (kms_flip:3356) DEBUG: name = flip last_ts = 823.682007 last_received_ts = 823.681702 last_seq = 29280 current_ts = 823.686157 current_received_ts = 823.685913 current_seq = 29281 count = 1674 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 33us (kms_flip:3356) DEBUG: name = flip last_ts = 823.686157 last_received_ts = 823.685913 last_seq = 29281 current_ts = 823.690369 current_received_ts = 823.690063 current_seq = 29282 count = 1675 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 50us (kms_flip:3356) DEBUG: name = flip last_ts = 823.690369 last_received_ts = 823.690063 last_seq = 29282 current_ts = 823.694519 current_received_ts = 823.694214 current_seq = 29283 count = 1676 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 34us (kms_flip:3356) DEBUG: name = flip last_ts = 823.694519 last_received_ts = 823.694214 last_seq = 29283 current_ts = 823.698669 current_received_ts = 823.698364 current_seq = 29284 count = 1677 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 117us (kms_flip:3356) DEBUG: name = flip last_ts = 823.698669 last_received_ts = 823.698364 last_seq = 29284 current_ts = 823.702881 current_received_ts = 823.702576 current_seq = 29285 count = 1678 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 111us (kms_flip:3356) DEBUG: name = flip last_ts = 823.702881 last_received_ts = 823.702576 last_seq = 29285 current_ts = 823.707031 current_received_ts = 823.706726 current_seq = 29286 count = 1679 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 99us (kms_flip:3356) DEBUG: name = flip last_ts = 823.707031 last_received_ts = 823.706726 last_seq = 29286 current_ts = 823.711182 current_received_ts = 823.710876 current_seq = 29287 count = 1680 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 88us (kms_flip:3356) DEBUG: name = flip last_ts = 823.711182 last_received_ts = 823.710876 last_seq = 29287 current_ts = 823.715332 current_received_ts = 823.715027 current_seq = 29288 count = 1681 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 49us (kms_flip:3356) DEBUG: name = flip last_ts = 823.715332 last_received_ts = 823.715027 last_seq = 29288 current_ts = 823.719543 current_received_ts = 823.719177 current_seq = 29289 count = 1682 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 31us (kms_flip:3356) DEBUG: name = flip last_ts = 823.719543 last_received_ts = 823.719177 last_seq = 29289 current_ts = 823.723694 current_received_ts = 823.723389 current_seq = 29290 count = 1683 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 112us (kms_flip:3356) DEBUG: name = flip last_ts = 823.723694 last_received_ts = 823.723389 last_seq = 29290 current_ts = 823.727844 current_received_ts = 823.727539 current_seq = 29291 count = 1684 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 126us (kms_flip:3356) DEBUG: name = flip last_ts = 823.727844 last_received_ts = 823.727539 last_seq = 29291 current_ts = 823.731995 current_received_ts = 823.731750 current_seq = 29292 count = 1685 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 102us (kms_flip:3356) DEBUG: name = flip last_ts = 823.731995 last_received_ts = 823.731750 last_seq = 29292 current_ts = 823.736206 current_received_ts = 823.735901 current_seq = 29293 count = 1686 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 106us (kms_flip:3356) DEBUG: name = flip last_ts = 823.736206 last_received_ts = 823.735901 last_seq = 29293 current_ts = 823.740356 current_received_ts = 823.740051 current_seq = 29294 count = 1687 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 36us (kms_flip:3356) DEBUG: name = flip last_ts = 823.740356 last_received_ts = 823.740051 last_seq = 29294 current_ts = 823.744507 current_received_ts = 823.744202 current_seq = 29295 count = 1688 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 33us (kms_flip:3356) DEBUG: name = flip last_ts = 823.744507 last_received_ts = 823.744202 last_seq = 29295 current_ts = 823.748718 current_received_ts = 823.748413 current_seq = 29296 count = 1689 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 132us (kms_flip:3356) DEBUG: name = flip last_ts = 823.748718 last_received_ts = 823.748413 last_seq = 29296 current_ts = 823.752869 current_received_ts = 823.752563 current_seq = 29297 count = 1690 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 98us (kms_flip:3356) DEBUG: name = flip last_ts = 823.752869 last_received_ts = 823.752563 last_seq = 29297 current_ts = 823.757019 current_received_ts = 823.756714 current_seq = 29298 count = 1691 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 96us (kms_flip:3356) DEBUG: name = flip last_ts = 823.757019 last_received_ts = 823.756714 last_seq = 29298 current_ts = 823.761169 current_received_ts = 823.760925 current_seq = 29299 count = 1692 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 117us (kms_flip:3356) DEBUG: name = flip last_ts = 823.761169 last_received_ts = 823.760925 last_seq = 29299 current_ts = 823.765381 current_received_ts = 823.765015 current_seq = 29300 count = 1693 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 108us (kms_flip:3356) DEBUG: name = flip last_ts = 823.765381 last_received_ts = 823.765015 last_seq = 29300 current_ts = 823.769531 current_received_ts = 823.769226 current_seq = 29301 count = 1694 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 32us (kms_flip:3356) DEBUG: name = flip last_ts = 823.769531 last_received_ts = 823.769226 last_seq = 29301 current_ts = 823.773682 current_received_ts = 823.773376 current_seq = 29302 count = 1695 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 95us (kms_flip:3356) DEBUG: name = flip last_ts = 823.773682 last_received_ts = 823.773376 last_seq = 29302 current_ts = 823.777893 current_received_ts = 823.777527 current_seq = 29303 count = 1696 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 34us (kms_flip:3356) DEBUG: name = flip last_ts = 823.777893 last_received_ts = 823.777527 last_seq = 29303 current_ts = 823.782043 current_received_ts = 823.781738 current_seq = 29304 count = 1697 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 101us (kms_flip:3356) DEBUG: name = flip last_ts = 823.782043 last_received_ts = 823.781738 last_seq = 29304 current_ts = 823.786194 current_received_ts = 823.785889 current_seq = 29305 count = 1698 seq_step = 1 (kms_flip:3356) DEBUG: Vblank took 784us (kms_flip:3356) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:3356) CRITICAL: Failed assertion: end - start < 500 (kms_flip:3356) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:3356) igt_core-INFO: Stack trace: (kms_flip:3356) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:3356) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:3356) igt_core-INFO: #2 ../tests/kms_flip.c:1884 run_test() (kms_flip:3356) igt_core-INFO: #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040() (kms_flip:3356) igt_core-INFO: #4 ../tests/kms_flip.c:2040 main() (kms_flip:3356) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:3356) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:3356) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (8.518s)
Dmesg	<6> [834.132972] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [834.134264] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:245] <7> [834.135075] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:246] <7> [834.199763] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:88:pipe A] <7> [834.199933] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [834.200226] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [834.200514] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [834.200771] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [834.201032] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 8214124/8388608 link 912680/524288, found tu 0, data 0/0 link 0/0) <7> [834.201349] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [834.201757] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [834.202015] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2560, found 0) <7> [834.202251] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2720, found 0) <7> [834.202635] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2560, found 0) <7> [834.202871] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2720, found 0) <7> [834.203104] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2608, found 0) <7> [834.203387] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2640, found 0) <7> [834.203673] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1600, found 0) <7> [834.203960] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1600, found 0) <7> [834.204189] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1663, found 0) <7> [834.204475] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1669, found 0) <7> [834.204716] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1800, found 0) <7> [834.204934] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1800, found 0) <7> [834.205152] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2560, found 0) <7> [834.205370] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2720, found 0) <7> [834.205637] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2560, found 0) <7> [834.205852] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2720, found 0) <7> [834.206067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2608, found 0) <7> [834.206279] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2640, found 0) <7> [834.206530] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1600, found 0) <7> [834.206799] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1600, found 0) <7> [834.207026] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1663, found 0) <7> [834.207235] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1669, found 0) <7> [834.207468] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1800, found 0) <7> [834.207666] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1800, found 0) <7> [834.207851] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [834.208074] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [834.208278] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [834.208514] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [834.208712] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pipe_bpp (expected 18, found 0) <7> [834.208891] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 1175040, found 0) <7> [834.209064] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 1175040, found 0) <7> [834.209234] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in port_clock (expected 675000, found 0) <7> [834.209424] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in min_voltage_level (expected 1, found 0) <7> [834.209643] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:88:pipe A] fastset requirement not met, forcing full modeset <7> [834.209872] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [834.210008] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:88:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [834.210164] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:33:plane 1A] ddb ( 0 - 3942) -> ( 0 - 0), size 3942 -> 0 <7> [834.210282] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:83:cursor A] ddb (3942 - 4096) -> ( 0 - 0), size 154 -> 0 <7> [834.210397] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:33:plane 1A] level wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm <7> [834.210532] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:33:plane 1A] lines 4, 46, 46, 46, 43, 46, 0, 0, 0, 9, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [834.210642] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:33:plane 1A] blocks 82, 933, 933, 933, 872, 933, 0, 0, 177, 184, 198 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [834.210748] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:33:plane 1A] min_ddb 163,1054,1054,1054, 973,1054, 0, 0, 178, 325, 325 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [834.210876] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:88:pipe A] data rate 0 num active planes 0 <7> [834.211025] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400 <7> [834.211174] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400 <7> [834.211316] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [834.211470] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [834.211629] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [834.211790] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via crawling and squashing <7> [834.211922] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [834.212047] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 0, actual 0 <7> [834.212197] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:88:pipe A] enable: no [modeset] <7> [834.212337] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:33:plane 1A] fb: [NOFB], visible: no <7> [834.212499] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:43:plane 2A] fb: [NOFB], visible: no <7> [834.212612] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:53:plane 3A] fb: [NOFB], visible: no <7> [834.212724] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:63:plane 4A] fb: [NOFB], visible: no <7> [834.212830] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:73:plane 5A] fb: [NOFB], visible: no <7> [834.212936] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:83:cursor A] fb: [NOFB], visible: no <7> [834.213105] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [834.213639] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [834.213802] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling Panel Replay <7> [834.218476] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [834.218753] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [834.218905] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [834.424583] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 0 <7> [834.424993] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [834.426273] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD on <7> [834.426614] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [834.427138] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power off <7> [834.427374] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power off time <7> [834.427653] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [834.488503] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [834.488836] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [834.489177] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A] <7> [834.489439] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1] <7> [834.489648] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A] <7> [834.489842] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B] <7> [834.490052] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C] <7> [834.490224] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2] <7> [834.490391] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A] <7> [834.490592] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B] <7> [834.490758] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C] <7> [834.490931] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3] <7> [834.491149] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A] <7> [834.491329] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B] <7> [834.491520] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C] <7> [834.491703] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1] <7> [834.491947] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 3 (mbus joined: no) <7> [834.492118] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [834.492283] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [834.492624] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [834.492916] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:88:pipe A] <7> [834.493119] 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> [834.493372] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [834.493655] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [834.493982] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B] <7> [834.494205] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C] <7> [834.494378] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B] <7> [834.494448] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:205:eDP-1] <7> [834.494574] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:205:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [834.494830] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:204:DDI A/PHY A][CRTC:145:pipe B] DP link limits: pixel clock 1175040 kHz DSC off max lanes 4 max rate 675000 max pipe_bpp 30 max link_bpp 30.0000 <7> [834.495056] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 675000 bpp input 18 compressed 0.0000 link rate required 2643840 available 2700000 <7> [834.495284] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:145:pipe B] hw max bpp: 30, pipe bpp: 18, dithering: 1 <7> [834.495555] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:204:DDI A/PHY A] [CRTC:145:pipe B] <7> [834.495796] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [834.496076] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [834.496303] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [834.496558] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [834.496784] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [834.497015] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [834.497242] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2560) <7> [834.497484] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2720) <7> [834.497709] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2560) <7> [834.497932] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2720) <7> [834.498189] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2608) <7> [834.498422] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2640) <7> [834.498638] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1600) <7> [834.498855] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1600) <7> [834.499068] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1663) <7> [834.499281] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1669) <7> [834.499519] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1800) <7> [834.499749] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1800) <7> [834.499960] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2560) <7> [834.500171] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2720) <7> [834.500382] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2560) <7> [834.500651] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2720) <7> [834.500861] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2608) <7> [834.501069] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2640) <7> [834.501278] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1600) <7> [834.501507] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1600) <7> [834.501715] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1663) <7> [834.501916] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1669) <7> [834.502112] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1800) <7> [834.502300] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1800) <7> [834.502551] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [834.502735] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [834.502913] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [834.503123] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [834.503308] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 18) <7> [834.503497] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in port_clock (expected 0, found 675000) <7> [834.503673] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in min_voltage_level (expected 0, found 1) <7> [834.503830] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:145:pipe B] fastset requirement not met, forcing full modeset <7> [834.504150] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [834.504347] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:145:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [834.504567] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:90:plane 1B] ddb ( 0 - 0) -> ( 0 - 3942), size 0 -> 3942 <7> [834.504730] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:140:cursor B] ddb ( 0 - 0) -> (3942 - 4096), size 0 -> 154 <7> [834.504869] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [834.505006] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 46, 46, 46, 43, 46, 0, 0, 0, 9, 0 <7> [834.505145] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 82, 933, 933, 933, 872, 933, 0, 0, 177, 184, 198 <7> [834.505310] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 163,1054,1054,1054, 973,1054, 0, 0, 178, 325, 325 <7> [834.505494] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:145:pipe B] data rate 4700160 num active planes 1 <7> [834.505699] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 4936 qgv_peak_bw: 38400 <7> [834.505899] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 4936 qgv_peak_bw: 38400 <7> [834.506095] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 4936 qgv_peak_bw: 38400 <7> [834.506301] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 4936 qgv_peak_bw: 38400 <7> [834.506529] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 4936 <7> [834.506735] xe 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [xe]] [PLANE:90:plane 1B] min cdclk (587520 kHz) > [CRTC:145:pipe B] min cdclk (0 kHz) <7> [834.506928] xe 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [xe]] new bandwidth min cdclk (91800 kHz) > old min cdclk (0 kHz) <7> [834.507146] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via crawling and squashing <7> [834.507364] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 612000 kHz, actual 612000 kHz <7> [834.507620] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 3, actual 3 <7> [834.507884] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:145:pipe B] enable: yes [modeset] <7> [834.508174] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [834.508433] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 18, dithering: 1 <7> [834.508671] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [834.508907] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [834.509156] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [834.509428] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [834.509670] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 8214124, data_n: 8388608, link_m: 912680, link_n: 524288, tu: 64 <7> [834.509915] 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> [834.510146] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled <7> [834.510367] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [834.510720] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: disabled, selective update: enabled, panel replay: enabled, selective fetch: enabled <7> [834.510949] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [834.511156] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [834.511359] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 6, length 16 <7> [834.511457] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [834.511593] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [834.511756] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [834.511797] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [834.512003] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [834.512028] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [834.512216] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [834.512324] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [834.512438] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [834.512706] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [834.512919] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0 <7> [834.513129] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1800, vmax: 1800, flipline: 1800, pipeline full: 0, guardband: 200 vsync start: 137, vsync end: 131 <7> [834.513391] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1600, vmax vblank: 1600, vmin vtotal: 1800, vmax vtotal: 1800 <7> [834.513646] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2560x1600": 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa <7> [834.513883] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2560x1600": 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa <7> [834.514097] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=1175040, hd=2560 hb=2560-2720 hs=2608-2640 ht=2720, vd=1600 vb=1600-1800 vs=1663-1669 vt=1800, flags=0xa <7> [834.514307] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2560x1600": 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x40 0xa <7> [834.514533] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=1175040, hd=2560 hb=2560-2720 hs=2608-2640 ht=2720, vd=1600 vb=1600-1800 vs=1663-1669 vt=1800, flags=0xa <7> [834.514772] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 675000, pipe src: 2560x1600+0+0, pixel rate 1175040 <7> [834.514979] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 19, ips linetime: 0 <7> [834.515172] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [834.515420] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [834.515630] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [834.515843] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0xa4cb8, dpll_md: 0xb42110, fp0: 0x13e, fp1: 0x1000000 <7> [834.516046] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [834.516238] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [834.516445] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [834.516656] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [834.516835] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [834.517011] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [834.517181] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [834.517346] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [834.517529] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [834.517689] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [834.517845] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [834.518002] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [834.518155] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:90:plane 1B] fb: [FB:245] 2560x1600 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [834.518306] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [834.518461] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2560.000000x1600.000000+0.000000+0.000000 dst: 2560x1600+0+0 <7> [834.518624] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:100:plane 2B] fb: [NOFB], visible: no <7> [834.518759] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:110:plane 3B] fb: [NOFB], visible: no <7> [834.518892] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:120:plane 4B] fb: [NOFB], visible: no <7> [834.519025] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:130:plane 5B] fb: [NOFB], visible: no <7> [834.519153] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:140:cursor B] fb: [NOFB], visible: no <7> [834.519654] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [834.519791] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [834.520084] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [834.520271] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [834.520458] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [834.520649] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 612000 kHz, VCO 1305600 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 3 <7> [834.520823] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 3 (mbus joined: no) <7> [834.520941] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=1530 <7> [834.521059] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A] <7> [834.521157] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1] <7> [834.521252] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A] <7> [834.521343] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B] <7> [834.521446] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C] <7> [834.521533] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2] <7> [834.521616] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A] <7> [834.521697] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B] <7> [834.521777] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C] <7> [834.521854] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3] <7> [834.521933] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A] <7> [834.522012] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B] <7> [834.522091] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C] <7> [834.522167] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [834.522345] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [834.522436] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 6 (mbus joined: yes) <7> [834.522555] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [834.523492] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD on <7> [834.523580] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power cycle (466 ms remaining) <7> [834.992487] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [835.045454] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [835.045735] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x00000000 PP_CONTROL: 0x00000068 <7> [835.045961] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 panel power wasn't enabled <7> [835.248713] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power on <7> [835.248967] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power cycle (0 ms remaining) <7> [835.249210] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x00000000 PP_CONTROL: 0x00000068 <7> [835.259407] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [835.259656] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power on <7> [835.259892] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x0000006b <7> [835.472586] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [835.476451] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e c4 c1 00 00 01 c0 02 00 02 00 08 09 84 <7> [835.478043] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [835.478779] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 07 <7> [835.479746] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [835.480828] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [835.481734] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Clock recovery OK <7> [835.481984] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [835.499621] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [835.499845] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Link Training passed at link rate = 675000, lane count = 4 <7> [835.500442] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [835.500741] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [835.500953] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [835.501286] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 13892 <7> [835.501650] xe 0000:00:02.0: [drm:i915_hotplug_work_func [xe]] running encoder hotplug functions <7> [835.505014] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling Panel Replay <7> [835.506535] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1] <7> [835.506796] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:145:pipe B] <3> [835.913868] usb usb4-port1: Cannot enable. Maybe the USB cable is bad? <4> [835.913961] usb usb4-port1: config error <7> [838.048151] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD off <7> [838.048455] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <3> [839.968332] usb usb4-port1: Cannot enable. Maybe the USB cable is bad? <4> [839.968412] usb usb4-port1: config error <7> [842.610719] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [842.611099] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [842.611391] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [842.651582] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

8.52 seconds

Igt-Version

IGT-Version: 2.1-g8a840cd64 (x86_64) (Linux: 6.17.0-rc3-lgci-xe-xe-3643-99f4b32d88cb9718c+ x86_64)

Out

Starting dynamic subtest: B-eDP1
  2560x1600: 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1884 run_test()
  #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (8.518s)

Err

Starting dynamic subtest: B-eDP1
(kms_flip:3356) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:3356) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3356) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:3356) DEBUG: Vblank took 99us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.281982
last_received_ts = 823.281677
last_seq = 29184
current_ts = 823.286133
current_received_ts = 823.285828
current_seq = 29185
count = 1578
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 102us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.286133
last_received_ts = 823.285828
last_seq = 29185
current_ts = 823.290344
current_received_ts = 823.289978
current_seq = 29186
count = 1579
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 55us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.290344
last_received_ts = 823.289978
last_seq = 29186
current_ts = 823.294495
current_received_ts = 823.294128
current_seq = 29187
count = 1580
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 108us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.294495
last_received_ts = 823.294128
last_seq = 29187
current_ts = 823.298645
current_received_ts = 823.298340
current_seq = 29188
count = 1581
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 111us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.298645
last_received_ts = 823.298340
last_seq = 29188
current_ts = 823.302795
current_received_ts = 823.302490
current_seq = 29189
count = 1582
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 101us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.302795
last_received_ts = 823.302490
last_seq = 29189
current_ts = 823.307007
current_received_ts = 823.306702
current_seq = 29190
count = 1583
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 118us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.307007
last_received_ts = 823.306702
last_seq = 29190
current_ts = 823.311157
current_received_ts = 823.310852
current_seq = 29191
count = 1584
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 35us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.311157
last_received_ts = 823.310852
last_seq = 29191
current_ts = 823.315308
current_received_ts = 823.315002
current_seq = 29192
count = 1585
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 107us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.315308
last_received_ts = 823.315002
last_seq = 29192
current_ts = 823.319458
current_received_ts = 823.319153
current_seq = 29193
count = 1586
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 108us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.319458
last_received_ts = 823.319153
last_seq = 29193
current_ts = 823.323669
current_received_ts = 823.323303
current_seq = 29194
count = 1587
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 115us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.323669
last_received_ts = 823.323303
last_seq = 29194
current_ts = 823.327820
current_received_ts = 823.327515
current_seq = 29195
count = 1588
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 89us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.327820
last_received_ts = 823.327515
last_seq = 29195
current_ts = 823.331970
current_received_ts = 823.331665
current_seq = 29196
count = 1589
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 105us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.331970
last_received_ts = 823.331665
last_seq = 29196
current_ts = 823.336182
current_received_ts = 823.335876
current_seq = 29197
count = 1590
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 123us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.336182
last_received_ts = 823.335876
last_seq = 29197
current_ts = 823.340332
current_received_ts = 823.340027
current_seq = 29198
count = 1591
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 98us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.340332
last_received_ts = 823.340027
last_seq = 29198
current_ts = 823.344482
current_received_ts = 823.344177
current_seq = 29199
count = 1592
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 108us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.344482
last_received_ts = 823.344177
last_seq = 29199
current_ts = 823.348633
current_received_ts = 823.348328
current_seq = 29200
count = 1593
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 34us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.348633
last_received_ts = 823.348328
last_seq = 29200
current_ts = 823.352844
current_received_ts = 823.352539
current_seq = 29201
count = 1594
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 114us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.352844
last_received_ts = 823.352539
last_seq = 29201
current_ts = 823.356995
current_received_ts = 823.356689
current_seq = 29202
count = 1595
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 104us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.356995
last_received_ts = 823.356689
last_seq = 29202
current_ts = 823.361145
current_received_ts = 823.360840
current_seq = 29203
count = 1596
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 102us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.361145
last_received_ts = 823.360840
last_seq = 29203
current_ts = 823.365295
current_received_ts = 823.365051
current_seq = 29204
count = 1597
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 76us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.365295
last_received_ts = 823.365051
last_seq = 29204
current_ts = 823.369507
current_received_ts = 823.369141
current_seq = 29205
count = 1598
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 51us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.369507
last_received_ts = 823.369141
last_seq = 29205
current_ts = 823.373657
current_received_ts = 823.373352
current_seq = 29206
count = 1599
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 131us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.373657
last_received_ts = 823.373352
last_seq = 29206
current_ts = 823.377808
current_received_ts = 823.377502
current_seq = 29207
count = 1600
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 97us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.377808
last_received_ts = 823.377502
last_seq = 29207
current_ts = 823.382019
current_received_ts = 823.381653
current_seq = 29208
count = 1601
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 102us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.382019
last_received_ts = 823.381653
last_seq = 29208
current_ts = 823.386169
current_received_ts = 823.385864
current_seq = 29209
count = 1602
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 142us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.386169
last_received_ts = 823.385864
last_seq = 29209
current_ts = 823.390320
current_received_ts = 823.390015
current_seq = 29210
count = 1603
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 32us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.390320
last_received_ts = 823.390015
last_seq = 29210
current_ts = 823.394470
current_received_ts = 823.394165
current_seq = 29211
count = 1604
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 34us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.394470
last_received_ts = 823.394165
last_seq = 29211
current_ts = 823.398682
current_received_ts = 823.398315
current_seq = 29212
count = 1605
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 112us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.398682
last_received_ts = 823.398315
last_seq = 29212
current_ts = 823.402832
current_received_ts = 823.402527
current_seq = 29213
count = 1606
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 100us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.402832
last_received_ts = 823.402527
last_seq = 29213
current_ts = 823.406982
current_received_ts = 823.406677
current_seq = 29214
count = 1607
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 100us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.406982
last_received_ts = 823.406677
last_seq = 29214
current_ts = 823.411133
current_received_ts = 823.410828
current_seq = 29215
count = 1608
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 116us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.411133
last_received_ts = 823.410828
last_seq = 29215
current_ts = 823.415344
current_received_ts = 823.415039
current_seq = 29216
count = 1609
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 104us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.415344
last_received_ts = 823.415039
last_seq = 29216
current_ts = 823.419495
current_received_ts = 823.419128
current_seq = 29217
count = 1610
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 33us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.419495
last_received_ts = 823.419128
last_seq = 29217
current_ts = 823.423645
current_received_ts = 823.423340
current_seq = 29218
count = 1611
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 108us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.423645
last_received_ts = 823.423340
last_seq = 29218
current_ts = 823.427856
current_received_ts = 823.427551
current_seq = 29219
count = 1612
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 114us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.427856
last_received_ts = 823.427551
last_seq = 29219
current_ts = 823.432007
current_received_ts = 823.431702
current_seq = 29220
count = 1613
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 112us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.432007
last_received_ts = 823.431702
last_seq = 29220
current_ts = 823.436157
current_received_ts = 823.435852
current_seq = 29221
count = 1614
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 100us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.436157
last_received_ts = 823.435852
last_seq = 29221
current_ts = 823.440308
current_received_ts = 823.440063
current_seq = 29222
count = 1615
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 89us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.440308
last_received_ts = 823.440063
last_seq = 29222
current_ts = 823.444519
current_received_ts = 823.444153
current_seq = 29223
count = 1616
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 50us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.444519
last_received_ts = 823.444153
last_seq = 29223
current_ts = 823.448669
current_received_ts = 823.448364
current_seq = 29224
count = 1617
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 49us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.448669
last_received_ts = 823.448364
last_seq = 29224
current_ts = 823.452820
current_received_ts = 823.452515
current_seq = 29225
count = 1618
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 109us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.452820
last_received_ts = 823.452515
last_seq = 29225
current_ts = 823.456970
current_received_ts = 823.456726
current_seq = 29226
count = 1619
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 133us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.456970
last_received_ts = 823.456726
last_seq = 29226
current_ts = 823.461182
current_received_ts = 823.460876
current_seq = 29227
count = 1620
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 124us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.461182
last_received_ts = 823.460876
last_seq = 29227
current_ts = 823.465332
current_received_ts = 823.465027
current_seq = 29228
count = 1621
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 114us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.465332
last_received_ts = 823.465027
last_seq = 29228
current_ts = 823.469482
current_received_ts = 823.469177
current_seq = 29229
count = 1622
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 33us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.469482
last_received_ts = 823.469177
last_seq = 29229
current_ts = 823.473694
current_received_ts = 823.473328
current_seq = 29230
count = 1623
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 133us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.473694
last_received_ts = 823.473328
last_seq = 29230
current_ts = 823.477844
current_received_ts = 823.477539
current_seq = 29231
count = 1624
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 108us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.477844
last_received_ts = 823.477539
last_seq = 29231
current_ts = 823.481995
current_received_ts = 823.481689
current_seq = 29232
count = 1625
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 131us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.481995
last_received_ts = 823.481689
last_seq = 29232
current_ts = 823.486145
current_received_ts = 823.485840
current_seq = 29233
count = 1626
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 86us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.486145
last_received_ts = 823.485840
last_seq = 29233
current_ts = 823.490356
current_received_ts = 823.490051
current_seq = 29234
count = 1627
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 100us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.490356
last_received_ts = 823.490051
last_seq = 29234
current_ts = 823.494507
current_received_ts = 823.494141
current_seq = 29235
count = 1628
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 111us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.494507
last_received_ts = 823.494141
last_seq = 29235
current_ts = 823.498657
current_received_ts = 823.498352
current_seq = 29236
count = 1629
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 116us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.498657
last_received_ts = 823.498352
last_seq = 29236
current_ts = 823.502808
current_received_ts = 823.502502
current_seq = 29237
count = 1630
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 128us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.502808
last_received_ts = 823.502502
last_seq = 29237
current_ts = 823.507019
current_received_ts = 823.506714
current_seq = 29238
count = 1631
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 115us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.507019
last_received_ts = 823.506714
last_seq = 29238
current_ts = 823.511169
current_received_ts = 823.510864
current_seq = 29239
count = 1632
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 96us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.511169
last_received_ts = 823.510864
last_seq = 29239
current_ts = 823.515320
current_received_ts = 823.515015
current_seq = 29240
count = 1633
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 104us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.515320
last_received_ts = 823.515015
last_seq = 29240
current_ts = 823.519531
current_received_ts = 823.519165
current_seq = 29241
count = 1634
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 35us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.519531
last_received_ts = 823.519165
last_seq = 29241
current_ts = 823.523682
current_received_ts = 823.523376
current_seq = 29242
count = 1635
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 97us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.523682
last_received_ts = 823.523376
last_seq = 29242
current_ts = 823.527832
current_received_ts = 823.527527
current_seq = 29243
count = 1636
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 128us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.527832
last_received_ts = 823.527527
last_seq = 29243
current_ts = 823.531982
current_received_ts = 823.531677
current_seq = 29244
count = 1637
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 113us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.531982
last_received_ts = 823.531677
last_seq = 29244
current_ts = 823.536194
current_received_ts = 823.535889
current_seq = 29245
count = 1638
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 90us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.536194
last_received_ts = 823.535889
last_seq = 29245
current_ts = 823.540344
current_received_ts = 823.540039
current_seq = 29246
count = 1639
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 106us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.540344
last_received_ts = 823.540039
last_seq = 29246
current_ts = 823.544495
current_received_ts = 823.544189
current_seq = 29247
count = 1640
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 33us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.544495
last_received_ts = 823.544189
last_seq = 29247
current_ts = 823.548645
current_received_ts = 823.548340
current_seq = 29248
count = 1641
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 104us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.548645
last_received_ts = 823.548340
last_seq = 29248
current_ts = 823.552856
current_received_ts = 823.552551
current_seq = 29249
count = 1642
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 103us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.552856
last_received_ts = 823.552551
last_seq = 29249
current_ts = 823.557007
current_received_ts = 823.556702
current_seq = 29250
count = 1643
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 117us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.557007
last_received_ts = 823.556702
last_seq = 29250
current_ts = 823.561157
current_received_ts = 823.560852
current_seq = 29251
count = 1644
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 110us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.561157
last_received_ts = 823.560852
last_seq = 29251
current_ts = 823.565369
current_received_ts = 823.565002
current_seq = 29252
count = 1645
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 32us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.565369
last_received_ts = 823.565002
last_seq = 29252
current_ts = 823.569519
current_received_ts = 823.569153
current_seq = 29253
count = 1646
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 31us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.569519
last_received_ts = 823.569153
last_seq = 29253
current_ts = 823.573669
current_received_ts = 823.573364
current_seq = 29254
count = 1647
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 128us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.573669
last_received_ts = 823.573364
last_seq = 29254
current_ts = 823.577820
current_received_ts = 823.577515
current_seq = 29255
count = 1648
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 101us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.577820
last_received_ts = 823.577515
last_seq = 29255
current_ts = 823.582031
current_received_ts = 823.581726
current_seq = 29256
count = 1649
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 116us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.582031
last_received_ts = 823.581726
last_seq = 29256
current_ts = 823.586182
current_received_ts = 823.585876
current_seq = 29257
count = 1650
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 119us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.586182
last_received_ts = 823.585876
last_seq = 29257
current_ts = 823.590332
current_received_ts = 823.590027
current_seq = 29258
count = 1651
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 111us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.590332
last_received_ts = 823.590027
last_seq = 29258
current_ts = 823.594543
current_received_ts = 823.594177
current_seq = 29259
count = 1652
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 105us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.594543
last_received_ts = 823.594177
last_seq = 29259
current_ts = 823.598694
current_received_ts = 823.598389
current_seq = 29260
count = 1653
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 129us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.598694
last_received_ts = 823.598389
last_seq = 29260
current_ts = 823.602844
current_received_ts = 823.602539
current_seq = 29261
count = 1654
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 120us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.602844
last_received_ts = 823.602539
last_seq = 29261
current_ts = 823.606995
current_received_ts = 823.606689
current_seq = 29262
count = 1655
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 96us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.606995
last_received_ts = 823.606689
last_seq = 29262
current_ts = 823.611206
current_received_ts = 823.610901
current_seq = 29263
count = 1656
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 119us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.611206
last_received_ts = 823.610901
last_seq = 29263
current_ts = 823.615356
current_received_ts = 823.615051
current_seq = 29264
count = 1657
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 49us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.615356
last_received_ts = 823.615051
last_seq = 29264
current_ts = 823.619507
current_received_ts = 823.619202
current_seq = 29265
count = 1658
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 34us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.619507
last_received_ts = 823.619202
last_seq = 29265
current_ts = 823.623657
current_received_ts = 823.623352
current_seq = 29266
count = 1659
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 117us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.623657
last_received_ts = 823.623352
last_seq = 29266
current_ts = 823.627869
current_received_ts = 823.627563
current_seq = 29267
count = 1660
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 114us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.627869
last_received_ts = 823.627563
last_seq = 29267
current_ts = 823.632019
current_received_ts = 823.631714
current_seq = 29268
count = 1661
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 106us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.632019
last_received_ts = 823.631714
last_seq = 29268
current_ts = 823.636169
current_received_ts = 823.635864
current_seq = 29269
count = 1662
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 126us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.636169
last_received_ts = 823.635864
last_seq = 29269
current_ts = 823.640381
current_received_ts = 823.640076
current_seq = 29270
count = 1663
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 35us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.640381
last_received_ts = 823.640076
last_seq = 29270
current_ts = 823.644531
current_received_ts = 823.644165
current_seq = 29271
count = 1664
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 33us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.644531
last_received_ts = 823.644165
last_seq = 29271
current_ts = 823.648682
current_received_ts = 823.648376
current_seq = 29272
count = 1665
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 115us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.648682
last_received_ts = 823.648376
last_seq = 29272
current_ts = 823.652832
current_received_ts = 823.652527
current_seq = 29273
count = 1666
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 114us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.652832
last_received_ts = 823.652527
last_seq = 29273
current_ts = 823.657043
current_received_ts = 823.656738
current_seq = 29274
count = 1667
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 108us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.657043
last_received_ts = 823.656738
last_seq = 29274
current_ts = 823.661194
current_received_ts = 823.660889
current_seq = 29275
count = 1668
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 88us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.661194
last_received_ts = 823.660889
last_seq = 29275
current_ts = 823.665344
current_received_ts = 823.665039
current_seq = 29276
count = 1669
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 103us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.665344
last_received_ts = 823.665039
last_seq = 29276
current_ts = 823.669495
current_received_ts = 823.669189
current_seq = 29277
count = 1670
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 32us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.669495
last_received_ts = 823.669189
last_seq = 29277
current_ts = 823.673706
current_received_ts = 823.673401
current_seq = 29278
count = 1671
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 125us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.673706
last_received_ts = 823.673401
last_seq = 29278
current_ts = 823.677856
current_received_ts = 823.677551
current_seq = 29279
count = 1672
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 117us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.677856
last_received_ts = 823.677551
last_seq = 29279
current_ts = 823.682007
current_received_ts = 823.681702
current_seq = 29280
count = 1673
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 101us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.682007
last_received_ts = 823.681702
last_seq = 29280
current_ts = 823.686157
current_received_ts = 823.685913
current_seq = 29281
count = 1674
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 33us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.686157
last_received_ts = 823.685913
last_seq = 29281
current_ts = 823.690369
current_received_ts = 823.690063
current_seq = 29282
count = 1675
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 50us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.690369
last_received_ts = 823.690063
last_seq = 29282
current_ts = 823.694519
current_received_ts = 823.694214
current_seq = 29283
count = 1676
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 34us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.694519
last_received_ts = 823.694214
last_seq = 29283
current_ts = 823.698669
current_received_ts = 823.698364
current_seq = 29284
count = 1677
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 117us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.698669
last_received_ts = 823.698364
last_seq = 29284
current_ts = 823.702881
current_received_ts = 823.702576
current_seq = 29285
count = 1678
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 111us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.702881
last_received_ts = 823.702576
last_seq = 29285
current_ts = 823.707031
current_received_ts = 823.706726
current_seq = 29286
count = 1679
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 99us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.707031
last_received_ts = 823.706726
last_seq = 29286
current_ts = 823.711182
current_received_ts = 823.710876
current_seq = 29287
count = 1680
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 88us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.711182
last_received_ts = 823.710876
last_seq = 29287
current_ts = 823.715332
current_received_ts = 823.715027
current_seq = 29288
count = 1681
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 49us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.715332
last_received_ts = 823.715027
last_seq = 29288
current_ts = 823.719543
current_received_ts = 823.719177
current_seq = 29289
count = 1682
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 31us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.719543
last_received_ts = 823.719177
last_seq = 29289
current_ts = 823.723694
current_received_ts = 823.723389
current_seq = 29290
count = 1683
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 112us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.723694
last_received_ts = 823.723389
last_seq = 29290
current_ts = 823.727844
current_received_ts = 823.727539
current_seq = 29291
count = 1684
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 126us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.727844
last_received_ts = 823.727539
last_seq = 29291
current_ts = 823.731995
current_received_ts = 823.731750
current_seq = 29292
count = 1685
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 102us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.731995
last_received_ts = 823.731750
last_seq = 29292
current_ts = 823.736206
current_received_ts = 823.735901
current_seq = 29293
count = 1686
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 106us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.736206
last_received_ts = 823.735901
last_seq = 29293
current_ts = 823.740356
current_received_ts = 823.740051
current_seq = 29294
count = 1687
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 36us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.740356
last_received_ts = 823.740051
last_seq = 29294
current_ts = 823.744507
current_received_ts = 823.744202
current_seq = 29295
count = 1688
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 33us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.744507
last_received_ts = 823.744202
last_seq = 29295
current_ts = 823.748718
current_received_ts = 823.748413
current_seq = 29296
count = 1689
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 132us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.748718
last_received_ts = 823.748413
last_seq = 29296
current_ts = 823.752869
current_received_ts = 823.752563
current_seq = 29297
count = 1690
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 98us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.752869
last_received_ts = 823.752563
last_seq = 29297
current_ts = 823.757019
current_received_ts = 823.756714
current_seq = 29298
count = 1691
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 96us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.757019
last_received_ts = 823.756714
last_seq = 29298
current_ts = 823.761169
current_received_ts = 823.760925
current_seq = 29299
count = 1692
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 117us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.761169
last_received_ts = 823.760925
last_seq = 29299
current_ts = 823.765381
current_received_ts = 823.765015
current_seq = 29300
count = 1693
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 108us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.765381
last_received_ts = 823.765015
last_seq = 29300
current_ts = 823.769531
current_received_ts = 823.769226
current_seq = 29301
count = 1694
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 32us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.769531
last_received_ts = 823.769226
last_seq = 29301
current_ts = 823.773682
current_received_ts = 823.773376
current_seq = 29302
count = 1695
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 95us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.773682
last_received_ts = 823.773376
last_seq = 29302
current_ts = 823.777893
current_received_ts = 823.777527
current_seq = 29303
count = 1696
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 34us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.777893
last_received_ts = 823.777527
last_seq = 29303
current_ts = 823.782043
current_received_ts = 823.781738
current_seq = 29304
count = 1697
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 101us
(kms_flip:3356) DEBUG: name = flip
last_ts = 823.782043
last_received_ts = 823.781738
last_seq = 29304
current_ts = 823.786194
current_received_ts = 823.785889
current_seq = 29305
count = 1698
seq_step = 1
(kms_flip:3356) DEBUG: Vblank took 784us
(kms_flip:3356) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:3356) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3356) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:3356) igt_core-INFO: Stack trace:
(kms_flip:3356) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:3356) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:3356) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:3356) igt_core-INFO:   #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
(kms_flip:3356) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:3356) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3356) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3356) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (8.518s)

Dmesg

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

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

<7> [834.135075] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:246]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [834.210164] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:33:plane 1A] ddb ( 0 - 3942) -> ( 0 - 0), size 3942 -> 0

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

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

<7> [834.210532] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:33:plane 1A] lines 4, 46, 46, 46, 43, 46, 0, 0, 0, 9, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [834.210642] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:33:plane 1A] blocks 82, 933, 933, 933, 872, 933, 0, 0, 177, 184, 198 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [834.210748] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:33:plane 1A] min_ddb 163,1054,1054,1054, 973,1054, 0, 0, 178, 325, 325 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [834.213802] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling Panel Replay

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [834.495056] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 675000 bpp input 18 compressed 0.0000 link rate required 2643840 available 2700000

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [834.505006] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 46, 46, 46, 43, 46, 0, 0, 0, 9, 0

<7> [834.505145] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 82, 933, 933, 933, 872, 933, 0, 0, 177, 184, 198

<7> [834.505310] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 163,1054,1054,1054, 973,1054, 0, 0, 178, 325, 325

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [834.508433] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 18, dithering: 1

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

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

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

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

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

<7> [834.509915] 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> [834.510146] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled

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

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

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

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

<7> [834.511359] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 6, length 16

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

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

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

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

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

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

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

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

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

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

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

<7> [834.513129] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1800, vmax: 1800, flipline: 1800, pipeline full: 0, guardband: 200 vsync start: 137, vsync end: 131

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

<7> [834.513646] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2560x1600": 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa

<7> [834.513883] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2560x1600": 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa

<7> [834.514097] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=1175040, hd=2560 hb=2560-2720 hs=2608-2640 ht=2720, vd=1600 vb=1600-1800 vs=1663-1669 vt=1800, flags=0xa

<7> [834.514307] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2560x1600": 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x40 0xa

<7> [834.514533] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=1175040, hd=2560 hb=2560-2720 hs=2608-2640 ht=2720, vd=1600 vb=1600-1800 vs=1663-1669 vt=1800, flags=0xa

<7> [834.514772] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 675000, pipe src: 2560x1600+0+0, pixel rate 1175040

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

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

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

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

<7> [834.515843] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0xa4cb8, dpll_md: 0xb42110, fp0: 0x13e, fp1: 0x1000000

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [834.518461] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2560.000000x1600.000000+0.000000+0.000000 dst: 2560x1600+0+0

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

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

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

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

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

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

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

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

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

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

<7> [834.520649] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 612000 kHz, VCO 1305600 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 3

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [835.045735] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x00000000 PP_CONTROL: 0x00000068

<7> [835.045961] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 panel power wasn't enabled

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

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

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

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

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

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

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

<7> [835.476451] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e c4 c1 00 00 01 c0 02 00 02 00 08 09 84

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

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

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

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

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

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

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

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

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

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

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

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

<7> [835.501650] xe 0000:00:02.0: [drm:i915_hotplug_work_func [xe]] running encoder hotplug functions

<7> [835.505014] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling Panel Replay

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

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

<3> [835.913868] usb usb4-port1: Cannot enable. Maybe the USB cable is bad?

<4> [835.913961] usb usb4-port1: config error

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

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

<3> [839.968332] usb usb4-port1: Cannot enable. Maybe the USB cable is bad?

<4> [839.968412] usb usb4-port1: config error

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

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

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

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

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