igt@kms_flip@flip-vs-expired-vblank-interruptible@b-dp2 on shard-bmg@xe-pw-167480v1 Test details

Detail	Value
Duration	2.49 seconds
Hostname	shard-bmg-1
Igt-Version	IGT-Version: 2.4-g0e365bfe5 (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-pw-167480v1-debug+ x86_64)
Out	Starting dynamic subtest: B-DP2 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2106 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-DP2: FAIL (2.487s)
Err	Starting dynamic subtest: B-DP2 [472.070725] (kms_flip:13343) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [472.070861] (kms_flip:13343) CRITICAL: Failed assertion: end - start < 500 [472.070958] (kms_flip:13343) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-DP2 failed. ** DEBUG [470.049010] (kms_flip:13343) DEBUG: Vblank took 25us [470.065647] (kms_flip:13343) DEBUG: name = flip last_ts = 471.438202 last_received_ts = 471.437775 last_seq = 16486 current_ts = 471.454895 current_received_ts = 471.454437 current_seq = 16487 count = 11 seq_step = 1 [470.065677] (kms_flip:13343) DEBUG: Vblank took 26us [470.082278] (kms_flip:13343) DEBUG: name = flip last_ts = 471.454895 last_received_ts = 471.454437 last_seq = 16487 current_ts = 471.471558 current_received_ts = 471.471069 current_seq = 16488 count = 12 seq_step = 1 [470.082308] (kms_flip:13343) DEBUG: Vblank took 26us [470.098982] (kms_flip:13343) DEBUG: name = flip last_ts = 471.471558 last_received_ts = 471.471069 last_seq = 16488 current_ts = 471.488220 current_received_ts = 471.487762 current_seq = 16489 count = 13 seq_step = 1 [470.099011] (kms_flip:13343) DEBUG: Vblank took 25us [470.115724] (kms_flip:13343) DEBUG: name = flip last_ts = 471.488220 last_received_ts = 471.487762 last_seq = 16489 current_ts = 471.504883 current_received_ts = 471.504517 current_seq = 16490 count = 14 seq_step = 1 [470.115753] (kms_flip:13343) DEBUG: Vblank took 24us [470.132318] (kms_flip:13343) DEBUG: name = flip last_ts = 471.504883 last_received_ts = 471.504517 last_seq = 16490 current_ts = 471.521545 current_received_ts = 471.521118 current_seq = 16491 count = 15 seq_step = 1 [470.132349] (kms_flip:13343) DEBUG: Vblank took 25us [470.148945] (kms_flip:13343) DEBUG: name = flip last_ts = 471.521545 last_received_ts = 471.521118 last_seq = 16491 current_ts = 471.538208 current_received_ts = 471.537750 current_seq = 16492 count = 16 seq_step = 1 [470.148975] (kms_flip:13343) DEBUG: Vblank took 26us [470.165652] (kms_flip:13343) DEBUG: name = flip last_ts = 471.538208 last_received_ts = 471.537750 last_seq = 16492 current_ts = 471.554901 current_received_ts = 471.554443 current_seq = 16493 count = 17 seq_step = 1 [470.165681] (kms_flip:13343) DEBUG: Vblank took 26us [470.182320] (kms_flip:13343) DEBUG: name = flip last_ts = 471.554901 last_received_ts = 471.554443 last_seq = 16493 current_ts = 471.571564 current_received_ts = 471.571106 current_seq = 16494 count = 18 seq_step = 1 [470.182350] (kms_flip:13343) DEBUG: Vblank took 26us [470.199060] (kms_flip:13343) DEBUG: name = flip last_ts = 471.571564 last_received_ts = 471.571106 last_seq = 16494 current_ts = 471.588226 current_received_ts = 471.587860 current_seq = 16495 count = 19 seq_step = 1 [470.199089] (kms_flip:13343) DEBUG: Vblank took 25us [470.215654] (kms_flip:13343) DEBUG: name = flip last_ts = 471.588226 last_received_ts = 471.587860 last_seq = 16495 current_ts = 471.604889 current_received_ts = 471.604462 current_seq = 16496 count = 20 seq_step = 1 [470.215684] (kms_flip:13343) DEBUG: Vblank took 26us [470.232321] (kms_flip:13343) DEBUG: name = flip last_ts = 471.604889 last_received_ts = 471.604462 last_seq = 16496 current_ts = 471.621552 current_received_ts = 471.621124 current_seq = 16497 count = 21 seq_step = 1 [470.232351] (kms_flip:13343) DEBUG: Vblank took 25us [470.248991] (kms_flip:13343) DEBUG: name = flip last_ts = 471.621552 last_received_ts = 471.621124 last_seq = 16497 current_ts = 471.638214 current_received_ts = 471.637787 current_seq = 16498 count = 22 seq_step = 1 [470.249021] (kms_flip:13343) DEBUG: Vblank took 26us [470.265656] (kms_flip:13343) DEBUG: name = flip last_ts = 471.638214 last_received_ts = 471.637787 last_seq = 16498 current_ts = 471.654907 current_received_ts = 471.654449 current_seq = 16499 count = 23 seq_step = 1 [470.265687] (kms_flip:13343) DEBUG: Vblank took 26us [470.282403] (kms_flip:13343) DEBUG: name = flip last_ts = 471.654907 last_received_ts = 471.654449 last_seq = 16499 current_ts = 471.671570 current_received_ts = 471.671204 current_seq = 16500 count = 24 seq_step = 1 [470.282433] (kms_flip:13343) DEBUG: Vblank took 26us [470.299064] (kms_flip:13343) DEBUG: name = flip last_ts = 471.671570 last_received_ts = 471.671204 last_seq = 16500 current_ts = 471.688232 current_received_ts = 471.687866 current_seq = 16501 count = 25 seq_step = 1 [470.299093] (kms_flip:13343) DEBUG: Vblank took 25us [470.315665] (kms_flip:13343) DEBUG: name = flip last_ts = 471.688232 last_received_ts = 471.687866 last_seq = 16501 current_ts = 471.704895 current_received_ts = 471.704468 current_seq = 16502 count = 26 seq_step = 1 [470.315696] (kms_flip:13343) DEBUG: Vblank took 25us [470.332329] (kms_flip:13343) DEBUG: name = flip last_ts = 471.704895 last_received_ts = 471.704468 last_seq = 16502 current_ts = 471.721558 current_received_ts = 471.721130 current_seq = 16503 count = 27 seq_step = 1 [470.332357] (kms_flip:13343) DEBUG: Vblank took 25us [470.348995] (kms_flip:13343) DEBUG: name = flip last_ts = 471.721558 last_received_ts = 471.721130 last_seq = 16503 current_ts = 471.738220 current_received_ts = 471.737793 current_seq = 16504 count = 28 seq_step = 1 [470.349024] (kms_flip:13343) DEBUG: Vblank took 25us [470.365522] (kms_flip:13343) DEBUG: name = flip last_ts = 471.738220 last_received_ts = 471.737793 last_seq = 16504 current_ts = 471.754913 current_received_ts = 471.754333 current_seq = 16505 count = 29 seq_step = 1 [470.365551] (kms_flip:13343) DEBUG: Vblank took 25us [470.382291] (kms_flip:13343) DEBUG: name = flip last_ts = 471.754913 last_received_ts = 471.754333 last_seq = 16505 current_ts = 471.771576 current_received_ts = 471.771088 current_seq = 16506 count = 30 seq_step = 1 [470.382321] (kms_flip:13343) DEBUG: Vblank took 25us [470.399071] (kms_flip:13343) DEBUG: name = flip last_ts = 471.771576 last_received_ts = 471.771088 last_seq = 16506 current_ts = 471.788239 current_received_ts = 471.787872 current_seq = 16507 count = 31 seq_step = 1 [470.399102] (kms_flip:13343) DEBUG: Vblank took 26us [470.415665] (kms_flip:13343) DEBUG: name = flip last_ts = 471.788239 last_received_ts = 471.787872 last_seq = 16507 current_ts = 471.804901 current_received_ts = 471.804474 current_seq = 16508 count = 32 seq_step = 1 [470.415694] (kms_flip:13343) DEBUG: Vblank took 26us [470.432406] (kms_flip:13343) DEBUG: name = flip last_ts = 471.804901 last_received_ts = 471.804474 last_seq = 16508 current_ts = 471.821564 current_received_ts = 471.821198 current_seq = 16509 count = 33 seq_step = 1 [470.432435] (kms_flip:13343) DEBUG: Vblank took 25us [470.449073] (kms_flip:13343) DEBUG: name = flip last_ts = 471.821564 last_received_ts = 471.821198 last_seq = 16509 current_ts = 471.838226 current_received_ts = 471.837860 current_seq = 16510 count = 34 seq_step = 1 [470.449103] (kms_flip:13343) DEBUG: Vblank took 26us [470.465740] (kms_flip:13343) DEBUG: name = flip last_ts = 471.838226 last_received_ts = 471.837860 last_seq = 16510 current_ts = 471.854919 current_received_ts = 471.854553 current_seq = 16511 count = 35 seq_step = 1 [470.465769] (kms_flip:13343) DEBUG: Vblank took 25us [470.482410] (kms_flip:13343) DEBUG: name = flip last_ts = 471.854919 last_received_ts = 471.854553 last_seq = 16511 current_ts = 471.871582 current_received_ts = 471.871216 current_seq = 16512 count = 36 seq_step = 1 [470.482439] (kms_flip:13343) DEBUG: Vblank took 25us [470.499080] (kms_flip:13343) DEBUG: name = flip last_ts = 471.871582 last_received_ts = 471.871216 last_seq = 16512 current_ts = 471.888245 current_received_ts = 471.887878 current_seq = 16513 count = 37 seq_step = 1 [470.499110] (kms_flip:13343) DEBUG: Vblank took 26us [470.515744] (kms_flip:13343) DEBUG: name = flip last_ts = 471.888245 last_received_ts = 471.887878 last_seq = 16513 current_ts = 471.904907 current_received_ts = 471.904541 current_seq = 16514 count = 38 seq_step = 1 [470.515774] (kms_flip:13343) DEBUG: Vblank took 25us [470.532413] (kms_flip:13343) DEBUG: name = flip last_ts = 471.904907 last_received_ts = 471.904541 last_seq = 16514 current_ts = 471.921570 current_received_ts = 471.921204 current_seq = 16515 count = 39 seq_step = 1 [470.532442] (kms_flip:13343) DEBUG: Vblank took 26us [470.549082] (kms_flip:13343) DEBUG: name = flip last_ts = 471.921570 last_received_ts = 471.921204 last_seq = 16515 current_ts = 471.938263 current_received_ts = 471.937897 current_seq = 16516 count = 40 seq_step = 1 [470.549114] (kms_flip:13343) DEBUG: Vblank took 26us [470.565750] (kms_flip:13343) DEBUG: name = flip last_ts = 471.938263 last_received_ts = 471.937897 last_seq = 16516 current_ts = 471.954926 current_received_ts = 471.954559 current_seq = 16517 count = 41 seq_step = 1 [470.565779] (kms_flip:13343) DEBUG: Vblank took 26us [470.582413] (kms_flip:13343) DEBUG: name = flip last_ts = 471.954926 last_received_ts = 471.954559 last_seq = 16517 current_ts = 471.971588 current_received_ts = 471.971222 current_seq = 16518 count = 42 seq_step = 1 [470.582442] (kms_flip:13343) DEBUG: Vblank took 25us [470.599007] (kms_flip:13343) DEBUG: name = flip last_ts = 471.971588 last_received_ts = 471.971222 last_seq = 16518 current_ts = 471.988251 current_received_ts = 471.987793 current_seq = 16519 count = 43 seq_step = 1 [470.599036] (kms_flip:13343) DEBUG: Vblank took 26us [470.615686] (kms_flip:13343) DEBUG: name = flip last_ts = 471.988251 last_received_ts = 471.987793 last_seq = 16519 current_ts = 472.004913 current_received_ts = 472.004486 current_seq = 16520 count = 44 seq_step = 1 [470.615717] (kms_flip:13343) DEBUG: Vblank took 26us [470.632347] (kms_flip:13343) DEBUG: name = flip last_ts = 472.004913 last_received_ts = 472.004486 last_seq = 16520 current_ts = 472.021576 current_received_ts = 472.021149 current_seq = 16521 count = 45 seq_step = 1 [470.632377] (kms_flip:13343) DEBUG: Vblank took 26us [470.649012] (kms_flip:13343) DEBUG: name = flip last_ts = 472.021576 last_received_ts = 472.021149 last_seq = 16521 current_ts = 472.038269 current_received_ts = 472.037811 current_seq = 16522 count = 46 seq_step = 1 [470.649042] (kms_flip:13343) DEBUG: Vblank took 26us [470.665749] (kms_flip:13343) DEBUG: name = flip last_ts = 472.038269 last_received_ts = 472.037811 last_seq = 16522 current_ts = 472.054932 current_received_ts = 472.054535 current_seq = 16523 count = 47 seq_step = 1 [470.665779] (kms_flip:13343) DEBUG: Vblank took 26us [470.682347] (kms_flip:13343) DEBUG: name = flip last_ts = 472.054932 last_received_ts = 472.054535 last_seq = 16523 current_ts = 472.071594 current_received_ts = 472.071136 current_seq = 16524 count = 48 seq_step = 1 [470.682378] (kms_flip:13343) DEBUG: Vblank took 25us [470.699088] (kms_flip:13343) DEBUG: name = flip last_ts = 472.071594 last_received_ts = 472.071136 last_seq = 16524 current_ts = 472.088257 current_received_ts = 472.087891 current_seq = 16525 count = 49 seq_step = 1 [470.699118] (kms_flip:13343) DEBUG: Vblank took 25us [470.715682] (kms_flip:13343) DEBUG: name = flip last_ts = 472.088257 last_received_ts = 472.087891 last_seq = 16525 current_ts = 472.104919 current_received_ts = 472.104492 current_seq = 16526 count = 50 seq_step = 1 [470.715713] (kms_flip:13343) DEBUG: Vblank took 26us [470.732349] (kms_flip:13343) DEBUG: name = flip last_ts = 472.104919 last_received_ts = 472.104492 last_seq = 16526 current_ts = 472.121582 current_received_ts = 472.121155 current_seq = 16527 count = 51 seq_step = 1 [470.732378] (kms_flip:13343) DEBUG: Vblank took 25us [470.749015] (kms_flip:13343) DEBUG: name = flip last_ts = 472.121582 last_received_ts = 472.121155 last_seq = 16527 current_ts = 472.138275 current_received_ts = 472.137817 current_seq = 16528 count = 52 seq_step = 1 [470.749045] (kms_flip:13343) DEBUG: Vblank took 24us [470.765683] (kms_flip:13343) DEBUG: name = flip last_ts = 472.138275 last_received_ts = 472.137817 last_seq = 16528 current_ts = 472.154938 current_received_ts = 472.154480 current_seq = 16529 count = 53 seq_step = 1 [470.765713] (kms_flip:13343) DEBUG: Vblank took 26us [470.782352] (kms_flip:13343) DEBUG: name = flip last_ts = 472.154938 last_received_ts = 472.154480 last_seq = 16529 current_ts = 472.171600 current_received_ts = 472.171143 current_seq = 16530 count = 54 seq_step = 1 [470.782382] (kms_flip:13343) DEBUG: Vblank took 25us [470.799094] (kms_flip:13343) DEBUG: name = flip last_ts = 472.171600 last_received_ts = 472.171143 last_seq = 16530 current_ts = 472.188263 current_received_ts = 472.187897 current_seq = 16531 count = 55 seq_step = 1 [470.799123] (kms_flip:13343) DEBUG: Vblank took 25us [470.815685] (kms_flip:13343) DEBUG: name = flip last_ts = 472.188263 last_received_ts = 472.187897 last_seq = 16531 current_ts = 472.204926 current_received_ts = 472.204498 current_seq = 16532 count = 56 seq_step = 1 [470.815715] (kms_flip:13343) DEBUG: Vblank took 26us [470.832354] (kms_flip:13343) DEBUG: name = flip last_ts = 472.204926 last_received_ts = 472.204498 last_seq = 16532 current_ts = 472.221588 current_received_ts = 472.221161 current_seq = 16533 count = 57 seq_step = 1 [470.832384] (kms_flip:13343) DEBUG: Vblank took 25us [470.849021] (kms_flip:13343) DEBUG: name = flip last_ts = 472.221588 last_received_ts = 472.221161 last_seq = 16533 current_ts = 472.238281 current_received_ts = 472.237823 current_seq = 16534 count = 58 seq_step = 1 [470.849052] (kms_flip:13343) DEBUG: Vblank took 25us [470.865691] (kms_flip:13343) DEBUG: name = flip last_ts = 472.238281 last_received_ts = 472.237823 last_seq = 16534 current_ts = 472.254944 current_received_ts = 472.254486 current_seq = 16535 count = 59 seq_step = 1 [470.865722] (kms_flip:13343) DEBUG: Vblank took 25us [470.882358] (kms_flip:13343) DEBUG: name = flip last_ts = 472.254944 last_received_ts = 472.254486 last_seq = 16535 current_ts = 472.271606 current_received_ts = 472.271149 current_seq = 16536 count = 60 seq_step = 1 [470.882388] (kms_flip:13343) DEBUG: Vblank took 26us [470.899023] (kms_flip:13343) DEBUG: name = flip last_ts = 472.271606 last_received_ts = 472.271149 last_seq = 16536 current_ts = 472.288269 current_received_ts = 472.287842 current_seq = 16537 count = 61 seq_step = 1 [470.899052] (kms_flip:13343) DEBUG: Vblank took 25us [470.915693] (kms_flip:13343) DEBUG: name = flip last_ts = 472.288269 last_received_ts = 472.287842 last_seq = 16537 current_ts = 472.304932 current_received_ts = 472.304504 current_seq = 16538 count = 62 seq_step = 1 [470.915723] (kms_flip:13343) DEBUG: Vblank took 26us [470.932360] (kms_flip:13343) DEBUG: name = flip last_ts = 472.304932 last_received_ts = 472.304504 last_seq = 16538 current_ts = 472.321594 current_received_ts = 472.321167 current_seq = 16539 count = 63 seq_step = 1 [470.932390] (kms_flip:13343) DEBUG: Vblank took 26us [470.949026] (kms_flip:13343) DEBUG: name = flip last_ts = 472.321594 last_received_ts = 472.321167 last_seq = 16539 current_ts = 472.338287 current_received_ts = 472.337830 current_seq = 16540 count = 64 seq_step = 1 [470.949055] (kms_flip:13343) DEBUG: Vblank took 25us [470.965694] (kms_flip:13343) DEBUG: name = flip last_ts = 472.338287 last_received_ts = 472.337830 last_seq = 16540 current_ts = 472.354950 current_received_ts = 472.354492 current_seq = 16541 count = 65 seq_step = 1 [470.965723] (kms_flip:13343) DEBUG: Vblank took 25us [470.982363] (kms_flip:13343) DEBUG: name = flip last_ts = 472.354950 last_received_ts = 472.354492 last_seq = 16541 current_ts = 472.371613 current_received_ts = 472.371155 current_seq = 16542 count = 66 seq_step = 1 [470.982393] (kms_flip:13343) DEBUG: Vblank took 26us [470.999104] (kms_flip:13343) DEBUG: name = flip last_ts = 472.371613 last_received_ts = 472.371155 last_seq = 16542 current_ts = 472.388275 current_received_ts = 472.387909 current_seq = 16543 count = 67 seq_step = 1 [470.999133] (kms_flip:13343) DEBUG: Vblank took 25us [471.015698] (kms_flip:13343) DEBUG: name = flip last_ts = 472.388275 last_received_ts = 472.387909 last_seq = 16543 current_ts = 472.404938 current_received_ts = 472.404510 current_seq = 16544 count = 68 seq_step = 1 [471.015728] (kms_flip:13343) DEBUG: Vblank took 25us [471.032366] (kms_flip:13343) DEBUG: name = flip last_ts = 472.404938 last_received_ts = 472.404510 last_seq = 16544 current_ts = 472.421600 current_received_ts = 472.421173 current_seq = 16545 count = 69 seq_step = 1 [471.032396] (kms_flip:13343) DEBUG: Vblank took 26us [471.049032] (kms_flip:13343) DEBUG: name = flip last_ts = 472.421600 last_received_ts = 472.421173 last_seq = 16545 current_ts = 472.438293 current_received_ts = 472.437836 current_seq = 16546 count = 70 seq_step = 1 [471.049062] (kms_flip:13343) DEBUG: Vblank took 25us [471.065698] (kms_flip:13343) DEBUG: name = flip last_ts = 472.438293 last_received_ts = 472.437836 last_seq = 16546 current_ts = 472.454956 current_received_ts = 472.454498 current_seq = 16547 count = 71 seq_step = 1 [471.065727] (kms_flip:13343) DEBUG: Vblank took 25us [471.082368] (kms_flip:13343) DEBUG: name = flip last_ts = 472.454956 last_received_ts = 472.454498 last_seq = 16547 current_ts = 472.471619 current_received_ts = 472.471191 current_seq = 16548 count = 72 seq_step = 1 [471.082398] (kms_flip:13343) DEBUG: Vblank took 26us [471.099108] (kms_flip:13343) DEBUG: name = flip last_ts = 472.471619 last_received_ts = 472.471191 last_seq = 16548 current_ts = 472.488281 current_received_ts = 472.487915 current_seq = 16549 count = 73 seq_step = 1 [471.099137] (kms_flip:13343) DEBUG: Vblank took 24us [471.115703] (kms_flip:13343) DEBUG: name = flip last_ts = 472.488281 last_received_ts = 472.487915 last_seq = 16549 current_ts = 472.504944 current_received_ts = 472.504517 current_seq = 16550 count = 74 seq_step = 1 [471.115732] (kms_flip:13343) DEBUG: Vblank took 25us [471.132382] (kms_flip:13343) DEBUG: name = flip last_ts = 472.504944 last_received_ts = 472.504517 last_seq = 16550 current_ts = 472.521637 current_received_ts = 472.521179 current_seq = 16551 count = 75 seq_step = 1 [471.132420] (kms_flip:13343) DEBUG: Vblank took 31us [471.149114] (kms_flip:13343) DEBUG: name = flip last_ts = 472.521637 last_received_ts = 472.521179 last_seq = 16551 current_ts = 472.538300 current_received_ts = 472.537933 current_seq = 16552 count = 76 seq_step = 1 [471.149145] (kms_flip:13343) DEBUG: Vblank took 25us [471.165707] (kms_flip:13343) DEBUG: name = flip last_ts = 472.538300 last_received_ts = 472.537933 last_seq = 16552 current_ts = 472.554962 current_received_ts = 472.554504 current_seq = 16553 count = 77 seq_step = 1 [471.165738] (kms_flip:13343) DEBUG: Vblank took 26us [471.182395] (kms_flip:13343) DEBUG: name = flip last_ts = 472.554962 last_received_ts = 472.554504 last_seq = 16553 current_ts = 472.571625 current_received_ts = 472.571198 current_seq = 16554 count = 78 seq_step = 1 [471.182425] (kms_flip:13343) DEBUG: Vblank took 24us [471.199062] (kms_flip:13343) DEBUG: name = flip last_ts = 472.571625 last_received_ts = 472.571198 last_seq = 16554 current_ts = 472.588287 current_received_ts = 472.587860 current_seq = 16555 count = 79 seq_step = 1 [471.199092] (kms_flip:13343) DEBUG: Vblank took 25us [471.215710] (kms_flip:13343) DEBUG: name = flip last_ts = 472.588287 last_received_ts = 472.587860 last_seq = 16555 current_ts = 472.604950 current_received_ts = 472.604523 current_seq = 16556 count = 80 seq_step = 1 [471.215761] (kms_flip:13343) DEBUG: Vblank took 46us [471.232378] (kms_flip:13343) DEBUG: name = flip last_ts = 472.604950 last_received_ts = 472.604523 last_seq = 16556 current_ts = 472.621643 current_received_ts = 472.621185 current_seq = 16557 count = 81 seq_step = 1 [471.232427] (kms_flip:13343) DEBUG: Vblank took 44us [471.249044] (kms_flip:13343) DEBUG: name = flip last_ts = 472.621643 last_received_ts = 472.621185 last_seq = 16557 current_ts = 472.638306 current_received_ts = 472.637848 current_seq = 16558 count = 82 seq_step = 1 [471.249073] (kms_flip:13343) DEBUG: Vblank took 25us [471.265712] (kms_flip:13343) DEBUG: name = flip last_ts = 472.638306 last_received_ts = 472.637848 last_seq = 16558 current_ts = 472.654968 current_received_ts = 472.654510 current_seq = 16559 count = 83 seq_step = 1 [471.265742] (kms_flip:13343) DEBUG: Vblank took 25us [471.282381] (kms_flip:13343) DEBUG: name = flip last_ts = 472.654968 last_received_ts = 472.654510 last_seq = 16559 current_ts = 472.671631 current_received_ts = 472.671204 current_seq = 16560 count = 84 seq_step = 1 [471.282412] (kms_flip:13343) DEBUG: Vblank took 26us [471.299123] (kms_flip:13343) DEBUG: name = flip last_ts = 472.671631 last_received_ts = 472.671204 last_seq = 16560 current_ts = 472.688293 current_received_ts = 472.687927 current_seq = 16561 count = 85 seq_step = 1 [471.299153] (kms_flip:13343) DEBUG: Vblank took 26us [471.315717] (kms_flip:13343) DEBUG: name = flip last_ts = 472.688293 last_received_ts = 472.687927 last_seq = 16561 current_ts = 472.704956 current_received_ts = 472.704529 current_seq = 16562 count = 86 seq_step = 1 [471.315747] (kms_flip:13343) DEBUG: Vblank took 26us [471.332385] (kms_flip:13343) DEBUG: name = flip last_ts = 472.704956 last_received_ts = 472.704529 last_seq = 16562 current_ts = 472.721649 current_received_ts = 472.721191 current_seq = 16563 count = 87 seq_step = 1 [471.332415] (kms_flip:13343) DEBUG: Vblank took 26us [471.349124] (kms_flip:13343) DEBUG: name = flip last_ts = 472.721649 last_received_ts = 472.721191 last_seq = 16563 current_ts = 472.738312 current_received_ts = 472.737946 current_seq = 16564 count = 88 seq_step = 1 [471.349153] (kms_flip:13343) DEBUG: Vblank took 25us [471.365790] (kms_flip:13343) DEBUG: name = flip last_ts = 472.738312 last_received_ts = 472.737946 last_seq = 16564 current_ts = 472.754974 current_received_ts = 472.754608 current_seq = 16565 count = 89 seq_step = 1 [471.365820] (kms_flip:13343) DEBUG: Vblank took 25us [471.382459] (kms_flip:13343) DEBUG: name = flip last_ts = 472.754974 last_received_ts = 472.754608 last_seq = 16565 current_ts = 472.771637 current_received_ts = 472.771271 current_seq = 16566 count = 90 seq_step = 1 [471.382489] (kms_flip:13343) DEBUG: Vblank took 25us [471.399127] (kms_flip:13343) DEBUG: name = flip last_ts = 472.771637 last_received_ts = 472.771271 last_seq = 16566 current_ts = 472.788300 current_received_ts = 472.787933 current_seq = 16567 count = 91 seq_step = 1 [471.399157] (kms_flip:13343) DEBUG: Vblank took 25us [471.415794] (kms_flip:13343) DEBUG: name = flip last_ts = 472.788300 last_received_ts = 472.787933 last_seq = 16567 current_ts = 472.804962 current_received_ts = 472.804596 current_seq = 16568 count = 92 seq_step = 1 [471.415822] (kms_flip:13343) DEBUG: Vblank took 25us [471.432461] (kms_flip:13343) DEBUG: name = flip last_ts = 472.804962 last_received_ts = 472.804596 last_seq = 16568 current_ts = 472.821655 current_received_ts = 472.821289 current_seq = 16569 count = 93 seq_step = 1 [471.432491] (kms_flip:13343) DEBUG: Vblank took 26us [471.449128] (kms_flip:13343) DEBUG: name = flip last_ts = 472.821655 last_received_ts = 472.821289 last_seq = 16569 current_ts = 472.838318 current_received_ts = 472.837952 current_seq = 16570 count = 94 seq_step = 1 [471.449157] (kms_flip:13343) DEBUG: Vblank took 24us [471.465795] (kms_flip:13343) DEBUG: name = flip last_ts = 472.838318 last_received_ts = 472.837952 last_seq = 16570 current_ts = 472.854980 current_received_ts = 472.854614 current_seq = 16571 count = 95 seq_step = 1 [471.465825] (kms_flip:13343) DEBUG: Vblank took 25us [471.482462] (kms_flip:13343) DEBUG: name = flip last_ts = 472.854980 last_received_ts = 472.854614 last_seq = 16571 current_ts = 472.871674 current_received_ts = 472.871277 current_seq = 16572 count = 96 seq_step = 1 [471.482492] (kms_flip:13343) DEBUG: Vblank took 25us [471.499129] (kms_flip:13343) DEBUG: name = flip last_ts = 472.871674 last_received_ts = 472.871277 last_seq = 16572 current_ts = 472.888336 current_received_ts = 472.887939 current_seq = 16573 count = 97 seq_step = 1 [471.499169] (kms_flip:13343) DEBUG: Vblank took 24us [471.515726] (kms_flip:13343) DEBUG: name = flip last_ts = 472.888336 last_received_ts = 472.887939 last_seq = 16573 current_ts = 472.904968 current_received_ts = 472.904541 current_seq = 16574 count = 98 seq_step = 1 [471.515759] (kms_flip:13343) DEBUG: Vblank took 24us [471.532395] (kms_flip:13343) DEBUG: name = flip last_ts = 472.904968 last_received_ts = 472.904541 last_seq = 16574 current_ts = 472.921661 current_received_ts = 472.921204 current_seq = 16575 count = 99 seq_step = 1 [471.532425] (kms_flip:13343) DEBUG: Vblank took 25us [471.549136] (kms_flip:13343) DEBUG: name = flip last_ts = 472.921661 last_received_ts = 472.921204 last_seq = 16575 current_ts = 472.938324 current_received_ts = 472.937958 current_seq = 16576 count = 100 seq_step = 1 [471.549165] (kms_flip:13343) DEBUG: Vblank took 26us [471.565728] (kms_flip:13343) DEBUG: name = flip last_ts = 472.938324 last_received_ts = 472.937958 last_seq = 16576 current_ts = 472.954987 current_received_ts = 472.954559 current_seq = 16577 count = 101 seq_step = 1 [471.565758] (kms_flip:13343) DEBUG: Vblank took 24us [471.582397] (kms_flip:13343) DEBUG: name = flip last_ts = 472.954987 last_received_ts = 472.954559 last_seq = 16577 current_ts = 472.971649 current_received_ts = 472.971222 current_seq = 16578 count = 102 seq_step = 1 [471.582427] (kms_flip:13343) DEBUG: Vblank took 25us [471.599137] (kms_flip:13343) DEBUG: name = flip last_ts = 472.971649 last_received_ts = 472.971222 last_seq = 16578 current_ts = 472.988312 current_received_ts = 472.987946 current_seq = 16579 count = 103 seq_step = 1 [471.599166] (kms_flip:13343) DEBUG: Vblank took 24us [471.615733] (kms_flip:13343) DEBUG: name = flip last_ts = 472.988312 last_received_ts = 472.987946 last_seq = 16579 current_ts = 473.005005 current_received_ts = 473.004547 current_seq = 16580 count = 104 seq_step = 1 [471.615762] (kms_flip:13343) DEBUG: Vblank took 25us [471.632418] (kms_flip:13343) DEBUG: name = flip last_ts = 473.005005 last_received_ts = 473.004547 last_seq = 16580 current_ts = 473.021667 current_received_ts = 473.021240 current_seq = 16581 count = 105 seq_step = 1 [471.632452] (kms_flip:13343) DEBUG: Vblank took 28us [471.649148] (kms_flip:13343) DEBUG: name = flip last_ts = 473.021667 last_received_ts = 473.021240 last_seq = 16581 current_ts = 473.038330 current_received_ts = 473.037964 current_seq = 16582 count = 106 seq_step = 1 [471.649226] (kms_flip:13343) DEBUG: Vblank took 72us [471.665810] (kms_flip:13343) DEBUG: name = flip last_ts = 473.038330 last_received_ts = 473.037964 last_seq = 16582 current_ts = 473.054993 current_received_ts = 473.054626 current_seq = 16583 count = 107 seq_step = 1 [471.665840] (kms_flip:13343) DEBUG: Vblank took 26us [471.682480] (kms_flip:13343) DEBUG: name = flip last_ts = 473.054993 last_received_ts = 473.054626 last_seq = 16583 current_ts = 473.071655 current_received_ts = 473.071289 current_seq = 16584 count = 108 seq_step = 1 [471.682510] (kms_flip:13343) DEBUG: Vblank took 25us [471.699147] (kms_flip:13343) DEBUG: name = flip last_ts = 473.071655 last_received_ts = 473.071289 last_seq = 16584 current_ts = 473.088318 current_received_ts = 473.087952 current_seq = 16585 count = 109 seq_step = 1 [471.699192] (kms_flip:13343) DEBUG: Vblank took 41us [471.715810] (kms_flip:13343) DEBUG: name = flip last_ts = 473.088318 last_received_ts = 473.087952 last_seq = 16585 current_ts = 473.105011 current_received_ts = 473.104614 current_seq = 16586 count = 110 seq_step = 1 [471.715840] (kms_flip:13343) DEBUG: Vblank took 25us [471.732480] (kms_flip:13343) DEBUG: name = flip last_ts = 473.105011 last_received_ts = 473.104614 last_seq = 16586 current_ts = 473.121674 current_received_ts = 473.121307 current_seq = 16587 count = 111 seq_step = 1 [471.732510] (kms_flip:13343) DEBUG: Vblank took 25us [471.749150] (kms_flip:13343) DEBUG: name = flip last_ts = 473.121674 last_received_ts = 473.121307 last_seq = 16587 current_ts = 473.138336 current_received_ts = 473.137970 current_seq = 16588 count = 112 seq_step = 1 [471.749196] (kms_flip:13343) DEBUG: Vblank took 42us [471.765815] (kms_flip:13343) DEBUG: name = flip last_ts = 473.138336 last_received_ts = 473.137970 last_seq = 16588 current_ts = 473.154999 current_received_ts = 473.154633 current_seq = 16589 count = 113 seq_step = 1 [471.765844] (kms_flip:13343) DEBUG: Vblank took 24us [471.782487] (kms_flip:13343) DEBUG: name = flip last_ts = 473.154999 last_received_ts = 473.154633 last_seq = 16589 current_ts = 473.171661 current_received_ts = 473.171295 current_seq = 16590 count = 114 seq_step = 1 [471.782517] (kms_flip:13343) DEBUG: Vblank took 25us [471.799150] (kms_flip:13343) DEBUG: name = flip last_ts = 473.171661 last_received_ts = 473.171295 last_seq = 16590 current_ts = 473.188324 current_received_ts = 473.187958 current_seq = 16591 count = 115 seq_step = 1 [471.799209] (kms_flip:13343) DEBUG: Vblank took 54us [471.815743] (kms_flip:13343) DEBUG: name = flip last_ts = 473.188324 last_received_ts = 473.187958 last_seq = 16591 current_ts = 473.205017 current_received_ts = 473.204559 current_seq = 16592 count = 116 seq_step = 1 [471.815772] (kms_flip:13343) DEBUG: Vblank took 26us [471.832411] (kms_flip:13343) DEBUG: name = flip last_ts = 473.205017 last_received_ts = 473.204559 last_seq = 16592 current_ts = 473.221680 current_received_ts = 473.221222 current_seq = 16593 count = 117 seq_step = 1 [471.832441] (kms_flip:13343) DEBUG: Vblank took 26us [471.849211] (kms_flip:13343) DEBUG: name = flip last_ts = 473.221680 last_received_ts = 473.221222 last_seq = 16593 current_ts = 473.238342 current_received_ts = 473.237976 current_seq = 16594 count = 118 seq_step = 1 [471.849267] (kms_flip:13343) DEBUG: Vblank took 38us [471.865827] (kms_flip:13343) DEBUG: name = flip last_ts = 473.238342 last_received_ts = 473.237976 last_seq = 16594 current_ts = 473.255005 current_received_ts = 473.254639 current_seq = 16595 count = 119 seq_step = 1 [471.865862] (kms_flip:13343) DEBUG: Vblank took 27us [471.882501] (kms_flip:13343) DEBUG: name = flip last_ts = 473.255005 last_received_ts = 473.254639 last_seq = 16595 current_ts = 473.271667 current_received_ts = 473.271332 current_seq = 16596 count = 120 seq_step = 1 [471.882536] (kms_flip:13343) DEBUG: Vblank took 27us [471.899162] (kms_flip:13343) DEBUG: name = flip last_ts = 473.271667 last_received_ts = 473.271332 last_seq = 16596 current_ts = 473.288361 current_received_ts = 473.287994 current_seq = 16597 count = 121 seq_step = 1 [471.899217] (kms_flip:13343) DEBUG: Vblank took 47us [471.915777] (kms_flip:13343) DEBUG: name = flip last_ts = 473.288361 last_received_ts = 473.287994 last_seq = 16597 current_ts = 473.305023 current_received_ts = 473.304596 current_seq = 16598 count = 122 seq_step = 1 [471.915794] (kms_flip:13343) DEBUG: Vblank took 16us [471.932445] (kms_flip:13343) DEBUG: name = flip last_ts = 473.305023 last_received_ts = 473.304596 last_seq = 16598 current_ts = 473.321686 current_received_ts = 473.321259 current_seq = 16599 count = 123 seq_step = 1 [471.932463] (kms_flip:13343) DEBUG: Vblank took 17us [471.948889] (kms_flip:13343) DEBUG: name = flip last_ts = 473.321686 last_received_ts = 473.321259 last_seq = 16599 current_ts = 473.338348 current_received_ts = 473.337708 current_seq = 16600 count = 124 seq_step = 1 [471.948907] (kms_flip:13343) DEBUG: Vblank took 17us [471.965779] (kms_flip:13343) DEBUG: name = flip last_ts = 473.338348 last_received_ts = 473.337708 last_seq = 16600 current_ts = 473.355011 current_received_ts = 473.354614 current_seq = 16601 count = 125 seq_step = 1 [471.965798] (kms_flip:13343) DEBUG: Vblank took 17us [471.982468] (kms_flip:13343) DEBUG: name = flip last_ts = 473.355011 last_received_ts = 473.354614 last_seq = 16601 current_ts = 473.371704 current_received_ts = 473.371307 current_seq = 16602 count = 126 seq_step = 1 [471.982492] (kms_flip:13343) DEBUG: Vblank took 21us [471.999159] (kms_flip:13343) DEBUG: name = flip last_ts = 473.371704 last_received_ts = 473.371307 last_seq = 16602 current_ts = 473.388367 current_received_ts = 473.387970 current_seq = 16603 count = 127 seq_step = 1 [471.999228] (kms_flip:13343) DEBUG: Vblank took 65us [472.015827] (kms_flip:13343) DEBUG: name = flip last_ts = 473.388367 last_received_ts = 473.387970 last_seq = 16603 current_ts = 473.405029 current_received_ts = 473.404663 current_seq = 16604 count = 128 seq_step = 1 [472.015858] (kms_flip:13343) DEBUG: Vblank took 27us [472.033347] (kms_flip:13343) DEBUG: name = flip last_ts = 473.405029 last_received_ts = 473.404663 last_seq = 16604 current_ts = 473.421692 current_received_ts = 473.422150 current_seq = 16605 count = 129 seq_step = 1 [472.033410] (kms_flip:13343) DEBUG: Vblank took 46us [472.049291] (kms_flip:13343) DEBUG: name = flip last_ts = 473.421692 last_received_ts = 473.422150 last_seq = 16605 current_ts = 473.438354 current_received_ts = 473.438080 current_seq = 16606 count = 130 seq_step = 1 [472.049361] (kms_flip:13343) DEBUG: Vblank took 48us [472.067100] (kms_flip:13343) DEBUG: name = flip last_ts = 473.438354 last_received_ts = 473.438080 last_seq = 16606 current_ts = 473.455048 current_received_ts = 473.455902 current_seq = 16607 count = 131 seq_step = 1 [472.070710] (kms_flip:13343) DEBUG: Vblank took 3581us [472.070725] (kms_flip:13343) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [472.070861] (kms_flip:13343) CRITICAL: Failed assertion: end - start < 500 [472.070958] (kms_flip:13343) CRITICAL: Last errno: 4, Interrupted system call [472.091737] (kms_flip:13343) igt_core-INFO: Stack trace: [472.103687] (kms_flip:13343) igt_core-INFO: #0 ../lib/igt_core.c:2106 __igt_fail_assert() [472.104456] (kms_flip:13343) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [472.104510] (kms_flip:13343) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [472.104532] (kms_flip:13343) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() [472.104558] (kms_flip:13343) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [472.107211] (kms_flip:13343) igt_core-INFO: #5 [__libc_init_first+0x8a] [472.107832] (kms_flip:13343) igt_core-INFO: #6 [__libc_start_main+0x8b] [472.107974] (kms_flip:13343) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-DP2: FAIL (2.487s)
Dmesg	<6> [486.556538] [IGT] kms_flip: starting dynamic subtest B-DP2 <7> [486.559317] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:554] <7> [486.560755] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:557] <7> [486.604225] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [486.604305] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [486.604451] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [486.604562] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [486.604667] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [486.604768] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 7208960/8388608 link 480597/524288, found tu 0, data 0/0 link 0/0) <7> [486.604869] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000080, found 0x00000000) <7> [486.604969] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [486.605068] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [486.605165] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [486.605262] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [486.605377] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [486.605475] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [486.605571] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [486.605667] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [486.605763] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [486.605859] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [486.605956] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [486.606050] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [486.606146] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [486.606242] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [486.606354] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [486.606451] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [486.606547] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [486.606642] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [486.606737] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [486.606833] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [486.606928] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [486.607023] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [486.607118] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [486.607214] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [486.607310] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [486.607415] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [486.607511] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [486.607607] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [486.607702] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [486.607798] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [486.607894] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [486.608007] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [486.608103] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 162000, found 0) <7> [486.608200] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [486.608296] xe 0000:03:00.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing TC PLL 2 <7> [486.608432] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [486.608516] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [486.608617] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4037 - 4096) -> ( 0 - 0), size 59 -> 0 <7> [486.608702] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 192000 kHz -> 0 kHz <7> [486.608837] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [486.608944] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [486.609048] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [486.609148] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [486.609248] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [486.609353] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [486.609453] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [486.609862] xe 0000:03:00.0: [drm:intel_audio_codec_disable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Disable audio codec on [CRTC:151:pipe A] <7> [486.632152] xe 0000:03:00.0: [drm:intel_audio_component_get_eld [xe]] Not valid for port E <7> [486.632847] xe 0000:03:00.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [486.650596] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [486.653504] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disable TC PLL 2 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [486.656003] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disabling TC PLL 2 <7> [486.656682] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [486.656756] xe 0000:03:00.0: [drm:intel_audio_component_get_power [xe]] restored AUD_FREQ_CNTRL to 0x8010 <7> [486.657107] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [486.657559] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [486.657909] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [486.658253] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [486.658625] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [486.659145] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [486.659491] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [486.659778] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [486.660057] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [486.660333] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [486.660648] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [486.660903] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [486.661159] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [486.661433] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [486.661669] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [486.661900] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [486.662308] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [486.662758] xe 0000:03:00.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [486.662958] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [486.663508] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [486.663948] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [486.664217] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [486.664854] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe C] <7> [486.665387] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe B] <7> [486.665559] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D] <7> [486.665723] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe C] <7> [486.665753] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:527:DP-2] <7> [486.665855] xe 0000:03:00.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:527:DP-2] Limiting target display pipe bpp to 30 (EDID bpp 48, max requested bpp 30, max platform bpp 36) <7> [486.666064] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:526:DDI TC2/PHY G][CRTC:269:pipe C] DP link limits: pixel clock 148500 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [486.666261] xe 0000:03:00.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 162000 bpp input 30 compressed 0.0000 HDR no link rate required 556875 available 648000 <7> [486.666454] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe C] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [486.666627] xe 0000:03:00.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:526:DDI TC2/PHY G] [CRTC:269:pipe C] <7> [486.666797] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [486.666954] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [486.667108] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [486.667262] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [486.667430] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7208960/8388608 link 480597/524288) <7> [486.667577] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000080) <7> [486.667726] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [486.667859] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [486.667991] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [486.668124] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [486.668249] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [486.668385] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [486.668511] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [486.668629] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [486.668744] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [486.668855] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [486.668966] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [486.669075] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [486.669183] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [486.669290] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [486.669405] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [486.669505] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [486.669603] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [486.669701] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [486.669798] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [486.669895] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [486.669989] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [486.670084] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [486.670178] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [486.670273] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [486.670373] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [486.670468] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [486.670562] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [486.670657] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [486.670751] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [486.670846] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in dpll_hw_state <7> [486.670940] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] expected: <7> [486.671034] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [486.671127] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: <7> [486.671121] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_2 <7> [486.671221] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000 <7> [486.671315] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [486.671422] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x40e8 <7> [486.671516] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[1] = 0x7d20 <7> [486.671610] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[2] = 0x0a06 <7> [486.671703] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[3] = 0x8f1c <7> [486.671796] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[4] = 0x0000 <7> [486.671889] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[5] = 0x0000 <7> [486.671981] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[6] = 0x2200 <7> [486.672074] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[7] = 0xffff <7> [486.672167] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[8] = 0x0400 <7> [486.672261] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[9] = 0x0000 <7> [486.672357] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0001 <7> [486.672450] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00 <7> [486.672543] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] found: <7> [486.672635] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [486.672728] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: <7> [486.672821] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000 <7> [486.672915] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [486.673008] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x50a8 <7> [486.673113] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[1] = 0x2120 <7> [486.673208] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[2] = 0xcd9a <7> [486.673299] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[3] = 0xbfc1 <7> [486.673397] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[4] = 0x5ab8 <7> [486.673492] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[5] = 0x4c34 <7> [486.673586] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[6] = 0x2000 <7> [486.673680] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[7] = 0x0001 <7> [486.673774] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[8] = 0x6000 <7> [486.673868] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[9] = 0x0000 <7> [486.673961] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000 <7> [486.674053] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x40, hdmi rate: 0x00 <7> [486.674164] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [486.674257] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [486.674353] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [486.674448] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in port_clock (expected 0, found 162000) <7> [486.674542] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe C] fastset requirement not met, forcing full modeset <7> [486.674655] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no <7> [486.674739] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:269:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4 <7> [486.674840] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:153:plane 1C] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989 <7> [486.674917] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:263:cursor C] ddb ( 0 - 0) -> (1989 - 2048), size 0 -> 59 <7> [486.674993] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [486.675068] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 9, 9, 17, 17, 17, 17, 0, 15, 0 <7> [486.675144] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 139, 139, 261, 261, 261, 261, 137, 230, 244 <7> [486.675219] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 245, 245, 367, 367, 0, 0, 138, 306, 306 <7> [486.675304] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:269:pipe C] data rate 594000 num active planes 1 <7> [486.675428] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 33600 required 624 qgv_peak_bw: 48000 <7> [486.675532] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 53000 required 624 qgv_peak_bw: 48000 <7> [486.675634] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 48000 for required data rate: 624 <7> [486.675746] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:269:pipe C] min cdclk: 0 kHz -> 192000 kHz <7> [486.675872] xe 0000:03:00.0: [drm:intel_find_dpll [xe]] [CRTC:269:pipe C] allocated TC PLL 2 <7> [486.675972] xe 0000:03:00.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:269:pipe C] reserving TC PLL 2 <7> [486.676070] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:269:pipe C] enable: yes [modeset] <7> [486.676176] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: DP (0x80), output format: RGB, sink format: RGB <7> [486.676279] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: C, pipe bpp: 30, dithering: 0 <7> [486.676392] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [486.676494] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [486.676594] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [486.676693] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [486.676791] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 7208960, data_n: 8388608, link_m: 480597, link_n: 524288, tu: 64 <7> [486.676889] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [486.676986] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled <7> [486.677083] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [486.677180] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] psr: disabled, selective update: disabled, panel replay: disabled, selective fetch: disabled <7> [486.677277] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [486.677381] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] audio: 1, infoframes: 0, infoframes enabled: 0x0 <7> [486.677478] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 10 00 09 00 68 36 00 01 00 00 00 00 00 00 00 00 <7> [486.677573] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 61 a4 9a 00 44 50 46 39 30 34 33 35 09 07 07 11 <7> [486.677671] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00 <7> [486.677767] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [486.677863] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [486.677959] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 25 vsync start: 41, vsync end: 36 <7> [486.678057] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1100, vmax vblank: 1100, vmin vtotal: 1125, vmax vtotal: 1125 <7> [486.678159] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [486.678258] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [486.678360] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [486.678457] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [486.678554] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5 <7> [486.678650] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [486.678746] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 162000, pixel rate 148500, min cdclk 192000, min voltage level 0 <7> [486.678841] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] linetime: 119, ips linetime: 0 <7> [486.678935] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [486.679030] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe src: 1920x1080+0+0 <7> [486.679125] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [486.679219] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [486.679314] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [486.679419] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [486.679518] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] c20pll_hw_state: <7> [486.679613] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000 <7> [486.679708] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [486.679803] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[0] = 0x50a8 <7> [486.679897] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[1] = 0x2120 <7> [486.679992] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[2] = 0xcd9a <7> [486.680086] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[3] = 0xbfc1 <7> [486.680180] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[4] = 0x5ab8 <7> [486.680275] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[5] = 0x4c34 <7> [486.680410] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[6] = 0x2000 <7> [486.680504] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[7] = 0x0001 <7> [486.680599] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[8] = 0x6000 <7> [486.680693] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[9] = 0x0000 <7> [486.680787] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[10] = 0x0000 <7> [486.680881] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vdr: custom width: 0x00, serdes rate: 0x40, hdmi rate: 0x00 <7> [486.680976] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [486.681071] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [486.681165] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [486.681259] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [486.681356] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [486.681449] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [486.681542] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [486.681635] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [486.681729] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [486.681822] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [486.681916] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [486.682010] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [486.682104] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:153:plane 1C] fb: [FB:554] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [486.682199] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [486.682294] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [486.682396] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:183:plane 2C] fb: [NOFB], visible: no <7> [486.682491] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:213:plane 3C] fb: [NOFB], visible: no <7> [486.682586] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:243:plane 4C] fb: [NOFB], visible: no <7> [486.682680] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:253:plane 5C] fb: [NOFB], visible: no <7> [486.682775] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:263:cursor C] fb: [NOFB], visible: no <7> [486.683393] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [486.683507] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_C <7> [486.683630] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x4 (CLKGATE_DIS_DSSDSC=0x8a000000) <7> [486.683741] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [486.683834] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [486.683925] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [486.684012] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [486.684099] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [486.684187] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [486.684276] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [486.684375] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [486.684461] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [486.684545] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [486.684628] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [486.684712] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [486.684796] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [486.684879] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [486.684961] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [486.685043] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [486.685134] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xd <7> [486.685305] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [486.685419] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enable TC PLL 2 (active 0x4, on? 0) for [CRTC:269:pipe C] <7> [486.685518] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enabling TC PLL 2 <7> [486.689496] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01 <7> [486.694234] xe 0000:03:00.0: [drm:intel_dp_init_lttpr_and_dprx_caps [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] LTTPR common capabilities: 00 00 00 00 00 00 00 00 <7> [486.695247] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01 <7> [486.695696] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 06 <7> [486.697196] xe 0000:03:00.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [486.697757] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS1 <7> [486.704234] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Clock recovery OK <7> [486.704363] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS3 <7> [486.710231] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Channel EQ done. DP Training successful <7> [486.710371] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Link Training passed at link rate = 162000, lane count = 4 <7> [486.711630] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe C <7> [486.745814] xe 0000:03:00.0: [drm:intel_audio_codec_enable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Enable audio codec on [CRTC:269:pipe C], 40 bytes ELD <7> [486.759893] xe 0000:03:00.0: [drm:intel_audio_component_get_power [xe]] restored AUD_FREQ_CNTRL to 0x8010 <7> [486.762746] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [486.763646] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe C] <7> [486.814377] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <7> [488.750574] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [488.853313] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <6> [488.857226] xe 0000:03:00.0: [drm] PL2 disabled for channel 0, val 0x00000000 <7> [488.862408] xe 0000:03:00.0: [drm:xe_hwmon_read [xe]] thermal data for group 0 val 0x26272626 <7> [488.862577] xe 0000:03:00.0: [drm:xe_hwmon_read [xe]] thermal data for group 1 val 0x27262626 <6> [489.046169] [IGT] kms_flip: finished subtest B-DP2, FAIL

Detail

Value

Duration

2.49 seconds

Hostname

shard-bmg-1

Igt-Version

IGT-Version: 2.4-g0e365bfe5 (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-pw-167480v1-debug+ x86_64)

Out

Starting dynamic subtest: B-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2106 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-DP2: FAIL (2.487s)

Err

Starting dynamic subtest: B-DP2
[472.070725] (kms_flip:13343) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[472.070861] (kms_flip:13343) CRITICAL: Failed assertion: end - start < 500
[472.070958] (kms_flip:13343) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-DP2 failed.
**** DEBUG ****
[470.049010] (kms_flip:13343) DEBUG: Vblank took 25us
[470.065647] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.438202
last_received_ts = 471.437775
last_seq = 16486
current_ts = 471.454895
current_received_ts = 471.454437
current_seq = 16487
count = 11
seq_step = 1
[470.065677] (kms_flip:13343) DEBUG: Vblank took 26us
[470.082278] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.454895
last_received_ts = 471.454437
last_seq = 16487
current_ts = 471.471558
current_received_ts = 471.471069
current_seq = 16488
count = 12
seq_step = 1
[470.082308] (kms_flip:13343) DEBUG: Vblank took 26us
[470.098982] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.471558
last_received_ts = 471.471069
last_seq = 16488
current_ts = 471.488220
current_received_ts = 471.487762
current_seq = 16489
count = 13
seq_step = 1
[470.099011] (kms_flip:13343) DEBUG: Vblank took 25us
[470.115724] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.488220
last_received_ts = 471.487762
last_seq = 16489
current_ts = 471.504883
current_received_ts = 471.504517
current_seq = 16490
count = 14
seq_step = 1
[470.115753] (kms_flip:13343) DEBUG: Vblank took 24us
[470.132318] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.504883
last_received_ts = 471.504517
last_seq = 16490
current_ts = 471.521545
current_received_ts = 471.521118
current_seq = 16491
count = 15
seq_step = 1
[470.132349] (kms_flip:13343) DEBUG: Vblank took 25us
[470.148945] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.521545
last_received_ts = 471.521118
last_seq = 16491
current_ts = 471.538208
current_received_ts = 471.537750
current_seq = 16492
count = 16
seq_step = 1
[470.148975] (kms_flip:13343) DEBUG: Vblank took 26us
[470.165652] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.538208
last_received_ts = 471.537750
last_seq = 16492
current_ts = 471.554901
current_received_ts = 471.554443
current_seq = 16493
count = 17
seq_step = 1
[470.165681] (kms_flip:13343) DEBUG: Vblank took 26us
[470.182320] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.554901
last_received_ts = 471.554443
last_seq = 16493
current_ts = 471.571564
current_received_ts = 471.571106
current_seq = 16494
count = 18
seq_step = 1
[470.182350] (kms_flip:13343) DEBUG: Vblank took 26us
[470.199060] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.571564
last_received_ts = 471.571106
last_seq = 16494
current_ts = 471.588226
current_received_ts = 471.587860
current_seq = 16495
count = 19
seq_step = 1
[470.199089] (kms_flip:13343) DEBUG: Vblank took 25us
[470.215654] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.588226
last_received_ts = 471.587860
last_seq = 16495
current_ts = 471.604889
current_received_ts = 471.604462
current_seq = 16496
count = 20
seq_step = 1
[470.215684] (kms_flip:13343) DEBUG: Vblank took 26us
[470.232321] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.604889
last_received_ts = 471.604462
last_seq = 16496
current_ts = 471.621552
current_received_ts = 471.621124
current_seq = 16497
count = 21
seq_step = 1
[470.232351] (kms_flip:13343) DEBUG: Vblank took 25us
[470.248991] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.621552
last_received_ts = 471.621124
last_seq = 16497
current_ts = 471.638214
current_received_ts = 471.637787
current_seq = 16498
count = 22
seq_step = 1
[470.249021] (kms_flip:13343) DEBUG: Vblank took 26us
[470.265656] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.638214
last_received_ts = 471.637787
last_seq = 16498
current_ts = 471.654907
current_received_ts = 471.654449
current_seq = 16499
count = 23
seq_step = 1
[470.265687] (kms_flip:13343) DEBUG: Vblank took 26us
[470.282403] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.654907
last_received_ts = 471.654449
last_seq = 16499
current_ts = 471.671570
current_received_ts = 471.671204
current_seq = 16500
count = 24
seq_step = 1
[470.282433] (kms_flip:13343) DEBUG: Vblank took 26us
[470.299064] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.671570
last_received_ts = 471.671204
last_seq = 16500
current_ts = 471.688232
current_received_ts = 471.687866
current_seq = 16501
count = 25
seq_step = 1
[470.299093] (kms_flip:13343) DEBUG: Vblank took 25us
[470.315665] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.688232
last_received_ts = 471.687866
last_seq = 16501
current_ts = 471.704895
current_received_ts = 471.704468
current_seq = 16502
count = 26
seq_step = 1
[470.315696] (kms_flip:13343) DEBUG: Vblank took 25us
[470.332329] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.704895
last_received_ts = 471.704468
last_seq = 16502
current_ts = 471.721558
current_received_ts = 471.721130
current_seq = 16503
count = 27
seq_step = 1
[470.332357] (kms_flip:13343) DEBUG: Vblank took 25us
[470.348995] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.721558
last_received_ts = 471.721130
last_seq = 16503
current_ts = 471.738220
current_received_ts = 471.737793
current_seq = 16504
count = 28
seq_step = 1
[470.349024] (kms_flip:13343) DEBUG: Vblank took 25us
[470.365522] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.738220
last_received_ts = 471.737793
last_seq = 16504
current_ts = 471.754913
current_received_ts = 471.754333
current_seq = 16505
count = 29
seq_step = 1
[470.365551] (kms_flip:13343) DEBUG: Vblank took 25us
[470.382291] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.754913
last_received_ts = 471.754333
last_seq = 16505
current_ts = 471.771576
current_received_ts = 471.771088
current_seq = 16506
count = 30
seq_step = 1
[470.382321] (kms_flip:13343) DEBUG: Vblank took 25us
[470.399071] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.771576
last_received_ts = 471.771088
last_seq = 16506
current_ts = 471.788239
current_received_ts = 471.787872
current_seq = 16507
count = 31
seq_step = 1
[470.399102] (kms_flip:13343) DEBUG: Vblank took 26us
[470.415665] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.788239
last_received_ts = 471.787872
last_seq = 16507
current_ts = 471.804901
current_received_ts = 471.804474
current_seq = 16508
count = 32
seq_step = 1
[470.415694] (kms_flip:13343) DEBUG: Vblank took 26us
[470.432406] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.804901
last_received_ts = 471.804474
last_seq = 16508
current_ts = 471.821564
current_received_ts = 471.821198
current_seq = 16509
count = 33
seq_step = 1
[470.432435] (kms_flip:13343) DEBUG: Vblank took 25us
[470.449073] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.821564
last_received_ts = 471.821198
last_seq = 16509
current_ts = 471.838226
current_received_ts = 471.837860
current_seq = 16510
count = 34
seq_step = 1
[470.449103] (kms_flip:13343) DEBUG: Vblank took 26us
[470.465740] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.838226
last_received_ts = 471.837860
last_seq = 16510
current_ts = 471.854919
current_received_ts = 471.854553
current_seq = 16511
count = 35
seq_step = 1
[470.465769] (kms_flip:13343) DEBUG: Vblank took 25us
[470.482410] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.854919
last_received_ts = 471.854553
last_seq = 16511
current_ts = 471.871582
current_received_ts = 471.871216
current_seq = 16512
count = 36
seq_step = 1
[470.482439] (kms_flip:13343) DEBUG: Vblank took 25us
[470.499080] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.871582
last_received_ts = 471.871216
last_seq = 16512
current_ts = 471.888245
current_received_ts = 471.887878
current_seq = 16513
count = 37
seq_step = 1
[470.499110] (kms_flip:13343) DEBUG: Vblank took 26us
[470.515744] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.888245
last_received_ts = 471.887878
last_seq = 16513
current_ts = 471.904907
current_received_ts = 471.904541
current_seq = 16514
count = 38
seq_step = 1
[470.515774] (kms_flip:13343) DEBUG: Vblank took 25us
[470.532413] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.904907
last_received_ts = 471.904541
last_seq = 16514
current_ts = 471.921570
current_received_ts = 471.921204
current_seq = 16515
count = 39
seq_step = 1
[470.532442] (kms_flip:13343) DEBUG: Vblank took 26us
[470.549082] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.921570
last_received_ts = 471.921204
last_seq = 16515
current_ts = 471.938263
current_received_ts = 471.937897
current_seq = 16516
count = 40
seq_step = 1
[470.549114] (kms_flip:13343) DEBUG: Vblank took 26us
[470.565750] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.938263
last_received_ts = 471.937897
last_seq = 16516
current_ts = 471.954926
current_received_ts = 471.954559
current_seq = 16517
count = 41
seq_step = 1
[470.565779] (kms_flip:13343) DEBUG: Vblank took 26us
[470.582413] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.954926
last_received_ts = 471.954559
last_seq = 16517
current_ts = 471.971588
current_received_ts = 471.971222
current_seq = 16518
count = 42
seq_step = 1
[470.582442] (kms_flip:13343) DEBUG: Vblank took 25us
[470.599007] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.971588
last_received_ts = 471.971222
last_seq = 16518
current_ts = 471.988251
current_received_ts = 471.987793
current_seq = 16519
count = 43
seq_step = 1
[470.599036] (kms_flip:13343) DEBUG: Vblank took 26us
[470.615686] (kms_flip:13343) DEBUG: name = flip
last_ts = 471.988251
last_received_ts = 471.987793
last_seq = 16519
current_ts = 472.004913
current_received_ts = 472.004486
current_seq = 16520
count = 44
seq_step = 1
[470.615717] (kms_flip:13343) DEBUG: Vblank took 26us
[470.632347] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.004913
last_received_ts = 472.004486
last_seq = 16520
current_ts = 472.021576
current_received_ts = 472.021149
current_seq = 16521
count = 45
seq_step = 1
[470.632377] (kms_flip:13343) DEBUG: Vblank took 26us
[470.649012] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.021576
last_received_ts = 472.021149
last_seq = 16521
current_ts = 472.038269
current_received_ts = 472.037811
current_seq = 16522
count = 46
seq_step = 1
[470.649042] (kms_flip:13343) DEBUG: Vblank took 26us
[470.665749] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.038269
last_received_ts = 472.037811
last_seq = 16522
current_ts = 472.054932
current_received_ts = 472.054535
current_seq = 16523
count = 47
seq_step = 1
[470.665779] (kms_flip:13343) DEBUG: Vblank took 26us
[470.682347] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.054932
last_received_ts = 472.054535
last_seq = 16523
current_ts = 472.071594
current_received_ts = 472.071136
current_seq = 16524
count = 48
seq_step = 1
[470.682378] (kms_flip:13343) DEBUG: Vblank took 25us
[470.699088] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.071594
last_received_ts = 472.071136
last_seq = 16524
current_ts = 472.088257
current_received_ts = 472.087891
current_seq = 16525
count = 49
seq_step = 1
[470.699118] (kms_flip:13343) DEBUG: Vblank took 25us
[470.715682] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.088257
last_received_ts = 472.087891
last_seq = 16525
current_ts = 472.104919
current_received_ts = 472.104492
current_seq = 16526
count = 50
seq_step = 1
[470.715713] (kms_flip:13343) DEBUG: Vblank took 26us
[470.732349] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.104919
last_received_ts = 472.104492
last_seq = 16526
current_ts = 472.121582
current_received_ts = 472.121155
current_seq = 16527
count = 51
seq_step = 1
[470.732378] (kms_flip:13343) DEBUG: Vblank took 25us
[470.749015] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.121582
last_received_ts = 472.121155
last_seq = 16527
current_ts = 472.138275
current_received_ts = 472.137817
current_seq = 16528
count = 52
seq_step = 1
[470.749045] (kms_flip:13343) DEBUG: Vblank took 24us
[470.765683] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.138275
last_received_ts = 472.137817
last_seq = 16528
current_ts = 472.154938
current_received_ts = 472.154480
current_seq = 16529
count = 53
seq_step = 1
[470.765713] (kms_flip:13343) DEBUG: Vblank took 26us
[470.782352] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.154938
last_received_ts = 472.154480
last_seq = 16529
current_ts = 472.171600
current_received_ts = 472.171143
current_seq = 16530
count = 54
seq_step = 1
[470.782382] (kms_flip:13343) DEBUG: Vblank took 25us
[470.799094] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.171600
last_received_ts = 472.171143
last_seq = 16530
current_ts = 472.188263
current_received_ts = 472.187897
current_seq = 16531
count = 55
seq_step = 1
[470.799123] (kms_flip:13343) DEBUG: Vblank took 25us
[470.815685] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.188263
last_received_ts = 472.187897
last_seq = 16531
current_ts = 472.204926
current_received_ts = 472.204498
current_seq = 16532
count = 56
seq_step = 1
[470.815715] (kms_flip:13343) DEBUG: Vblank took 26us
[470.832354] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.204926
last_received_ts = 472.204498
last_seq = 16532
current_ts = 472.221588
current_received_ts = 472.221161
current_seq = 16533
count = 57
seq_step = 1
[470.832384] (kms_flip:13343) DEBUG: Vblank took 25us
[470.849021] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.221588
last_received_ts = 472.221161
last_seq = 16533
current_ts = 472.238281
current_received_ts = 472.237823
current_seq = 16534
count = 58
seq_step = 1
[470.849052] (kms_flip:13343) DEBUG: Vblank took 25us
[470.865691] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.238281
last_received_ts = 472.237823
last_seq = 16534
current_ts = 472.254944
current_received_ts = 472.254486
current_seq = 16535
count = 59
seq_step = 1
[470.865722] (kms_flip:13343) DEBUG: Vblank took 25us
[470.882358] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.254944
last_received_ts = 472.254486
last_seq = 16535
current_ts = 472.271606
current_received_ts = 472.271149
current_seq = 16536
count = 60
seq_step = 1
[470.882388] (kms_flip:13343) DEBUG: Vblank took 26us
[470.899023] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.271606
last_received_ts = 472.271149
last_seq = 16536
current_ts = 472.288269
current_received_ts = 472.287842
current_seq = 16537
count = 61
seq_step = 1
[470.899052] (kms_flip:13343) DEBUG: Vblank took 25us
[470.915693] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.288269
last_received_ts = 472.287842
last_seq = 16537
current_ts = 472.304932
current_received_ts = 472.304504
current_seq = 16538
count = 62
seq_step = 1
[470.915723] (kms_flip:13343) DEBUG: Vblank took 26us
[470.932360] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.304932
last_received_ts = 472.304504
last_seq = 16538
current_ts = 472.321594
current_received_ts = 472.321167
current_seq = 16539
count = 63
seq_step = 1
[470.932390] (kms_flip:13343) DEBUG: Vblank took 26us
[470.949026] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.321594
last_received_ts = 472.321167
last_seq = 16539
current_ts = 472.338287
current_received_ts = 472.337830
current_seq = 16540
count = 64
seq_step = 1
[470.949055] (kms_flip:13343) DEBUG: Vblank took 25us
[470.965694] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.338287
last_received_ts = 472.337830
last_seq = 16540
current_ts = 472.354950
current_received_ts = 472.354492
current_seq = 16541
count = 65
seq_step = 1
[470.965723] (kms_flip:13343) DEBUG: Vblank took 25us
[470.982363] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.354950
last_received_ts = 472.354492
last_seq = 16541
current_ts = 472.371613
current_received_ts = 472.371155
current_seq = 16542
count = 66
seq_step = 1
[470.982393] (kms_flip:13343) DEBUG: Vblank took 26us
[470.999104] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.371613
last_received_ts = 472.371155
last_seq = 16542
current_ts = 472.388275
current_received_ts = 472.387909
current_seq = 16543
count = 67
seq_step = 1
[470.999133] (kms_flip:13343) DEBUG: Vblank took 25us
[471.015698] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.388275
last_received_ts = 472.387909
last_seq = 16543
current_ts = 472.404938
current_received_ts = 472.404510
current_seq = 16544
count = 68
seq_step = 1
[471.015728] (kms_flip:13343) DEBUG: Vblank took 25us
[471.032366] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.404938
last_received_ts = 472.404510
last_seq = 16544
current_ts = 472.421600
current_received_ts = 472.421173
current_seq = 16545
count = 69
seq_step = 1
[471.032396] (kms_flip:13343) DEBUG: Vblank took 26us
[471.049032] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.421600
last_received_ts = 472.421173
last_seq = 16545
current_ts = 472.438293
current_received_ts = 472.437836
current_seq = 16546
count = 70
seq_step = 1
[471.049062] (kms_flip:13343) DEBUG: Vblank took 25us
[471.065698] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.438293
last_received_ts = 472.437836
last_seq = 16546
current_ts = 472.454956
current_received_ts = 472.454498
current_seq = 16547
count = 71
seq_step = 1
[471.065727] (kms_flip:13343) DEBUG: Vblank took 25us
[471.082368] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.454956
last_received_ts = 472.454498
last_seq = 16547
current_ts = 472.471619
current_received_ts = 472.471191
current_seq = 16548
count = 72
seq_step = 1
[471.082398] (kms_flip:13343) DEBUG: Vblank took 26us
[471.099108] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.471619
last_received_ts = 472.471191
last_seq = 16548
current_ts = 472.488281
current_received_ts = 472.487915
current_seq = 16549
count = 73
seq_step = 1
[471.099137] (kms_flip:13343) DEBUG: Vblank took 24us
[471.115703] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.488281
last_received_ts = 472.487915
last_seq = 16549
current_ts = 472.504944
current_received_ts = 472.504517
current_seq = 16550
count = 74
seq_step = 1
[471.115732] (kms_flip:13343) DEBUG: Vblank took 25us
[471.132382] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.504944
last_received_ts = 472.504517
last_seq = 16550
current_ts = 472.521637
current_received_ts = 472.521179
current_seq = 16551
count = 75
seq_step = 1
[471.132420] (kms_flip:13343) DEBUG: Vblank took 31us
[471.149114] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.521637
last_received_ts = 472.521179
last_seq = 16551
current_ts = 472.538300
current_received_ts = 472.537933
current_seq = 16552
count = 76
seq_step = 1
[471.149145] (kms_flip:13343) DEBUG: Vblank took 25us
[471.165707] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.538300
last_received_ts = 472.537933
last_seq = 16552
current_ts = 472.554962
current_received_ts = 472.554504
current_seq = 16553
count = 77
seq_step = 1
[471.165738] (kms_flip:13343) DEBUG: Vblank took 26us
[471.182395] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.554962
last_received_ts = 472.554504
last_seq = 16553
current_ts = 472.571625
current_received_ts = 472.571198
current_seq = 16554
count = 78
seq_step = 1
[471.182425] (kms_flip:13343) DEBUG: Vblank took 24us
[471.199062] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.571625
last_received_ts = 472.571198
last_seq = 16554
current_ts = 472.588287
current_received_ts = 472.587860
current_seq = 16555
count = 79
seq_step = 1
[471.199092] (kms_flip:13343) DEBUG: Vblank took 25us
[471.215710] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.588287
last_received_ts = 472.587860
last_seq = 16555
current_ts = 472.604950
current_received_ts = 472.604523
current_seq = 16556
count = 80
seq_step = 1
[471.215761] (kms_flip:13343) DEBUG: Vblank took 46us
[471.232378] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.604950
last_received_ts = 472.604523
last_seq = 16556
current_ts = 472.621643
current_received_ts = 472.621185
current_seq = 16557
count = 81
seq_step = 1
[471.232427] (kms_flip:13343) DEBUG: Vblank took 44us
[471.249044] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.621643
last_received_ts = 472.621185
last_seq = 16557
current_ts = 472.638306
current_received_ts = 472.637848
current_seq = 16558
count = 82
seq_step = 1
[471.249073] (kms_flip:13343) DEBUG: Vblank took 25us
[471.265712] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.638306
last_received_ts = 472.637848
last_seq = 16558
current_ts = 472.654968
current_received_ts = 472.654510
current_seq = 16559
count = 83
seq_step = 1
[471.265742] (kms_flip:13343) DEBUG: Vblank took 25us
[471.282381] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.654968
last_received_ts = 472.654510
last_seq = 16559
current_ts = 472.671631
current_received_ts = 472.671204
current_seq = 16560
count = 84
seq_step = 1
[471.282412] (kms_flip:13343) DEBUG: Vblank took 26us
[471.299123] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.671631
last_received_ts = 472.671204
last_seq = 16560
current_ts = 472.688293
current_received_ts = 472.687927
current_seq = 16561
count = 85
seq_step = 1
[471.299153] (kms_flip:13343) DEBUG: Vblank took 26us
[471.315717] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.688293
last_received_ts = 472.687927
last_seq = 16561
current_ts = 472.704956
current_received_ts = 472.704529
current_seq = 16562
count = 86
seq_step = 1
[471.315747] (kms_flip:13343) DEBUG: Vblank took 26us
[471.332385] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.704956
last_received_ts = 472.704529
last_seq = 16562
current_ts = 472.721649
current_received_ts = 472.721191
current_seq = 16563
count = 87
seq_step = 1
[471.332415] (kms_flip:13343) DEBUG: Vblank took 26us
[471.349124] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.721649
last_received_ts = 472.721191
last_seq = 16563
current_ts = 472.738312
current_received_ts = 472.737946
current_seq = 16564
count = 88
seq_step = 1
[471.349153] (kms_flip:13343) DEBUG: Vblank took 25us
[471.365790] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.738312
last_received_ts = 472.737946
last_seq = 16564
current_ts = 472.754974
current_received_ts = 472.754608
current_seq = 16565
count = 89
seq_step = 1
[471.365820] (kms_flip:13343) DEBUG: Vblank took 25us
[471.382459] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.754974
last_received_ts = 472.754608
last_seq = 16565
current_ts = 472.771637
current_received_ts = 472.771271
current_seq = 16566
count = 90
seq_step = 1
[471.382489] (kms_flip:13343) DEBUG: Vblank took 25us
[471.399127] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.771637
last_received_ts = 472.771271
last_seq = 16566
current_ts = 472.788300
current_received_ts = 472.787933
current_seq = 16567
count = 91
seq_step = 1
[471.399157] (kms_flip:13343) DEBUG: Vblank took 25us
[471.415794] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.788300
last_received_ts = 472.787933
last_seq = 16567
current_ts = 472.804962
current_received_ts = 472.804596
current_seq = 16568
count = 92
seq_step = 1
[471.415822] (kms_flip:13343) DEBUG: Vblank took 25us
[471.432461] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.804962
last_received_ts = 472.804596
last_seq = 16568
current_ts = 472.821655
current_received_ts = 472.821289
current_seq = 16569
count = 93
seq_step = 1
[471.432491] (kms_flip:13343) DEBUG: Vblank took 26us
[471.449128] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.821655
last_received_ts = 472.821289
last_seq = 16569
current_ts = 472.838318
current_received_ts = 472.837952
current_seq = 16570
count = 94
seq_step = 1
[471.449157] (kms_flip:13343) DEBUG: Vblank took 24us
[471.465795] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.838318
last_received_ts = 472.837952
last_seq = 16570
current_ts = 472.854980
current_received_ts = 472.854614
current_seq = 16571
count = 95
seq_step = 1
[471.465825] (kms_flip:13343) DEBUG: Vblank took 25us
[471.482462] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.854980
last_received_ts = 472.854614
last_seq = 16571
current_ts = 472.871674
current_received_ts = 472.871277
current_seq = 16572
count = 96
seq_step = 1
[471.482492] (kms_flip:13343) DEBUG: Vblank took 25us
[471.499129] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.871674
last_received_ts = 472.871277
last_seq = 16572
current_ts = 472.888336
current_received_ts = 472.887939
current_seq = 16573
count = 97
seq_step = 1
[471.499169] (kms_flip:13343) DEBUG: Vblank took 24us
[471.515726] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.888336
last_received_ts = 472.887939
last_seq = 16573
current_ts = 472.904968
current_received_ts = 472.904541
current_seq = 16574
count = 98
seq_step = 1
[471.515759] (kms_flip:13343) DEBUG: Vblank took 24us
[471.532395] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.904968
last_received_ts = 472.904541
last_seq = 16574
current_ts = 472.921661
current_received_ts = 472.921204
current_seq = 16575
count = 99
seq_step = 1
[471.532425] (kms_flip:13343) DEBUG: Vblank took 25us
[471.549136] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.921661
last_received_ts = 472.921204
last_seq = 16575
current_ts = 472.938324
current_received_ts = 472.937958
current_seq = 16576
count = 100
seq_step = 1
[471.549165] (kms_flip:13343) DEBUG: Vblank took 26us
[471.565728] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.938324
last_received_ts = 472.937958
last_seq = 16576
current_ts = 472.954987
current_received_ts = 472.954559
current_seq = 16577
count = 101
seq_step = 1
[471.565758] (kms_flip:13343) DEBUG: Vblank took 24us
[471.582397] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.954987
last_received_ts = 472.954559
last_seq = 16577
current_ts = 472.971649
current_received_ts = 472.971222
current_seq = 16578
count = 102
seq_step = 1
[471.582427] (kms_flip:13343) DEBUG: Vblank took 25us
[471.599137] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.971649
last_received_ts = 472.971222
last_seq = 16578
current_ts = 472.988312
current_received_ts = 472.987946
current_seq = 16579
count = 103
seq_step = 1
[471.599166] (kms_flip:13343) DEBUG: Vblank took 24us
[471.615733] (kms_flip:13343) DEBUG: name = flip
last_ts = 472.988312
last_received_ts = 472.987946
last_seq = 16579
current_ts = 473.005005
current_received_ts = 473.004547
current_seq = 16580
count = 104
seq_step = 1
[471.615762] (kms_flip:13343) DEBUG: Vblank took 25us
[471.632418] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.005005
last_received_ts = 473.004547
last_seq = 16580
current_ts = 473.021667
current_received_ts = 473.021240
current_seq = 16581
count = 105
seq_step = 1
[471.632452] (kms_flip:13343) DEBUG: Vblank took 28us
[471.649148] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.021667
last_received_ts = 473.021240
last_seq = 16581
current_ts = 473.038330
current_received_ts = 473.037964
current_seq = 16582
count = 106
seq_step = 1
[471.649226] (kms_flip:13343) DEBUG: Vblank took 72us
[471.665810] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.038330
last_received_ts = 473.037964
last_seq = 16582
current_ts = 473.054993
current_received_ts = 473.054626
current_seq = 16583
count = 107
seq_step = 1
[471.665840] (kms_flip:13343) DEBUG: Vblank took 26us
[471.682480] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.054993
last_received_ts = 473.054626
last_seq = 16583
current_ts = 473.071655
current_received_ts = 473.071289
current_seq = 16584
count = 108
seq_step = 1
[471.682510] (kms_flip:13343) DEBUG: Vblank took 25us
[471.699147] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.071655
last_received_ts = 473.071289
last_seq = 16584
current_ts = 473.088318
current_received_ts = 473.087952
current_seq = 16585
count = 109
seq_step = 1
[471.699192] (kms_flip:13343) DEBUG: Vblank took 41us
[471.715810] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.088318
last_received_ts = 473.087952
last_seq = 16585
current_ts = 473.105011
current_received_ts = 473.104614
current_seq = 16586
count = 110
seq_step = 1
[471.715840] (kms_flip:13343) DEBUG: Vblank took 25us
[471.732480] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.105011
last_received_ts = 473.104614
last_seq = 16586
current_ts = 473.121674
current_received_ts = 473.121307
current_seq = 16587
count = 111
seq_step = 1
[471.732510] (kms_flip:13343) DEBUG: Vblank took 25us
[471.749150] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.121674
last_received_ts = 473.121307
last_seq = 16587
current_ts = 473.138336
current_received_ts = 473.137970
current_seq = 16588
count = 112
seq_step = 1
[471.749196] (kms_flip:13343) DEBUG: Vblank took 42us
[471.765815] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.138336
last_received_ts = 473.137970
last_seq = 16588
current_ts = 473.154999
current_received_ts = 473.154633
current_seq = 16589
count = 113
seq_step = 1
[471.765844] (kms_flip:13343) DEBUG: Vblank took 24us
[471.782487] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.154999
last_received_ts = 473.154633
last_seq = 16589
current_ts = 473.171661
current_received_ts = 473.171295
current_seq = 16590
count = 114
seq_step = 1
[471.782517] (kms_flip:13343) DEBUG: Vblank took 25us
[471.799150] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.171661
last_received_ts = 473.171295
last_seq = 16590
current_ts = 473.188324
current_received_ts = 473.187958
current_seq = 16591
count = 115
seq_step = 1
[471.799209] (kms_flip:13343) DEBUG: Vblank took 54us
[471.815743] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.188324
last_received_ts = 473.187958
last_seq = 16591
current_ts = 473.205017
current_received_ts = 473.204559
current_seq = 16592
count = 116
seq_step = 1
[471.815772] (kms_flip:13343) DEBUG: Vblank took 26us
[471.832411] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.205017
last_received_ts = 473.204559
last_seq = 16592
current_ts = 473.221680
current_received_ts = 473.221222
current_seq = 16593
count = 117
seq_step = 1
[471.832441] (kms_flip:13343) DEBUG: Vblank took 26us
[471.849211] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.221680
last_received_ts = 473.221222
last_seq = 16593
current_ts = 473.238342
current_received_ts = 473.237976
current_seq = 16594
count = 118
seq_step = 1
[471.849267] (kms_flip:13343) DEBUG: Vblank took 38us
[471.865827] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.238342
last_received_ts = 473.237976
last_seq = 16594
current_ts = 473.255005
current_received_ts = 473.254639
current_seq = 16595
count = 119
seq_step = 1
[471.865862] (kms_flip:13343) DEBUG: Vblank took 27us
[471.882501] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.255005
last_received_ts = 473.254639
last_seq = 16595
current_ts = 473.271667
current_received_ts = 473.271332
current_seq = 16596
count = 120
seq_step = 1
[471.882536] (kms_flip:13343) DEBUG: Vblank took 27us
[471.899162] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.271667
last_received_ts = 473.271332
last_seq = 16596
current_ts = 473.288361
current_received_ts = 473.287994
current_seq = 16597
count = 121
seq_step = 1
[471.899217] (kms_flip:13343) DEBUG: Vblank took 47us
[471.915777] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.288361
last_received_ts = 473.287994
last_seq = 16597
current_ts = 473.305023
current_received_ts = 473.304596
current_seq = 16598
count = 122
seq_step = 1
[471.915794] (kms_flip:13343) DEBUG: Vblank took 16us
[471.932445] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.305023
last_received_ts = 473.304596
last_seq = 16598
current_ts = 473.321686
current_received_ts = 473.321259
current_seq = 16599
count = 123
seq_step = 1
[471.932463] (kms_flip:13343) DEBUG: Vblank took 17us
[471.948889] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.321686
last_received_ts = 473.321259
last_seq = 16599
current_ts = 473.338348
current_received_ts = 473.337708
current_seq = 16600
count = 124
seq_step = 1
[471.948907] (kms_flip:13343) DEBUG: Vblank took 17us
[471.965779] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.338348
last_received_ts = 473.337708
last_seq = 16600
current_ts = 473.355011
current_received_ts = 473.354614
current_seq = 16601
count = 125
seq_step = 1
[471.965798] (kms_flip:13343) DEBUG: Vblank took 17us
[471.982468] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.355011
last_received_ts = 473.354614
last_seq = 16601
current_ts = 473.371704
current_received_ts = 473.371307
current_seq = 16602
count = 126
seq_step = 1
[471.982492] (kms_flip:13343) DEBUG: Vblank took 21us
[471.999159] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.371704
last_received_ts = 473.371307
last_seq = 16602
current_ts = 473.388367
current_received_ts = 473.387970
current_seq = 16603
count = 127
seq_step = 1
[471.999228] (kms_flip:13343) DEBUG: Vblank took 65us
[472.015827] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.388367
last_received_ts = 473.387970
last_seq = 16603
current_ts = 473.405029
current_received_ts = 473.404663
current_seq = 16604
count = 128
seq_step = 1
[472.015858] (kms_flip:13343) DEBUG: Vblank took 27us
[472.033347] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.405029
last_received_ts = 473.404663
last_seq = 16604
current_ts = 473.421692
current_received_ts = 473.422150
current_seq = 16605
count = 129
seq_step = 1
[472.033410] (kms_flip:13343) DEBUG: Vblank took 46us
[472.049291] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.421692
last_received_ts = 473.422150
last_seq = 16605
current_ts = 473.438354
current_received_ts = 473.438080
current_seq = 16606
count = 130
seq_step = 1
[472.049361] (kms_flip:13343) DEBUG: Vblank took 48us
[472.067100] (kms_flip:13343) DEBUG: name = flip
last_ts = 473.438354
last_received_ts = 473.438080
last_seq = 16606
current_ts = 473.455048
current_received_ts = 473.455902
current_seq = 16607
count = 131
seq_step = 1
[472.070710] (kms_flip:13343) DEBUG: Vblank took 3581us
[472.070725] (kms_flip:13343) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[472.070861] (kms_flip:13343) CRITICAL: Failed assertion: end - start < 500
[472.070958] (kms_flip:13343) CRITICAL: Last errno: 4, Interrupted system call
[472.091737] (kms_flip:13343) igt_core-INFO: Stack trace:
[472.103687] (kms_flip:13343) igt_core-INFO:   #0 ../lib/igt_core.c:2106 __igt_fail_assert()
[472.104456] (kms_flip:13343) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[472.104510] (kms_flip:13343) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[472.104532] (kms_flip:13343) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
[472.104558] (kms_flip:13343) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[472.107211] (kms_flip:13343) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[472.107832] (kms_flip:13343) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[472.107974] (kms_flip:13343) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-DP2: FAIL (2.487s)

Dmesg

<6> [486.556538] [IGT] kms_flip: starting dynamic subtest B-DP2

<7> [486.559317] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:554]

