Hardware List

Results for igt@kms_flip@plain-flip-ts-check@a-edp1

Machine description: shard-mtlp-6

Result: Fail

git-log-oneline i915_display_info13 igt_runner13 runtimes13 results13.json results13-i915-load.json i915_display_info_post_exec13 boot13 dmesg13

Detail	Value
Duration	12.27 seconds
Hostname	shard-mtlp-6
Igt-Version	IGT-Version: 1.30-g1595d0371 (x86_64) (Linux: 6.14.0-rc5-CI_DRM_16231-g3ccfd8016ad8+ x86_64)
Out	Using IGT_SRANDOM=1741248571 for randomisation Opened device: /dev/dri/card0 Using monotonic timestamps Starting subtest: plain-flip-ts-check Starting dynamic subtest: A-eDP1 2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa Expected frametime: 11111us; measured 11059.4us +- 4.802us accuracy 0.13% vblank interval differs from modeline! expected 11111.1us, measured 11059us +- 4.802us, difference 51.7us (10.8 sigma) Stack trace: #0 ../lib/igt_core.c:2055 __igt_fail_assert() #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1845 run_test() #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001() #4 ../tests/kms_flip.c:2001 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-eDP1: FAIL (12.267s)
Err	Starting subtest: plain-flip-ts-check Starting dynamic subtest: A-eDP1 (kms_flip:2213) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674: (kms_flip:2213) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon) Dynamic subtest A-eDP1 failed. ** DEBUG (kms_flip:2213) DEBUG: name = flip last_ts = 68.620064 last_received_ts = 68.619743 last_seq = 1497 current_ts = 68.631149 current_received_ts = 68.630852 current_seq = 1498 count = 556 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.620064/1497, current 68.631149/1498: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.631149 last_received_ts = 68.630852 last_seq = 1498 current_ts = 68.642242 current_received_ts = 68.641922 current_seq = 1499 count = 557 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.631149/1498, current 68.642242/1499: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.642242 last_received_ts = 68.641922 last_seq = 1499 current_ts = 68.653336 current_received_ts = 68.653023 current_seq = 1500 count = 558 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.642242/1499, current 68.653336/1500: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.653336 last_received_ts = 68.653023 last_seq = 1500 current_ts = 68.664421 current_received_ts = 68.664108 current_seq = 1501 count = 559 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.653336/1500, current 68.664421/1501: elapsed=11087.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 68.664421 last_received_ts = 68.664108 last_seq = 1501 current_ts = 68.675507 current_received_ts = 68.675201 current_seq = 1502 count = 560 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.664421/1501, current 68.675507/1502: elapsed=11086.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 68.675507 last_received_ts = 68.675201 last_seq = 1502 current_ts = 68.686600 current_received_ts = 68.686272 current_seq = 1503 count = 561 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.675507/1502, current 68.686600/1503: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.686600 last_received_ts = 68.686272 last_seq = 1503 current_ts = 68.697685 current_received_ts = 68.697411 current_seq = 1504 count = 562 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.686600/1503, current 68.697685/1504: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.697685 last_received_ts = 68.697411 last_seq = 1504 current_ts = 68.708778 current_received_ts = 68.708496 current_seq = 1505 count = 563 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.697685/1504, current 68.708778/1505: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.708778 last_received_ts = 68.708496 last_seq = 1505 current_ts = 68.719872 current_received_ts = 68.719566 current_seq = 1506 count = 564 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.708778/1505, current 68.719872/1506: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.719872 last_received_ts = 68.719566 last_seq = 1506 current_ts = 68.730957 current_received_ts = 68.730659 current_seq = 1507 count = 565 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.719872/1506, current 68.730957/1507: elapsed=11087.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 68.730957 last_received_ts = 68.730659 last_seq = 1507 current_ts = 68.742043 current_received_ts = 68.741669 current_seq = 1508 count = 566 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.730957/1507, current 68.742043/1508: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.742043 last_received_ts = 68.741669 last_seq = 1508 current_ts = 68.753136 current_received_ts = 68.752747 current_seq = 1509 count = 567 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.742043/1508, current 68.753136/1509: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.753136 last_received_ts = 68.752747 last_seq = 1509 current_ts = 68.764221 current_received_ts = 68.763870 current_seq = 1510 count = 568 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.753136/1509, current 68.764221/1510: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.764221 last_received_ts = 68.763870 last_seq = 1510 current_ts = 68.775314 current_received_ts = 68.774925 current_seq = 1511 count = 569 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.764221/1510, current 68.775314/1511: elapsed=11089.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.775314 last_received_ts = 68.774925 last_seq = 1511 current_ts = 68.786400 current_received_ts = 68.786026 current_seq = 1512 count = 570 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.775314/1511, current 68.786400/1512: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.786400 last_received_ts = 68.786026 last_seq = 1512 current_ts = 68.797493 current_received_ts = 68.797188 current_seq = 1513 count = 571 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.786400/1512, current 68.797493/1513: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.797493 last_received_ts = 68.797188 last_seq = 1513 current_ts = 68.808578 current_received_ts = 68.808258 current_seq = 1514 count = 572 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.797493/1513, current 68.808578/1514: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.808578 last_received_ts = 68.808258 last_seq = 1514 current_ts = 68.819672 current_received_ts = 68.819359 current_seq = 1515 count = 573 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.808578/1514, current 68.819672/1515: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.819672 last_received_ts = 68.819359 last_seq = 1515 current_ts = 68.830757 current_received_ts = 68.830460 current_seq = 1516 count = 574 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.819672/1515, current 68.830757/1516: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.830757 last_received_ts = 68.830460 last_seq = 1516 current_ts = 68.841850 current_received_ts = 68.841553 current_seq = 1517 count = 575 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.830757/1516, current 68.841850/1517: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.841850 last_received_ts = 68.841553 last_seq = 1517 current_ts = 68.852943 current_received_ts = 68.852638 current_seq = 1518 count = 576 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.841850/1517, current 68.852943/1518: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.852943 last_received_ts = 68.852638 last_seq = 1518 current_ts = 68.864029 current_received_ts = 68.863716 current_seq = 1519 count = 577 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.852943/1518, current 68.864029/1519: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.864029 last_received_ts = 68.863716 last_seq = 1519 current_ts = 68.875114 current_received_ts = 68.874802 current_seq = 1520 count = 578 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.864029/1519, current 68.875114/1520: elapsed=11087.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 68.875114 last_received_ts = 68.874802 last_seq = 1520 current_ts = 68.886208 current_received_ts = 68.885902 current_seq = 1521 count = 579 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.875114/1520, current 68.886208/1521: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.886208 last_received_ts = 68.885902 last_seq = 1521 current_ts = 68.897293 current_received_ts = 68.896988 current_seq = 1522 count = 580 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.886208/1521, current 68.897293/1522: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.897293 last_received_ts = 68.896988 last_seq = 1522 current_ts = 68.908386 current_received_ts = 68.908058 current_seq = 1523 count = 581 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.897293/1522, current 68.908386/1523: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.908386 last_received_ts = 68.908058 last_seq = 1523 current_ts = 68.919479 current_received_ts = 68.919182 current_seq = 1524 count = 582 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.908386/1523, current 68.919479/1524: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.919479 last_received_ts = 68.919182 last_seq = 1524 current_ts = 68.930565 current_received_ts = 68.930260 current_seq = 1525 count = 583 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.919479/1524, current 68.930565/1525: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.930565 last_received_ts = 68.930260 last_seq = 1525 current_ts = 68.941658 current_received_ts = 68.941338 current_seq = 1526 count = 584 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.930565/1525, current 68.941658/1526: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.941658 last_received_ts = 68.941338 last_seq = 1526 current_ts = 68.952744 current_received_ts = 68.952477 current_seq = 1527 count = 585 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.941658/1526, current 68.952744/1527: elapsed=11089.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.952744 last_received_ts = 68.952477 last_seq = 1527 current_ts = 68.963837 current_received_ts = 68.963509 current_seq = 1528 count = 586 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.952744/1527, current 68.963837/1528: elapsed=11089.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.963837 last_received_ts = 68.963509 last_seq = 1528 current_ts = 68.974922 current_received_ts = 68.974602 current_seq = 1529 count = 587 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.963837/1528, current 68.974922/1529: elapsed=11087.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 68.974922 last_received_ts = 68.974602 last_seq = 1529 current_ts = 68.986015 current_received_ts = 68.985725 current_seq = 1530 count = 588 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.974922/1529, current 68.986015/1530: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.986015 last_received_ts = 68.985725 last_seq = 1530 current_ts = 68.997101 current_received_ts = 68.996780 current_seq = 1531 count = 589 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.986015/1530, current 68.997101/1531: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 68.997101 last_received_ts = 68.996780 last_seq = 1531 current_ts = 69.008186 current_received_ts = 69.007881 current_seq = 1532 count = 590 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 68.997101/1531, current 69.008186/1532: elapsed=11086.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 69.008186 last_received_ts = 69.007881 last_seq = 1532 current_ts = 69.019279 current_received_ts = 69.018982 current_seq = 1533 count = 591 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.008186/1532, current 69.019279/1533: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.019279 last_received_ts = 69.018982 last_seq = 1533 current_ts = 69.030373 current_received_ts = 69.030052 current_seq = 1534 count = 592 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.019279/1533, current 69.030373/1534: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.030373 last_received_ts = 69.030052 last_seq = 1534 current_ts = 69.041458 current_received_ts = 69.041138 current_seq = 1535 count = 593 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.030373/1534, current 69.041458/1535: elapsed=11089.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.041458 last_received_ts = 69.041138 last_seq = 1535 current_ts = 69.052544 current_received_ts = 69.052238 current_seq = 1536 count = 594 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.041458/1535, current 69.052544/1536: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.052544 last_received_ts = 69.052238 last_seq = 1536 current_ts = 69.063637 current_received_ts = 69.063309 current_seq = 1537 count = 595 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.052544/1536, current 69.063637/1537: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.063637 last_received_ts = 69.063309 last_seq = 1537 current_ts = 69.074722 current_received_ts = 69.074471 current_seq = 1538 count = 596 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.063637/1537, current 69.074722/1538: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.074722 last_received_ts = 69.074471 last_seq = 1538 current_ts = 69.085823 current_received_ts = 69.085518 current_seq = 1539 count = 597 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.074722/1538, current 69.085823/1539: elapsed=11094.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.085823 last_received_ts = 69.085518 last_seq = 1539 current_ts = 69.096909 current_received_ts = 69.096596 current_seq = 1540 count = 598 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.085823/1539, current 69.096909/1540: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.096909 last_received_ts = 69.096596 last_seq = 1540 current_ts = 69.107994 current_received_ts = 69.107704 current_seq = 1541 count = 599 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.096909/1540, current 69.107994/1541: elapsed=11084.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 69.107994 last_received_ts = 69.107704 last_seq = 1541 current_ts = 69.119087 current_received_ts = 69.118797 current_seq = 1542 count = 600 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.107994/1541, current 69.119087/1542: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.119087 last_received_ts = 69.118797 last_seq = 1542 current_ts = 69.130173 current_received_ts = 69.129860 current_seq = 1543 count = 601 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.119087/1542, current 69.130173/1543: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.130173 last_received_ts = 69.129860 last_seq = 1543 current_ts = 69.141266 current_received_ts = 69.141045 current_seq = 1544 count = 602 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.130173/1543, current 69.141266/1544: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.141266 last_received_ts = 69.141045 last_seq = 1544 current_ts = 69.152351 current_received_ts = 69.152046 current_seq = 1545 count = 603 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.141266/1544, current 69.152351/1545: elapsed=11085.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 69.152351 last_received_ts = 69.152046 last_seq = 1545 current_ts = 69.163445 current_received_ts = 69.163177 current_seq = 1546 count = 604 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.152351/1545, current 69.163445/1546: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.163445 last_received_ts = 69.163177 last_seq = 1546 current_ts = 69.174538 current_received_ts = 69.174232 current_seq = 1547 count = 605 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.163445/1546, current 69.174538/1547: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.174538 last_received_ts = 69.174232 last_seq = 1547 current_ts = 69.185623 current_received_ts = 69.185303 current_seq = 1548 count = 606 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.174538/1547, current 69.185623/1548: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.185623 last_received_ts = 69.185303 last_seq = 1548 current_ts = 69.196709 current_received_ts = 69.196404 current_seq = 1549 count = 607 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.185623/1548, current 69.196709/1549: elapsed=11087.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 69.196709 last_received_ts = 69.196404 last_seq = 1549 current_ts = 69.207802 current_received_ts = 69.207497 current_seq = 1550 count = 608 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.196709/1549, current 69.207802/1550: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.207802 last_received_ts = 69.207497 last_seq = 1550 current_ts = 69.218887 current_received_ts = 69.218575 current_seq = 1551 count = 609 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.207802/1550, current 69.218887/1551: elapsed=11085.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 69.218887 last_received_ts = 69.218575 last_seq = 1551 current_ts = 69.229980 current_received_ts = 69.229683 current_seq = 1552 count = 610 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.218887/1551, current 69.229980/1552: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.229980 last_received_ts = 69.229683 last_seq = 1552 current_ts = 69.241066 current_received_ts = 69.240753 current_seq = 1553 count = 611 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.229980/1552, current 69.241066/1553: elapsed=11087.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 69.241066 last_received_ts = 69.240753 last_seq = 1553 current_ts = 69.252159 current_received_ts = 69.251854 current_seq = 1554 count = 612 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.241066/1553, current 69.252159/1554: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.252159 last_received_ts = 69.251854 last_seq = 1554 current_ts = 69.263252 current_received_ts = 69.262932 current_seq = 1555 count = 613 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.252159/1554, current 69.263252/1555: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.263252 last_received_ts = 69.262932 last_seq = 1555 current_ts = 69.274338 current_received_ts = 69.274063 current_seq = 1556 count = 614 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.263252/1555, current 69.274338/1556: elapsed=11089.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.274338 last_received_ts = 69.274063 last_seq = 1556 current_ts = 69.285431 current_received_ts = 69.285103 current_seq = 1557 count = 615 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.274338/1556, current 69.285431/1557: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.285431 last_received_ts = 69.285103 last_seq = 1557 current_ts = 69.296516 current_received_ts = 69.296196 current_seq = 1558 count = 616 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.285431/1557, current 69.296516/1558: elapsed=11087.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 69.296516 last_received_ts = 69.296196 last_seq = 1558 current_ts = 69.307602 current_received_ts = 69.307312 current_seq = 1559 count = 617 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.296516/1558, current 69.307602/1559: elapsed=11087.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 69.307602 last_received_ts = 69.307312 last_seq = 1559 current_ts = 69.318695 current_received_ts = 69.318382 current_seq = 1560 count = 618 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.307602/1559, current 69.318695/1560: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.318695 last_received_ts = 69.318382 last_seq = 1560 current_ts = 69.329788 current_received_ts = 69.329514 current_seq = 1561 count = 619 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.318695/1560, current 69.329788/1561: elapsed=11089.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.329788 last_received_ts = 69.329514 last_seq = 1561 current_ts = 69.340874 current_received_ts = 69.340553 current_seq = 1562 count = 620 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.329788/1561, current 69.340874/1562: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.340874 last_received_ts = 69.340553 last_seq = 1562 current_ts = 69.351967 current_received_ts = 69.351654 current_seq = 1563 count = 621 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.340874/1562, current 69.351967/1563: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.351967 last_received_ts = 69.351654 last_seq = 1563 current_ts = 69.363052 current_received_ts = 69.362808 current_seq = 1564 count = 622 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.351967/1563, current 69.363052/1564: elapsed=11086.0us expected=11059.4us +- 55.3us, error 0.2% (kms_flip:2213) DEBUG: name = flip last_ts = 69.363052 last_received_ts = 69.362808 last_seq = 1564 current_ts = 69.374146 current_received_ts = 69.373840 current_seq = 1565 count = 623 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.363052/1564, current 69.374146/1565: elapsed=11096.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.374146 last_received_ts = 69.373840 last_seq = 1565 current_ts = 69.385239 current_received_ts = 69.384918 current_seq = 1566 count = 624 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.374146/1565, current 69.385239/1566: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.385239 last_received_ts = 69.384918 last_seq = 1566 current_ts = 69.396332 current_received_ts = 69.396057 current_seq = 1567 count = 625 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.385239/1566, current 69.396332/1567: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.396332 last_received_ts = 69.396057 last_seq = 1567 current_ts = 69.407417 current_received_ts = 69.407104 current_seq = 1568 count = 626 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.396332/1567, current 69.407417/1568: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.407417 last_received_ts = 69.407104 last_seq = 1568 current_ts = 69.418518 current_received_ts = 69.418190 current_seq = 1569 count = 627 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.407417/1568, current 69.418518/1569: elapsed=11094.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.418518 last_received_ts = 69.418190 last_seq = 1569 current_ts = 69.429604 current_received_ts = 69.429298 current_seq = 1570 count = 628 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.418518/1569, current 69.429604/1570: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.429604 last_received_ts = 69.429298 last_seq = 1570 current_ts = 69.440697 current_received_ts = 69.440384 current_seq = 1571 count = 629 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.429604/1570, current 69.440697/1571: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.440697 last_received_ts = 69.440384 last_seq = 1571 current_ts = 69.451790 current_received_ts = 69.451462 current_seq = 1572 count = 630 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.440697/1571, current 69.451790/1572: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.451790 last_received_ts = 69.451462 last_seq = 1572 current_ts = 69.462883 current_received_ts = 69.462570 current_seq = 1573 count = 631 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.451790/1572, current 69.462883/1573: elapsed=11094.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.462883 last_received_ts = 69.462570 last_seq = 1573 current_ts = 69.473976 current_received_ts = 69.473663 current_seq = 1574 count = 632 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.462883/1573, current 69.473976/1574: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.473976 last_received_ts = 69.473663 last_seq = 1574 current_ts = 69.485062 current_received_ts = 69.484749 current_seq = 1575 count = 633 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.473976/1574, current 69.485062/1575: elapsed=11089.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.485062 last_received_ts = 69.484749 last_seq = 1575 current_ts = 69.496162 current_received_ts = 69.495857 current_seq = 1576 count = 634 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.485062/1575, current 69.496162/1576: elapsed=11095.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.496162 last_received_ts = 69.495857 last_seq = 1576 current_ts = 69.507256 current_received_ts = 69.506935 current_seq = 1577 count = 635 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.496162/1576, current 69.507256/1577: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.507256 last_received_ts = 69.506935 last_seq = 1577 current_ts = 69.518341 current_received_ts = 69.518036 current_seq = 1578 count = 636 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.507256/1577, current 69.518341/1578: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.518341 last_received_ts = 69.518036 last_seq = 1578 current_ts = 69.529434 current_received_ts = 69.529152 current_seq = 1579 count = 637 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.518341/1578, current 69.529434/1579: elapsed=11094.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.529434 last_received_ts = 69.529152 last_seq = 1579 current_ts = 69.540527 current_received_ts = 69.540199 current_seq = 1580 count = 638 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.529434/1579, current 69.540527/1580: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.540527 last_received_ts = 69.540199 last_seq = 1580 current_ts = 69.551613 current_received_ts = 69.551292 current_seq = 1581 count = 639 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.540527/1580, current 69.551613/1581: elapsed=11089.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.551613 last_received_ts = 69.551292 last_seq = 1581 current_ts = 69.562714 current_received_ts = 69.562431 current_seq = 1582 count = 640 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.551613/1581, current 69.562714/1582: elapsed=11098.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.562714 last_received_ts = 69.562431 last_seq = 1582 current_ts = 69.573799 current_received_ts = 69.573494 current_seq = 1583 count = 641 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.562714/1582, current 69.573799/1583: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.573799 last_received_ts = 69.573494 last_seq = 1583 current_ts = 69.584900 current_received_ts = 69.584579 current_seq = 1584 count = 642 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.573799/1583, current 69.584900/1584: elapsed=11096.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.584900 last_received_ts = 69.584579 last_seq = 1584 current_ts = 69.595985 current_received_ts = 69.595680 current_seq = 1585 count = 643 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.584900/1584, current 69.595985/1585: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.595985 last_received_ts = 69.595680 last_seq = 1585 current_ts = 69.607079 current_received_ts = 69.606766 current_seq = 1586 count = 644 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.595985/1585, current 69.607079/1586: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.607079 last_received_ts = 69.606766 last_seq = 1586 current_ts = 69.618172 current_received_ts = 69.617912 current_seq = 1587 count = 645 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.607079/1586, current 69.618172/1587: elapsed=11095.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.618172 last_received_ts = 69.617912 last_seq = 1587 current_ts = 69.629265 current_received_ts = 69.628952 current_seq = 1588 count = 646 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.618172/1587, current 69.629265/1588: elapsed=11090.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.629265 last_received_ts = 69.628952 last_seq = 1588 current_ts = 69.640358 current_received_ts = 69.640038 current_seq = 1589 count = 647 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.629265/1588, current 69.640358/1589: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.640358 last_received_ts = 69.640038 last_seq = 1589 current_ts = 69.651443 current_received_ts = 69.651131 current_seq = 1590 count = 648 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.640358/1589, current 69.651443/1590: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.651443 last_received_ts = 69.651131 last_seq = 1590 current_ts = 69.662537 current_received_ts = 69.662239 current_seq = 1591 count = 649 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.651443/1590, current 69.662537/1591: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.662537 last_received_ts = 69.662239 last_seq = 1591 current_ts = 69.673630 current_received_ts = 69.673347 current_seq = 1592 count = 650 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.662537/1591, current 69.673630/1592: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.673630 last_received_ts = 69.673347 last_seq = 1592 current_ts = 69.684723 current_received_ts = 69.684418 current_seq = 1593 count = 651 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.673630/1592, current 69.684723/1593: elapsed=11094.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.684723 last_received_ts = 69.684418 last_seq = 1593 current_ts = 69.695816 current_received_ts = 69.695518 current_seq = 1594 count = 652 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.684723/1593, current 69.695816/1594: elapsed=11094.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.695816 last_received_ts = 69.695518 last_seq = 1594 current_ts = 69.706909 current_received_ts = 69.706604 current_seq = 1595 count = 653 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.695816/1594, current 69.706909/1595: elapsed=11094.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.706909 last_received_ts = 69.706604 last_seq = 1595 current_ts = 69.718002 current_received_ts = 69.717690 current_seq = 1596 count = 654 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.706909/1595, current 69.718002/1596: elapsed=11089.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.718002 last_received_ts = 69.717690 last_seq = 1596 current_ts = 69.729095 current_received_ts = 69.728775 current_seq = 1597 count = 655 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.718002/1596, current 69.729095/1597: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.729095 last_received_ts = 69.728775 last_seq = 1597 current_ts = 69.740189 current_received_ts = 69.739861 current_seq = 1598 count = 656 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.729095/1597, current 69.740189/1598: elapsed=11094.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.740189 last_received_ts = 69.739861 last_seq = 1598 current_ts = 69.751282 current_received_ts = 69.750992 current_seq = 1599 count = 657 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.740189/1598, current 69.751282/1599: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.751282 last_received_ts = 69.750992 last_seq = 1599 current_ts = 69.762367 current_received_ts = 69.762070 current_seq = 1600 count = 658 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.751282/1599, current 69.762367/1600: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.762367 last_received_ts = 69.762070 last_seq = 1600 current_ts = 69.773460 current_received_ts = 69.773140 current_seq = 1601 count = 659 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.762367/1600, current 69.773460/1601: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.773460 last_received_ts = 69.773140 last_seq = 1601 current_ts = 69.784554 current_received_ts = 69.784256 current_seq = 1602 count = 660 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.773460/1601, current 69.784554/1602: elapsed=11096.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.784554 last_received_ts = 69.784256 last_seq = 1602 current_ts = 69.795647 current_received_ts = 69.795326 current_seq = 1603 count = 661 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.784554/1602, current 69.795647/1603: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.795647 last_received_ts = 69.795326 last_seq = 1603 current_ts = 69.806740 current_received_ts = 69.806427 current_seq = 1604 count = 662 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.795647/1603, current 69.806740/1604: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.806740 last_received_ts = 69.806427 last_seq = 1604 current_ts = 69.817833 current_received_ts = 69.817528 current_seq = 1605 count = 663 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.806740/1604, current 69.817833/1605: elapsed=11094.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.817833 last_received_ts = 69.817528 last_seq = 1605 current_ts = 69.828918 current_received_ts = 69.828613 current_seq = 1606 count = 664 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.817833/1605, current 69.828918/1606: elapsed=11089.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.828918 last_received_ts = 69.828613 last_seq = 1606 current_ts = 69.840019 current_received_ts = 69.839691 current_seq = 1607 count = 665 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.828918/1606, current 69.840019/1607: elapsed=11096.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.840019 last_received_ts = 69.839691 last_seq = 1607 current_ts = 69.851105 current_received_ts = 69.850815 current_seq = 1608 count = 666 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.840019/1607, current 69.851105/1608: elapsed=11091.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.851105 last_received_ts = 69.850815 last_seq = 1608 current_ts = 69.862198 current_received_ts = 69.861885 current_seq = 1609 count = 667 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.851105/1608, current 69.862198/1609: elapsed=11088.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.862198 last_received_ts = 69.861885 last_seq = 1609 current_ts = 69.873291 current_received_ts = 69.873024 current_seq = 1610 count = 668 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.862198/1609, current 69.873291/1610: elapsed=11094.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.873291 last_received_ts = 69.873024 last_seq = 1610 current_ts = 69.884384 current_received_ts = 69.884087 current_seq = 1611 count = 669 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.873291/1610, current 69.884384/1611: elapsed=11095.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.884384 last_received_ts = 69.884087 last_seq = 1611 current_ts = 69.895477 current_received_ts = 69.895187 current_seq = 1612 count = 670 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.884384/1611, current 69.895477/1612: elapsed=11089.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.895477 last_received_ts = 69.895187 last_seq = 1612 current_ts = 69.906563 current_received_ts = 69.906281 current_seq = 1613 count = 671 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.895477/1612, current 69.906563/1613: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.906563 last_received_ts = 69.906281 last_seq = 1613 current_ts = 69.917656 current_received_ts = 69.917351 current_seq = 1614 count = 672 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.906563/1613, current 69.917656/1614: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.917656 last_received_ts = 69.917351 last_seq = 1614 current_ts = 69.928749 current_received_ts = 69.928444 current_seq = 1615 count = 673 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.917656/1614, current 69.928749/1615: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.928749 last_received_ts = 69.928444 last_seq = 1615 current_ts = 69.939842 current_received_ts = 69.939545 current_seq = 1616 count = 674 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.928749/1615, current 69.939842/1616: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.939842 last_received_ts = 69.939545 last_seq = 1616 current_ts = 69.950935 current_received_ts = 69.950661 current_seq = 1617 count = 675 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.939842/1616, current 69.950935/1617: elapsed=11092.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: name = flip last_ts = 69.950935 last_received_ts = 69.950661 last_seq = 1617 current_ts = 69.962029 current_received_ts = 69.961708 current_seq = 1618 count = 676 seq_step = 1 (kms_flip:2213) DEBUG: flip ts/seq: last 69.950935/1617, current 69.962029/1618: elapsed=11093.0us expected=11059.4us +- 55.3us, error 0.3% (kms_flip:2213) DEBUG: expected 678, counted 677, encoder type 2 (kms_flip:2213) DEBUG: dropped frames, expected 678, counted 677, encoder type 2 (kms_flip:2213) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674: (kms_flip:2213) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon) (kms_flip:2213) igt_core-INFO: Stack trace: (kms_flip:2213) igt_core-INFO: #0 ../lib/igt_core.c:2055 __igt_fail_assert() (kms_flip:2213) igt_core-INFO: #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0() (kms_flip:2213) igt_core-INFO: #2 ../tests/kms_flip.c:1845 run_test() (kms_flip:2213) igt_core-INFO: #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001() (kms_flip:2213) igt_core-INFO: #4 ../tests/kms_flip.c:2001 main() (kms_flip:2213) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2213) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2213) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-eDP1: FAIL (12.267s)
Dmesg	<6> [61.141747] Console: switching to colour dummy device 80x25 <6> [61.141786] [IGT] kms_flip: executing <7> [61.148896] i915 0000:00:02.0: [drm:i915_gem_open [i915]] <7> [61.150958] i915 0000:00:02.0: [drm:i915_drop_caches_set [i915]] Dropping caches: 0x000001dc [0x000001dc] <7> [61.173135] i915 0000:00:02.0: [drm:i915_gem_open [i915]] <7> [61.178940] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1] <7> [61.178956] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:250:DP-1] <7> [61.183987] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1] disconnected <7> [61.184239] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1] <7> [61.184247] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:262:HDMI-A-1] <7> [61.188977] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1] disconnected <7> [61.189216] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2] <7> [61.189223] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:268:DP-2] <7> [61.189446] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt) <7> [61.189622] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2] disconnected <7> [61.189852] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2] <7> [61.189860] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:277:HDMI-A-2] <7> [61.190114] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port E/TC#2: TC port mode reset (disconnected -> legacy) <7> [61.195049] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2] disconnected <7> [61.195287] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3] <7> [61.195294] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:281:DP-3] <7> [61.195497] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt) <7> [61.195674] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3] disconnected <7> [61.195902] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4] <7> [61.195909] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:290:DP-4] <7> [61.196212] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port G/TC#4: TC port mode reset (disconnected -> tbt-alt) <7> [61.196400] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4] disconnected <7> [61.196714] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:241:eDP-1] <7> [61.196721] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:241:eDP-1] <7> [61.197625] i915 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [i915]] DSC DPCD: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 <7> [61.198322] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000 <7> [61.198431] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] sink rates: 162000, 216000, 243000, 270000, 324000, 378000, 432000, 540000 <7> [61.198538] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000 <7> [61.198669] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc. <7> [61.198676] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] ELD monitor <7> [61.198679] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] ELD size 20, SAD count 0 <7> [61.198695] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] VRR capable: no <7> [61.198802] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps <7> [61.199664] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] PCON ENCODER DSC DPCD: 00 00 00 00 00 00 00 00 00 00 00 00 00 <7> [61.199774] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no <7> [61.201101] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:241:eDP-1] probed modes: <7> [61.201109] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] Probed mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa <7> [61.201124] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1] <7> [61.201132] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:250:DP-1] <7> [61.206125] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1] disconnected <7> [61.206141] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1] <7> [61.206147] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:262:HDMI-A-1] <7> [61.211097] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1] disconnected <7> [61.211111] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2] <7> [61.211118] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:268:DP-2] <7> [61.211323] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2] disconnected <7> [61.211336] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2] <7> [61.211343] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:277:HDMI-A-2] <7> [61.216180] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2] disconnected <7> [61.216194] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3] <7> [61.216200] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:281:DP-3] <7> [61.216401] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3] disconnected <7> [61.216413] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4] <7> [61.216420] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:290:DP-4] <7> [61.216619] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4] disconnected <6> [61.216915] [IGT] kms_flip: starting subtest plain-flip-ts-check <6> [61.218858] [IGT] kms_flip: starting dynamic subtest A-eDP1 <7> [61.219107] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:298] <7> [61.219156] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:301] <7> [61.228069] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [61.228355] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [61.285270] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [61.285469] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [61.304591] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [61.304823] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [61.327439] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [61.327634] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509 <7> [61.354793] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A] <7> [61.354974] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [61.355097] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [61.355214] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [61.355328] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [61.355440] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 7483046/8388608 link 498869/524288, found tu 0, data 0/0 link 0/0) <7> [61.355554] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [61.355666] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [61.355780] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [61.355892] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [61.356023] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [61.356137] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [61.356254] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [61.356366] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [61.356478] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [61.356591] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [61.356702] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [61.356815] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [61.356941] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1878, found 0) <7> [61.357057] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1878, found 0) <7> [61.357170] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [61.357281] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [61.357394] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [61.357506] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [61.357618] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [61.357731] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [61.357844] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [61.357991] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [61.358145] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [61.358268] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [61.358378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1878, found 0) <7> [61.358487] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1878, found 0) <7> [61.358596] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [61.358706] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [61.358818] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [61.358935] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [61.359050] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [61.359162] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 513820, found 0) <7> [61.359273] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 513820, found 0) <7> [61.359384] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in port_clock (expected 540000, found 0) <7> [61.359497] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset <7> [61.359639] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [61.359749] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:82:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [61.359885] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] ddb ( 0 - 4001) -> ( 0 - 0), size 4001 -> 0 <7> [61.360006] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:cursor A] ddb (4001 - 4096) -> ( 0 - 0), size 95 -> 0 <7> [61.360116] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32: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> [61.360222] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] lines 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [61.360330] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] blocks 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [61.360439] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] min_ddb 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [61.360547] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:82:pipe A] data rate 0 num active planes 0 <7> [61.360663] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 0 qgv_peak_bw: 51200 <7> [61.360780] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 51200 <7> [61.360895] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 51200 <7> [61.361030] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 51200 <7> [61.361152] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 0 <7> [61.361271] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing <7> [61.361385] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz <7> [61.361498] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0 <7> [61.361628] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:82:pipe A] enable: no [modeset] <7> [61.361745] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:plane 1A] fb: [NOFB], visible: no <7> [61.361858] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:41:plane 2A] fb: [NOFB], visible: no <7> [61.362000] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:plane 3A] fb: [NOFB], visible: no <7> [61.362142] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:59:plane 4A] fb: [NOFB], visible: no <7> [61.362254] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:68:plane 5A] fb: [NOFB], visible: no <7> [61.362365] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:77:cursor A] fb: [NOFB], visible: no <7> [61.362533] i915 0000:00:02.0: [drm:intel_psr_disable_locked [i915]] Disabling PSR2 <7> [61.363540] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]] <7> [61.569308] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 0 <7> [61.570877] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [61.574719] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power off <7> [61.575101] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x00000089, pins 0x00000010, long 0x00000000 <7> [61.575270] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power off time <7> [61.575571] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - short <7> [61.575818] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [61.627407] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [61.627766] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010 <7> [61.627928] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring short hpd on eDP [ENCODER:240:DDI A/PHY A] <7> [61.628017] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A <7> [61.628227] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long <7> [61.628651] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [61.628802] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A] <7> [61.629082] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A] <7> [61.629396] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B] <7> [61.629884] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A] <7> [61.630279] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B] <7> [61.630515] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C] <7> [61.630722] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D] <7> [61.630925] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1] <7> [61.631126] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A] <7> [61.631328] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B] <7> [61.631557] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C] <7> [61.631766] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D] <7> [61.631968] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2] <7> [61.632143] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3] <7> [61.632290] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A] <7> [61.632467] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B] <7> [61.632661] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C] <7> [61.632870] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D] <7> [61.633013] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4] <7> [61.633160] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A] <7> [61.633298] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B] <7> [61.633448] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C] <7> [61.633571] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D] <7> [61.633685] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1] <7> [61.633832] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no) <7> [61.633974] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: yes -> no (pipe: ) <7> [61.634101] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Post changing CDCLK to 172800 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [61.634389] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=432 <7> [61.634522] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [61.634742] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_A <7> [61.634971] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:82:pipe A] <7> [61.635202] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:134:pipe B] <7> [61.635577] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:186:pipe C] <7> [61.635666] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:238:pipe D] <7> [61.635772] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A] <7> [61.635805] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:241:eDP-1] <7> [61.635893] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:241:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [61.636081] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:240:DDI A/PHY A][CRTC:82:pipe A] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 max link_bpp 30.0000 <7> [61.636264] i915 0000:00:02.0: [drm:intel_dp_compute_link_config [i915]] DP lane count 4 clock 540000 bpp input 30 compressed 0.0000 link rate required 1926825 available 2160000 <7> [61.636446] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [61.636592] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:240:DDI A/PHY A] [CRTC:82:pipe A] <7> [61.636715] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [61.636831] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [61.636949] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [61.637064] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [61.637175] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7483046/8388608 link 498869/524288) <7> [61.637288] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [61.637416] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [61.637555] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [61.637666] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [61.637776] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [61.637886] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [61.637998] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [61.638108] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [61.638221] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [61.638332] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [61.638468] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [61.638596] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [61.638706] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1878) <7> [61.638817] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1878) <7> [61.638926] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [61.639035] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [61.639145] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [61.639255] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [61.639366] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [61.639502] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [61.639624] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [61.639733] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [61.639841] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [61.639950] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [61.640059] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1878) <7> [61.640169] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1878) <7> [61.640280] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [61.640391] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [61.640522] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [61.640645] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [61.640755] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [61.640865] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 513820) <7> [61.640973] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 513820) <7> [61.641081] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in port_clock (expected 0, found 540000) <7> [61.641190] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset <7> [61.641444] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [61.641721] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:82:pipe A] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x1 <7> [61.642027] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] ddb ( 0 - 0) -> ( 0 - 4001), size 0 -> 4001 <7> [61.642297] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:cursor A] ddb ( 0 - 0) -> (4001 - 4096), size 0 -> 95 <7> [61.642540] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32: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> [61.642743] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0 <7> [61.642941] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87 <7> [61.643136] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88 <7> [61.643336] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:82:pipe A] data rate 2055280 num active planes 1 <7> [61.643589] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200 <7> [61.643770] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [61.643890] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [61.644011] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200 <7> [61.644131] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159 <7> [61.644249] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:32:plane 1A] min cdclk (256910 kHz) > [CRTC:82:pipe A] min cdclk (0 kHz) <7> [61.644369] i915 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [i915]] new bandwidth min cdclk (40143 kHz) > old min cdclk (0 kHz) <7> [61.644510] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing <7> [61.644628] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 307200 kHz, actual 307200 kHz <7> [61.644745] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0 <7> [61.644877] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:82:pipe A] enable: yes [modeset] <7> [61.645000] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [61.645120] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 30, dithering: 0 <7> [61.645238] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [61.645353] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [61.645488] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [61.645609] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [61.645726] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m_n: lanes: 4; data_m: 7483046, data_n: 8388608, link_m: 498869, link_n: 524288, tu: 64 <7> [61.645843] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [61.645958] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled <7> [61.646075] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled <7> [61.646193] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [61.646309] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum HBlank: 0 <7> [61.646429] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [61.646573] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] DP SDP: VSC, revision 4, length 14 <7> [61.646695] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB <7> [61.646815] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB <7> [61.646932] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0 <7> [61.647049] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range <7> [61.647168] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined <7> [61.647286] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1 <7> [61.647404] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0 <7> [61.647546] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0 <7> [61.647668] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0 <7> [61.647786] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa <7> [61.647905] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa <7> [61.648025] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1878 vs=1803-1809 vt=1878, flags=0xa <7> [61.648144] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x40 0xa <7> [61.648262] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1878 vs=1803-1809 vt=1878, flags=0xa <7> [61.648382] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 540000, pipe src: 2880x1800+0+0, pixel rate 513820 <7> [61.648517] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 48, ips linetime: 0 <7> [61.648637] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [61.648756] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [61.648875] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [61.648992] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x83d60, dpll_md: 0xf42110, fp0: 0xf8, fp1: 0x1000000 <7> [61.649111] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [61.649229] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [61.649345] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [61.649469] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [61.649591] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [61.649709] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [61.649826] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [61.649944] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [61.650062] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [61.650179] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [61.650296] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [61.650418] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [61.650553] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:plane 1A] fb: [FB:298] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes <7> [61.650673] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [61.650790] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [61.650910] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:41:plane 2A] fb: [NOFB], visible: no <7> [61.651028] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:plane 3A] fb: [NOFB], visible: no <7> [61.651146] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:59:plane 4A] fb: [NOFB], visible: no <7> [61.651263] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:68:plane 5A] fb: [NOFB], visible: no <7> [61.651379] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:77:cursor A] fb: [NOFB], visible: no <7> [61.653514] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off <7> [61.654018] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6 <7> [61.654437] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02 <7> [61.654954] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off <7> [61.655089] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00 <7> [61.655513] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_A <7> [61.655714] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 307200 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [61.655876] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=768 <7> [61.655998] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A] <7> [61.656114] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B] <7> [61.656231] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A] <7> [61.656349] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B] <7> [61.656464] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C] <7> [61.656603] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D] <7> [61.656720] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1] <7> [61.656835] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A] <7> [61.656948] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B] <7> [61.657093] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C] <7> [61.657224] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D] <7> [61.657340] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2] <7> [61.657455] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3] <7> [61.657594] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A] <7> [61.657709] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B] <7> [61.657821] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C] <7> [61.657933] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D] <7> [61.658045] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4] <7> [61.658156] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A] <7> [61.658266] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B] <7> [61.658375] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C] <7> [61.658490] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D] <7> [61.658620] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0xf <7> [61.658837] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: no -> yes (pipe: ) <7> [61.658960] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 4 (mbus joined: yes) <7> [61.659110] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A <7> [61.660490] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power on <7> [61.660653] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power cycle (468 ms remaining) <7> [62.140117] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x00000000 PP_CONTROL: 0x00000060 <7> [62.140548] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [62.141155] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power on <7> [62.141682] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [62.172887] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010 <7> [62.173391] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long <7> [62.173822] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [62.174253] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A] <7> [62.252868] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port G/TC#4: TC port mode reset (tbt-alt -> disconnected) <7> [62.252963] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) <7> [62.253114] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port E/TC#2: TC port mode reset (legacy -> disconnected) <7> [62.253217] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) <7> [62.343579] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete <7> [62.345992] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD on <7> [62.346520] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [62.350759] i915 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c4 41 00 00 01 c0 02 00 00 00 00 0b 80 <7> [62.351705] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [62.352577] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 07 <7> [62.353566] i915 0000:00:02.0: [drm:intel_dp_set_signal_levels [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [62.354282] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [62.355421] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Clock recovery OK <7> [62.355529] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS3 <7> [62.357082] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [62.357187] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Link Training passed at link rate = 540000, lane count = 4 <7> [62.357782] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A <7> [62.358021] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]] <7> [62.358130] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe A <7> [62.358294] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 13892 <7> [62.369196] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR2 <7> [62.370762] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1] <7> [62.370928] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:82:pipe A] <7> [64.887250] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD off <7> [64.887800] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [70.108994] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off <7> [70.109465] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6 <7> [70.109965] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02 <6> [73.485919] [IGT] kms_flip: finished subtest A-eDP1, FAIL

Created at 2025-03-06 09:19:49