<7> [486.560755] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:557]

<7> [486.604225] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

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

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

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

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

<7> [486.604768] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 7208960/8388608 link 480597/524288, found tu 0, data 0/0 link 0/0)

<7> [486.604869] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000080, found 0x00000000)

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

<7> [486.605068] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0)

<7> [486.605165] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0)

<7> [486.605262] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0)

<7> [486.605377] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0)

<7> [486.605475] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0)

<7> [486.605571] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0)

<7> [486.605667] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0)

<7> [486.605763] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0)

<7> [486.605859] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0)

<7> [486.605956] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0)

<7> [486.606050] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0)

<7> [486.606146] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0)

<7> [486.606242] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0)

<7> [486.606354] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0)

<7> [486.606451] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0)

<7> [486.606547] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0)

<7> [486.606642] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0)

<7> [486.606737] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0)

<7> [486.606833] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0)

<7> [486.606928] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0)

<7> [486.607023] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0)

<7> [486.607118] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0)

<7> [486.607214] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0)

<7> [486.607310] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0)

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

<7> [486.607511] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0)

<7> [486.607607] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0)

<7> [486.607702] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in enhanced_framing (expected yes, found no)

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

<7> [486.607894] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0)

<7> [486.608007] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0)

<7> [486.608103] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 162000, found 0)

<7> [486.608200] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

<7> [486.608296] xe 0000:03:00.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing TC PLL 2

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

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

<7> [486.608617] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4037 - 4096) -> ( 0 - 0), size 59 -> 0

<7> [486.608702] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 192000 kHz -> 0 kHz

<7> [486.608837] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset]

<7> [486.608944] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no

<7> [486.609048] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no

<7> [486.609148] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no

<7> [486.609248] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no

<7> [486.609353] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no

<7> [486.609453] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no

<7> [486.609862] xe 0000:03:00.0: [drm:intel_audio_codec_disable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Disable audio codec on [CRTC:151:pipe A]

<7> [486.632152] xe 0000:03:00.0: [drm:intel_audio_component_get_eld [xe]] Not valid for port E

<7> [486.632847] xe 0000:03:00.0: [drm:intel_disable_transcoder [xe]] disabling pipe A

<7> [486.650596] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2

<7> [486.653504] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disable TC PLL 2 (active 0x1, on? 1) for [CRTC:151:pipe A]

<7> [486.656003] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disabling TC PLL 2

<7> [486.656682] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F]

<7> [486.656756] xe 0000:03:00.0: [drm:intel_audio_component_get_power [xe]] restored AUD_FREQ_CNTRL to 0x8010

<7> [486.657107] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A]

<7> [486.657559] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B]

<7> [486.657909] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C]

<7> [486.658253] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D]

<7> [486.658625] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G]

<7> [486.659145] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A]

<7> [486.659491] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B]

<7> [486.659778] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C]

<7> [486.660057] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D]

<7> [486.660333] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H]

<7> [486.660648] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I]

<7> [486.660903] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A]

<7> [486.661159] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B]

<7> [486.661433] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C]

<7> [486.661669] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D]

<7> [486.661900] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2]

<7> [486.662308] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no)

<7> [486.662758] xe 0000:03:00.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: *)

<7> [486.662958] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1

<7> [486.663508] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_A

<7> [486.663948] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000)

<7> [486.664217] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A]

<7> [486.664854] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe C]

<7> [486.665387] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe B]

<7> [486.665559] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D]

<7> [486.665723] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe C]

<7> [486.665753] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:527:DP-2]

<7> [486.665855] xe 0000:03:00.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:527:DP-2] Limiting target display pipe bpp to 30 (EDID bpp 48, max requested bpp 30, max platform bpp 36)

<7> [486.666064] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:526:DDI TC2/PHY G][CRTC:269:pipe C] DP link limits: pixel clock 148500 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000

<7> [486.666261] xe 0000:03:00.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 162000 bpp input 30 compressed 0.0000 HDR no link rate required 556875 available 648000

<7> [486.666454] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe C] hw max bpp: 30, pipe bpp: 30, dithering: 0

<7> [486.666627] xe 0000:03:00.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:526:DDI TC2/PHY G] [CRTC:269:pipe C]

<7> [486.666797] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.enable (expected no, found yes)

<7> [486.666954] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.active (expected no, found yes)

<7> [486.667108] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2)

<7> [486.667262] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in lane_count (expected 0, found 4)

<7> [486.667430] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7208960/8388608 link 480597/524288)

<7> [486.667577] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000080)

<7> [486.667726] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1)

<7> [486.667859] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920)

<7> [486.667991] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200)

<7> [486.668124] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920)

<7> [486.668249] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200)

<7> [486.668385] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008)

<7> [486.668511] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052)

<7> [486.668629] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080)

<7> [486.668744] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080)

<7> [486.668855] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084)

<7> [486.668966] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089)

<7> [486.669075] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125)

<7> [486.669183] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125)

<7> [486.669290] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920)

<7> [486.669405] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200)

<7> [486.669505] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920)

<7> [486.669603] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200)

<7> [486.669701] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008)

<7> [486.669798] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052)

<7> [486.669895] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080)

<7> [486.669989] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080)

<7> [486.670084] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084)

<7> [486.670178] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089)

<7> [486.670273] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125)

<7> [486.670373] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125)

<7> [486.670468] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1)

<7> [486.670562] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1)

<7> [486.670657] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4)

<7> [486.670751] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes)

<7> [486.670846] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in dpll_hw_state

<7> [486.670940] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] expected:

<7> [486.671034] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no

<7> [486.671127] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state:

<7> [486.671121] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_2

<7> [486.671221] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000

<7> [486.671315] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [486.671422] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x40e8

<7> [486.671516] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[1] = 0x7d20

<7> [486.671610] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[2] = 0x0a06

<7> [486.671703] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[3] = 0x8f1c

<7> [486.671796] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[4] = 0x0000

<7> [486.671889] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[5] = 0x0000

<7> [486.671981] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[6] = 0x2200

<7> [486.672074] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[7] = 0xffff

<7> [486.672167] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[8] = 0x0400

<7> [486.672261] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[9] = 0x0000

<7> [486.672357] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0001

<7> [486.672450] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00

<7> [486.672543] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] found:

<7> [486.672635] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no

<7> [486.672728] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state:

<7> [486.672821] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000

<7> [486.672915] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [486.673008] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x50a8

<7> [486.673113] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[1] = 0x2120

<7> [486.673208] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[2] = 0xcd9a

<7> [486.673299] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[3] = 0xbfc1

<7> [486.673397] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[4] = 0x5ab8

<7> [486.673492] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[5] = 0x4c34

<7> [486.673586] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[6] = 0x2000

<7> [486.673680] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[7] = 0x0001

<7> [486.673774] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[8] = 0x6000

<7> [486.673868] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[9] = 0x0000

<7> [486.673961] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000

<7> [486.674053] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x40, hdmi rate: 0x00

<7> [486.674164] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 30)

<7> [486.674257] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500)

<7> [486.674353] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500)

<7> [486.674448] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in port_clock (expected 0, found 162000)

<7> [486.674542] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe C] fastset requirement not met, forcing full modeset

<7> [486.674655] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no

<7> [486.674739] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:269:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4

<7> [486.674840] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:153:plane 1C] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989

<7> [486.674917] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:263:cursor C] ddb ( 0 - 0) -> (1989 - 2048), size 0 -> 59

<7> [486.674993] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm

<7> [486.675068] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 9, 9, 17, 17, 17, 17, 0, 15, 0

<7> [486.675144] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 139, 139, 261, 261, 261, 261, 137, 230, 244

<7> [486.675219] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 245, 245, 367, 367, 0, 0, 138, 306, 306

<7> [486.675304] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:269:pipe C] data rate 594000 num active planes 1

<7> [486.675428] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 33600 required 624 qgv_peak_bw: 48000

<7> [486.675532] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 53000 required 624 qgv_peak_bw: 48000

<7> [486.675634] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 48000 for required data rate: 624

<7> [486.675746] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:269:pipe C] min cdclk: 0 kHz -> 192000 kHz

<7> [486.675872] xe 0000:03:00.0: [drm:intel_find_dpll [xe]] [CRTC:269:pipe C] allocated TC PLL 2

<7> [486.675972] xe 0000:03:00.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:269:pipe C] reserving TC PLL 2

<7> [486.676070] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:269:pipe C] enable: yes [modeset]

<7> [486.676176] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: DP (0x80), output format: RGB, sink format: RGB

<7> [486.676279] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: C, pipe bpp: 30, dithering: 0

<7> [486.676392] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid>

<7> [486.676494] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0

<7> [486.676594] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0

<7> [486.676693] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0

<7> [486.676791] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 7208960, data_n: 8388608, link_m: 480597, link_n: 524288, tu: 64

<7> [486.676889] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0

<7> [486.676986] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled

<7> [486.677083] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled

<7> [486.677180] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] psr: disabled, selective update: disabled, panel replay: disabled, selective fetch: disabled

<7> [486.677277] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0

<7> [486.677381] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] audio: 1, infoframes: 0, infoframes enabled: 0x0

<7> [486.677478] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 10 00 09 00 68 36 00 01 00 00 00 00 00 00 00 00

<7> [486.677573] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 61 a4 9a 00 44 50 46 39 30 34 33 35 09 07 07 11

<7> [486.677671] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00

<7> [486.677767] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1

<7> [486.677863] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0

<7> [486.677959] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 25 vsync start: 41, vsync end: 36

<7> [486.678057] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1100, vmax vblank: 1100, vmin vtotal: 1125, vmax vtotal: 1125

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

<7> [486.678258] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5

<7> [486.678360] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5

<7> [486.678457] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [486.678554] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5

<7> [486.678650] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [486.678746] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 162000, pixel rate 148500, min cdclk 192000, min voltage level 0

<7> [486.678841] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] linetime: 119, ips linetime: 0

<7> [486.678935] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0

<7> [486.679030] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe src: 1920x1080+0+0

<7> [486.679125] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no

<7> [486.679219] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0

<7> [486.679314] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0

<7> [486.679419] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no

<7> [486.679518] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] c20pll_hw_state:

<7> [486.679613] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000

<7> [486.679708] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [486.679803] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[0] = 0x50a8

<7> [486.679897] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[1] = 0x2120

<7> [486.679992] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[2] = 0xcd9a

<7> [486.680086] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[3] = 0xbfc1

<7> [486.680180] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[4] = 0x5ab8

<7> [486.680275] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[5] = 0x4c34

<7> [486.680410] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[6] = 0x2000

<7> [486.680504] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[7] = 0x0001

<7> [486.680599] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[8] = 0x6000

<7> [486.680693] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[9] = 0x0000

<7> [486.680787] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[10] = 0x0000

<7> [486.680881] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vdr: custom width: 0x00, serdes rate: 0x40, hdmi rate: 0x00

<7> [486.680976] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

<7> [486.681071] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries

<7> [486.681165] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000

<7> [486.681259] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [486.681356] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [486.681449] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [486.681542] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000

<7> [486.681635] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000

<7> [486.681729] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [486.681822] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [486.681916] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [486.682010] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000

<7> [486.682104] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:153:plane 1C] fb: [FB:554] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes

<7> [486.682199] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0

<7> [486.682294] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0

<7> [486.682396] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:183:plane 2C] fb: [NOFB], visible: no

<7> [486.682491] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:213:plane 3C] fb: [NOFB], visible: no

<7> [486.682586] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:243:plane 4C] fb: [NOFB], visible: no

<7> [486.682680] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:253:plane 5C] fb: [NOFB], visible: no

<7> [486.682775] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:263:cursor C] fb: [NOFB], visible: no

<7> [486.683393] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_2

<7> [486.683507] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_C

<7> [486.683630] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x4 (CLKGATE_DIS_DSSDSC=0x8a000000)

<7> [486.683741] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F]

<7> [486.683834] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A]

<7> [486.683925] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B]

<7> [486.684012] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C]

<7> [486.684099] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D]

<7> [486.684187] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G]

<7> [486.684276] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A]

<7> [486.684375] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B]

<7> [486.684461] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C]

<7> [486.684545] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D]

<7> [486.684628] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H]

<7> [486.684712] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I]

<7> [486.684796] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A]

<7> [486.684879] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B]

<7> [486.684961] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C]

<7> [486.685043] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D]

<7> [486.685134] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xd

<7> [486.685305] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no)

<7> [486.685419] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enable TC PLL 2 (active 0x4, on? 0) for [CRTC:269:pipe C]

<7> [486.685518] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enabling TC PLL 2

<7> [486.689496] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01

<7> [486.694234] xe 0000:03:00.0: [drm:intel_dp_init_lttpr_and_dprx_caps [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] LTTPR common capabilities: 00 00 00 00 00 00 00 00

<7> [486.695247] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01

<7> [486.695696] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 06

<7> [486.697196] xe 0000:03:00.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0

<7> [486.697757] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS1

<7> [486.704234] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Clock recovery OK

<7> [486.704363] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS3

<7> [486.710231] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Channel EQ done. DP Training successful

<7> [486.710371] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Link Training passed at link rate = 162000, lane count = 4

<7> [486.711630] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe C

<7> [486.745814] xe 0000:03:00.0: [drm:intel_audio_codec_enable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Enable audio codec on [CRTC:269:pipe C], 40 bytes ELD

<7> [486.759893] xe 0000:03:00.0: [drm:intel_audio_component_get_power [xe]] restored AUD_FREQ_CNTRL to 0x8010

<7> [486.762746] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2]

<7> [486.763646] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe C]

<7> [486.814377] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2

<7> [488.750574] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2

<7> [488.853313] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2

<6> [488.857226] xe 0000:03:00.0: [drm] PL2 disabled for channel 0, val 0x00000000

<7> [488.862408] xe 0000:03:00.0: [drm:xe_hwmon_read [xe]] thermal data for group 0 val 0x26272626

<7> [488.862577] xe 0000:03:00.0: [drm:xe_hwmon_read [xe]] thermal data for group 1 val 0x27262626

<6> [489.046169] [IGT] kms_flip: finished subtest B-DP2, FAIL

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