igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1 on shard-lnl@xe-4099-3462442c8cd967b22f9b9d250560be1e29e1d24f Test details

Detail	Value
Duration	3.78 seconds
Hostname	shard-lnl-4
Igt-Version	IGT-Version: 2.2-geb100acf0 (x86_64) (Linux: 6.18.0-rc5-lgci-xe-xe-4099-3462442c8cd967b22+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1889 run_test() #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045() #4 ../tests/kms_flip.c:2045 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (3.780s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:2070) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2070) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2070) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 76.719200 last_received_ts = 76.718384 last_seq = 33 current_ts = 76.735939 current_received_ts = 76.735146 current_seq = 34 count = 30 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 77us (kms_flip:2070) DEBUG: name = flip last_ts = 76.735939 last_received_ts = 76.735146 last_seq = 34 current_ts = 76.752670 current_received_ts = 76.751884 current_seq = 35 count = 31 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 76.752670 last_received_ts = 76.751884 last_seq = 35 current_ts = 76.769409 current_received_ts = 76.768623 current_seq = 36 count = 32 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 56us (kms_flip:2070) DEBUG: name = flip last_ts = 76.769409 last_received_ts = 76.768623 last_seq = 36 current_ts = 76.786156 current_received_ts = 76.785355 current_seq = 37 count = 33 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 76.786156 last_received_ts = 76.785355 last_seq = 37 current_ts = 76.802887 current_received_ts = 76.802094 current_seq = 38 count = 34 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 57us (kms_flip:2070) DEBUG: name = flip last_ts = 76.802887 last_received_ts = 76.802094 last_seq = 38 current_ts = 76.819626 current_received_ts = 76.818840 current_seq = 39 count = 35 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 56us (kms_flip:2070) DEBUG: name = flip last_ts = 76.819626 last_received_ts = 76.818840 last_seq = 39 current_ts = 76.836365 current_received_ts = 76.835579 current_seq = 40 count = 36 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 43us (kms_flip:2070) DEBUG: name = flip last_ts = 76.836365 last_received_ts = 76.835579 last_seq = 40 current_ts = 76.853111 current_received_ts = 76.852303 current_seq = 41 count = 37 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 56us (kms_flip:2070) DEBUG: name = flip last_ts = 76.853111 last_received_ts = 76.852303 last_seq = 41 current_ts = 76.869843 current_received_ts = 76.869057 current_seq = 42 count = 38 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 76.869843 last_received_ts = 76.869057 last_seq = 42 current_ts = 76.886581 current_received_ts = 76.885773 current_seq = 43 count = 39 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 43us (kms_flip:2070) DEBUG: name = flip last_ts = 76.886581 last_received_ts = 76.885773 last_seq = 43 current_ts = 76.903320 current_received_ts = 76.902527 current_seq = 44 count = 40 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 67us (kms_flip:2070) DEBUG: name = flip last_ts = 76.903320 last_received_ts = 76.902527 last_seq = 44 current_ts = 76.920059 current_received_ts = 76.919250 current_seq = 45 count = 41 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 76.920059 last_received_ts = 76.919250 last_seq = 45 current_ts = 76.936798 current_received_ts = 76.936028 current_seq = 46 count = 42 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 76.936798 last_received_ts = 76.936028 last_seq = 46 current_ts = 76.953545 current_received_ts = 76.952759 current_seq = 47 count = 43 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 76.953545 last_received_ts = 76.952759 last_seq = 47 current_ts = 76.970284 current_received_ts = 76.969498 current_seq = 48 count = 44 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 60us (kms_flip:2070) DEBUG: name = flip last_ts = 76.970284 last_received_ts = 76.969498 last_seq = 48 current_ts = 76.987015 current_received_ts = 76.986214 current_seq = 49 count = 45 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 76.987015 last_received_ts = 76.986214 last_seq = 49 current_ts = 77.003761 current_received_ts = 77.002975 current_seq = 50 count = 46 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 70us (kms_flip:2070) DEBUG: name = flip last_ts = 77.003761 last_received_ts = 77.002975 last_seq = 50 current_ts = 77.020493 current_received_ts = 77.019707 current_seq = 51 count = 47 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 77.020493 last_received_ts = 77.019707 last_seq = 51 current_ts = 77.037231 current_received_ts = 77.036446 current_seq = 52 count = 48 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 77.037231 last_received_ts = 77.036446 last_seq = 52 current_ts = 77.053978 current_received_ts = 77.053169 current_seq = 53 count = 49 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 77.053978 last_received_ts = 77.053169 last_seq = 53 current_ts = 77.070717 current_received_ts = 77.069916 current_seq = 54 count = 50 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.070717 last_received_ts = 77.069916 last_seq = 54 current_ts = 77.087456 current_received_ts = 77.086639 current_seq = 55 count = 51 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 77.087456 last_received_ts = 77.086639 last_seq = 55 current_ts = 77.104195 current_received_ts = 77.103416 current_seq = 56 count = 52 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 52us (kms_flip:2070) DEBUG: name = flip last_ts = 77.104195 last_received_ts = 77.103416 last_seq = 56 current_ts = 77.120934 current_received_ts = 77.120140 current_seq = 57 count = 53 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.120934 last_received_ts = 77.120140 last_seq = 57 current_ts = 77.137665 current_received_ts = 77.136879 current_seq = 58 count = 54 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.137665 last_received_ts = 77.136879 last_seq = 58 current_ts = 77.154411 current_received_ts = 77.153625 current_seq = 59 count = 55 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 57us (kms_flip:2070) DEBUG: name = flip last_ts = 77.154411 last_received_ts = 77.153625 last_seq = 59 current_ts = 77.171150 current_received_ts = 77.170349 current_seq = 60 count = 56 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.171150 last_received_ts = 77.170349 last_seq = 60 current_ts = 77.187881 current_received_ts = 77.187088 current_seq = 61 count = 57 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 77.187881 last_received_ts = 77.187088 last_seq = 61 current_ts = 77.204620 current_received_ts = 77.203842 current_seq = 62 count = 58 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.204620 last_received_ts = 77.203842 last_seq = 62 current_ts = 77.221367 current_received_ts = 77.220573 current_seq = 63 count = 59 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 42us (kms_flip:2070) DEBUG: name = flip last_ts = 77.221367 last_received_ts = 77.220573 last_seq = 63 current_ts = 77.238106 current_received_ts = 77.237297 current_seq = 64 count = 60 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 52us (kms_flip:2070) DEBUG: name = flip last_ts = 77.238106 last_received_ts = 77.237297 last_seq = 64 current_ts = 77.254845 current_received_ts = 77.254044 current_seq = 65 count = 61 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 58us (kms_flip:2070) DEBUG: name = flip last_ts = 77.254845 last_received_ts = 77.254044 last_seq = 65 current_ts = 77.271584 current_received_ts = 77.270813 current_seq = 66 count = 62 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 58us (kms_flip:2070) DEBUG: name = flip last_ts = 77.271584 last_received_ts = 77.270813 last_seq = 66 current_ts = 77.288322 current_received_ts = 77.287529 current_seq = 67 count = 63 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.288322 last_received_ts = 77.287529 last_seq = 67 current_ts = 77.305061 current_received_ts = 77.304253 current_seq = 68 count = 64 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 62us (kms_flip:2070) DEBUG: name = flip last_ts = 77.305061 last_received_ts = 77.304253 last_seq = 68 current_ts = 77.321800 current_received_ts = 77.321022 current_seq = 69 count = 65 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 50us (kms_flip:2070) DEBUG: name = flip last_ts = 77.321800 last_received_ts = 77.321022 last_seq = 69 current_ts = 77.338539 current_received_ts = 77.337753 current_seq = 70 count = 66 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 77.338539 last_received_ts = 77.337753 last_seq = 70 current_ts = 77.355278 current_received_ts = 77.354492 current_seq = 71 count = 67 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 77.355278 last_received_ts = 77.354492 last_seq = 71 current_ts = 77.372017 current_received_ts = 77.371208 current_seq = 72 count = 68 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 77.372017 last_received_ts = 77.371208 last_seq = 72 current_ts = 77.388756 current_received_ts = 77.387970 current_seq = 73 count = 69 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 67us (kms_flip:2070) DEBUG: name = flip last_ts = 77.388756 last_received_ts = 77.387970 last_seq = 73 current_ts = 77.405487 current_received_ts = 77.404709 current_seq = 74 count = 70 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 52us (kms_flip:2070) DEBUG: name = flip last_ts = 77.405487 last_received_ts = 77.404709 last_seq = 74 current_ts = 77.422218 current_received_ts = 77.421410 current_seq = 75 count = 71 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 77.422218 last_received_ts = 77.421410 last_seq = 75 current_ts = 77.438942 current_received_ts = 77.438164 current_seq = 76 count = 72 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 61us (kms_flip:2070) DEBUG: name = flip last_ts = 77.438942 last_received_ts = 77.438164 last_seq = 76 current_ts = 77.455673 current_received_ts = 77.454887 current_seq = 77 count = 73 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 56us (kms_flip:2070) DEBUG: name = flip last_ts = 77.455673 last_received_ts = 77.454887 last_seq = 77 current_ts = 77.472404 current_received_ts = 77.471619 current_seq = 78 count = 74 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.472404 last_received_ts = 77.471619 last_seq = 78 current_ts = 77.489136 current_received_ts = 77.488342 current_seq = 79 count = 75 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 61us (kms_flip:2070) DEBUG: name = flip last_ts = 77.489136 last_received_ts = 77.488342 last_seq = 79 current_ts = 77.505859 current_received_ts = 77.505066 current_seq = 80 count = 76 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 77.505859 last_received_ts = 77.505066 last_seq = 80 current_ts = 77.522591 current_received_ts = 77.521805 current_seq = 81 count = 77 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 56us (kms_flip:2070) DEBUG: name = flip last_ts = 77.522591 last_received_ts = 77.521805 last_seq = 81 current_ts = 77.539322 current_received_ts = 77.538536 current_seq = 82 count = 78 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 42us (kms_flip:2070) DEBUG: name = flip last_ts = 77.539322 last_received_ts = 77.538536 last_seq = 82 current_ts = 77.556053 current_received_ts = 77.555244 current_seq = 83 count = 79 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 56us (kms_flip:2070) DEBUG: name = flip last_ts = 77.556053 last_received_ts = 77.555244 last_seq = 83 current_ts = 77.572784 current_received_ts = 77.571976 current_seq = 84 count = 80 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 64us (kms_flip:2070) DEBUG: name = flip last_ts = 77.572784 last_received_ts = 77.571976 last_seq = 84 current_ts = 77.589508 current_received_ts = 77.588715 current_seq = 85 count = 81 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 56us (kms_flip:2070) DEBUG: name = flip last_ts = 77.589508 last_received_ts = 77.588715 last_seq = 85 current_ts = 77.606239 current_received_ts = 77.605453 current_seq = 86 count = 82 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 57us (kms_flip:2070) DEBUG: name = flip last_ts = 77.606239 last_received_ts = 77.605453 last_seq = 86 current_ts = 77.622971 current_received_ts = 77.622162 current_seq = 87 count = 83 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 77.622971 last_received_ts = 77.622162 last_seq = 87 current_ts = 77.639702 current_received_ts = 77.638916 current_seq = 88 count = 84 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 77.639702 last_received_ts = 77.638916 last_seq = 88 current_ts = 77.656425 current_received_ts = 77.655647 current_seq = 89 count = 85 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 59us (kms_flip:2070) DEBUG: name = flip last_ts = 77.656425 last_received_ts = 77.655647 last_seq = 89 current_ts = 77.673164 current_received_ts = 77.672363 current_seq = 90 count = 86 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 59us (kms_flip:2070) DEBUG: name = flip last_ts = 77.673164 last_received_ts = 77.672363 last_seq = 90 current_ts = 77.689888 current_received_ts = 77.689095 current_seq = 91 count = 87 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 77.689888 last_received_ts = 77.689095 last_seq = 91 current_ts = 77.706619 current_received_ts = 77.705833 current_seq = 92 count = 88 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 77.706619 last_received_ts = 77.705833 last_seq = 92 current_ts = 77.723351 current_received_ts = 77.722542 current_seq = 93 count = 89 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.723351 last_received_ts = 77.722542 last_seq = 93 current_ts = 77.740082 current_received_ts = 77.739273 current_seq = 94 count = 90 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 60us (kms_flip:2070) DEBUG: name = flip last_ts = 77.740082 last_received_ts = 77.739273 last_seq = 94 current_ts = 77.756805 current_received_ts = 77.756058 current_seq = 95 count = 91 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 56us (kms_flip:2070) DEBUG: name = flip last_ts = 77.756805 last_received_ts = 77.756058 last_seq = 95 current_ts = 77.773537 current_received_ts = 77.772751 current_seq = 96 count = 92 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 43us (kms_flip:2070) DEBUG: name = flip last_ts = 77.773537 last_received_ts = 77.772751 last_seq = 96 current_ts = 77.790268 current_received_ts = 77.789482 current_seq = 97 count = 93 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 56us (kms_flip:2070) DEBUG: name = flip last_ts = 77.790268 last_received_ts = 77.789482 last_seq = 97 current_ts = 77.806999 current_received_ts = 77.806190 current_seq = 98 count = 94 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 61us (kms_flip:2070) DEBUG: name = flip last_ts = 77.806999 last_received_ts = 77.806190 last_seq = 98 current_ts = 77.823723 current_received_ts = 77.822945 current_seq = 99 count = 95 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 84us (kms_flip:2070) DEBUG: name = flip last_ts = 77.823723 last_received_ts = 77.822945 last_seq = 99 current_ts = 77.840454 current_received_ts = 77.839676 current_seq = 100 count = 96 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 40us (kms_flip:2070) DEBUG: name = flip last_ts = 77.840454 last_received_ts = 77.839676 last_seq = 100 current_ts = 77.857185 current_received_ts = 77.856392 current_seq = 101 count = 97 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.857185 last_received_ts = 77.856392 last_seq = 101 current_ts = 77.873917 current_received_ts = 77.873108 current_seq = 102 count = 98 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.873917 last_received_ts = 77.873108 last_seq = 102 current_ts = 77.890640 current_received_ts = 77.889877 current_seq = 103 count = 99 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.890640 last_received_ts = 77.889877 last_seq = 103 current_ts = 77.907372 current_received_ts = 77.906593 current_seq = 104 count = 100 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 62us (kms_flip:2070) DEBUG: name = flip last_ts = 77.907372 last_received_ts = 77.906593 last_seq = 104 current_ts = 77.924103 current_received_ts = 77.923294 current_seq = 105 count = 101 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 52us (kms_flip:2070) DEBUG: name = flip last_ts = 77.924103 last_received_ts = 77.923294 last_seq = 105 current_ts = 77.940834 current_received_ts = 77.940056 current_seq = 106 count = 102 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 58us (kms_flip:2070) DEBUG: name = flip last_ts = 77.940834 last_received_ts = 77.940056 last_seq = 106 current_ts = 77.957558 current_received_ts = 77.956779 current_seq = 107 count = 103 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.957558 last_received_ts = 77.956779 last_seq = 107 current_ts = 77.974289 current_received_ts = 77.973511 current_seq = 108 count = 104 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 59us (kms_flip:2070) DEBUG: name = flip last_ts = 77.974289 last_received_ts = 77.973511 last_seq = 108 current_ts = 77.991020 current_received_ts = 77.990219 current_seq = 109 count = 105 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 77.991020 last_received_ts = 77.990219 last_seq = 109 current_ts = 78.007759 current_received_ts = 78.006966 current_seq = 110 count = 106 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 75us (kms_flip:2070) DEBUG: name = flip last_ts = 78.007759 last_received_ts = 78.006966 last_seq = 110 current_ts = 78.024483 current_received_ts = 78.023674 current_seq = 111 count = 107 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 42us (kms_flip:2070) DEBUG: name = flip last_ts = 78.024483 last_received_ts = 78.023674 last_seq = 111 current_ts = 78.041214 current_received_ts = 78.040428 current_seq = 112 count = 108 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 78.041214 last_received_ts = 78.040428 last_seq = 112 current_ts = 78.057938 current_received_ts = 78.057144 current_seq = 113 count = 109 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 78.057938 last_received_ts = 78.057144 last_seq = 113 current_ts = 78.074669 current_received_ts = 78.073891 current_seq = 114 count = 110 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 57us (kms_flip:2070) DEBUG: name = flip last_ts = 78.074669 last_received_ts = 78.073891 last_seq = 114 current_ts = 78.091400 current_received_ts = 78.090622 current_seq = 115 count = 111 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 57us (kms_flip:2070) DEBUG: name = flip last_ts = 78.091400 last_received_ts = 78.090622 last_seq = 115 current_ts = 78.108131 current_received_ts = 78.107323 current_seq = 116 count = 112 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 78.108131 last_received_ts = 78.107323 last_seq = 116 current_ts = 78.124855 current_received_ts = 78.124069 current_seq = 117 count = 113 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 60us (kms_flip:2070) DEBUG: name = flip last_ts = 78.124855 last_received_ts = 78.124069 last_seq = 117 current_ts = 78.141586 current_received_ts = 78.140808 current_seq = 118 count = 114 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 64us (kms_flip:2070) DEBUG: name = flip last_ts = 78.141586 last_received_ts = 78.140808 last_seq = 118 current_ts = 78.158318 current_received_ts = 78.157509 current_seq = 119 count = 115 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 48us (kms_flip:2070) DEBUG: name = flip last_ts = 78.158318 last_received_ts = 78.157509 last_seq = 119 current_ts = 78.175049 current_received_ts = 78.174225 current_seq = 120 count = 116 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 78.175049 last_received_ts = 78.174225 last_seq = 120 current_ts = 78.191772 current_received_ts = 78.190994 current_seq = 121 count = 117 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 78.191772 last_received_ts = 78.190994 last_seq = 121 current_ts = 78.208504 current_received_ts = 78.207726 current_seq = 122 count = 118 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 60us (kms_flip:2070) DEBUG: name = flip last_ts = 78.208504 last_received_ts = 78.207726 last_seq = 122 current_ts = 78.225235 current_received_ts = 78.224449 current_seq = 123 count = 119 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 42us (kms_flip:2070) DEBUG: name = flip last_ts = 78.225235 last_received_ts = 78.224449 last_seq = 123 current_ts = 78.241966 current_received_ts = 78.241165 current_seq = 124 count = 120 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 61us (kms_flip:2070) DEBUG: name = flip last_ts = 78.241966 last_received_ts = 78.241165 last_seq = 124 current_ts = 78.258698 current_received_ts = 78.257912 current_seq = 125 count = 121 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 56us (kms_flip:2070) DEBUG: name = flip last_ts = 78.258698 last_received_ts = 78.257912 last_seq = 125 current_ts = 78.275421 current_received_ts = 78.274651 current_seq = 126 count = 122 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 78.275421 last_received_ts = 78.274651 last_seq = 126 current_ts = 78.292152 current_received_ts = 78.291359 current_seq = 127 count = 123 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 41us (kms_flip:2070) DEBUG: name = flip last_ts = 78.292152 last_received_ts = 78.291359 last_seq = 127 current_ts = 78.308884 current_received_ts = 78.308090 current_seq = 128 count = 124 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 62us (kms_flip:2070) DEBUG: name = flip last_ts = 78.308884 last_received_ts = 78.308090 last_seq = 128 current_ts = 78.325607 current_received_ts = 78.324829 current_seq = 129 count = 125 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 78.325607 last_received_ts = 78.324829 last_seq = 129 current_ts = 78.342346 current_received_ts = 78.341560 current_seq = 130 count = 126 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 59us (kms_flip:2070) DEBUG: name = flip last_ts = 78.342346 last_received_ts = 78.341560 last_seq = 130 current_ts = 78.359077 current_received_ts = 78.358276 current_seq = 131 count = 127 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 46us (kms_flip:2070) DEBUG: name = flip last_ts = 78.359077 last_received_ts = 78.358276 last_seq = 131 current_ts = 78.375801 current_received_ts = 78.375038 current_seq = 132 count = 128 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 78.375801 last_received_ts = 78.375038 last_seq = 132 current_ts = 78.392532 current_received_ts = 78.391747 current_seq = 133 count = 129 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 49us (kms_flip:2070) DEBUG: name = flip last_ts = 78.392532 last_received_ts = 78.391747 last_seq = 133 current_ts = 78.409248 current_received_ts = 78.408478 current_seq = 134 count = 130 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 56us (kms_flip:2070) DEBUG: name = flip last_ts = 78.409248 last_received_ts = 78.408478 last_seq = 134 current_ts = 78.425980 current_received_ts = 78.425179 current_seq = 135 count = 131 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 60us (kms_flip:2070) DEBUG: name = flip last_ts = 78.425980 last_received_ts = 78.425179 last_seq = 135 current_ts = 78.442703 current_received_ts = 78.441895 current_seq = 136 count = 132 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 59us (kms_flip:2070) DEBUG: name = flip last_ts = 78.442703 last_received_ts = 78.441895 last_seq = 136 current_ts = 78.459419 current_received_ts = 78.458641 current_seq = 137 count = 133 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 52us (kms_flip:2070) DEBUG: name = flip last_ts = 78.459419 last_received_ts = 78.458641 last_seq = 137 current_ts = 78.476143 current_received_ts = 78.475357 current_seq = 138 count = 134 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 55us (kms_flip:2070) DEBUG: name = flip last_ts = 78.476143 last_received_ts = 78.475357 last_seq = 138 current_ts = 78.492859 current_received_ts = 78.492065 current_seq = 139 count = 135 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 78.492859 last_received_ts = 78.492065 last_seq = 139 current_ts = 78.509583 current_received_ts = 78.508804 current_seq = 140 count = 136 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 78.509583 last_received_ts = 78.508804 last_seq = 140 current_ts = 78.526299 current_received_ts = 78.525520 current_seq = 141 count = 137 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 78.526299 last_received_ts = 78.525520 last_seq = 141 current_ts = 78.543030 current_received_ts = 78.542221 current_seq = 142 count = 138 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 78.543030 last_received_ts = 78.542221 last_seq = 142 current_ts = 78.559746 current_received_ts = 78.558945 current_seq = 143 count = 139 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 95us (kms_flip:2070) DEBUG: name = flip last_ts = 78.559746 last_received_ts = 78.558945 last_seq = 143 current_ts = 78.576469 current_received_ts = 78.575676 current_seq = 144 count = 140 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 78.576469 last_received_ts = 78.575676 last_seq = 144 current_ts = 78.593193 current_received_ts = 78.592400 current_seq = 145 count = 141 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 78.593193 last_received_ts = 78.592400 last_seq = 145 current_ts = 78.609909 current_received_ts = 78.609116 current_seq = 146 count = 142 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 53us (kms_flip:2070) DEBUG: name = flip last_ts = 78.609909 last_received_ts = 78.609116 last_seq = 146 current_ts = 78.626633 current_received_ts = 78.625854 current_seq = 147 count = 143 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 58us (kms_flip:2070) DEBUG: name = flip last_ts = 78.626633 last_received_ts = 78.625854 last_seq = 147 current_ts = 78.643349 current_received_ts = 78.642578 current_seq = 148 count = 144 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 52us (kms_flip:2070) DEBUG: name = flip last_ts = 78.643349 last_received_ts = 78.642578 last_seq = 148 current_ts = 78.660080 current_received_ts = 78.659271 current_seq = 149 count = 145 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 78.660080 last_received_ts = 78.659271 last_seq = 149 current_ts = 78.676796 current_received_ts = 78.676033 current_seq = 150 count = 146 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 78.676796 last_received_ts = 78.676033 last_seq = 150 current_ts = 78.693520 current_received_ts = 78.692719 current_seq = 151 count = 147 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 78.693520 last_received_ts = 78.692719 last_seq = 151 current_ts = 78.710236 current_received_ts = 78.709465 current_seq = 152 count = 148 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 54us (kms_flip:2070) DEBUG: name = flip last_ts = 78.710236 last_received_ts = 78.709465 last_seq = 152 current_ts = 78.726967 current_received_ts = 78.726166 current_seq = 153 count = 149 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 59us (kms_flip:2070) DEBUG: name = flip last_ts = 78.726967 last_received_ts = 78.726166 last_seq = 153 current_ts = 78.743683 current_received_ts = 78.742935 current_seq = 154 count = 150 seq_step = 1 (kms_flip:2070) DEBUG: Vblank took 1660us (kms_flip:2070) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:2070) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2070) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:2070) igt_core-INFO: Stack trace: (kms_flip:2070) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2070) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:2070) igt_core-INFO: #2 ../tests/kms_flip.c:1889 run_test() (kms_flip:2070) igt_core-INFO: #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045() (kms_flip:2070) igt_core-INFO: #4 ../tests/kms_flip.c:2045 main() (kms_flip:2070) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2070) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2070) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (3.780s)
Dmesg	<6> [74.761957] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [74.764377] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:244] <7> [74.766025] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:247] <7> [74.776440] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [74.776848] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [74.777189] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [74.834816] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:88:pipe A] <7> [74.834898] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [74.835044] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [74.835165] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [74.835283] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [74.835398] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [74.835506] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [74.835607] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [74.835704] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [74.835798] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [74.835893] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [74.835985] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [74.836092] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [74.836198] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [74.836303] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [74.836394] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [74.836480] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [74.836569] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [74.836656] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [74.836737] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [74.836816] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [74.836908] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [74.836992] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [74.837094] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [74.837194] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [74.837292] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [74.837378] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [74.837472] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [74.837568] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [74.837662] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [74.837757] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [74.837837] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [74.837909] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [74.837980] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [74.838065] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [74.838159] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [74.838251] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [74.838337] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [74.838406] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [74.838478] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:88:pipe A] fastset requirement not met, forcing full modeset <7> [74.838574] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [74.838642] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:88:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [74.838729] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:83:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [74.838812] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:88:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [74.838899] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [74.838980] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [74.839147] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [74.839274] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:88:pipe A] enable: no [modeset] <7> [74.839374] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:33:plane 1A] fb: [NOFB], visible: no <7> [74.839473] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:43:plane 2A] fb: [NOFB], visible: no <7> [74.839571] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:53:plane 3A] fb: [NOFB], visible: no <7> [74.839653] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:63:plane 4A] fb: [NOFB], visible: no <7> [74.839727] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:73:plane 5A] fb: [NOFB], visible: no <7> [74.839800] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:83:cursor A] fb: [NOFB], visible: no <7> [74.839926] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [74.840040] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [74.840303] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [74.840382] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [75.048100] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:208:eDP-1] set backlight PWM = 0 <7> [75.048631] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [75.059362] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 turn panel power off <7> [75.059916] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 wait for panel power off time <7> [75.060427] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [75.111807] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [75.112318] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [75.112452] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [75.112918] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:207:DDI A/PHY A] - short <7> [75.112937] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:207:DDI A/PHY A] <7> [75.113300] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DDI TC1/PHY TC1] <7> [75.113499] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:207:DDI A/PHY A] <7> [75.113703] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:218:DP-MST A] <7> [75.114108] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:219:DP-MST B] <7> [75.114496] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:220:DP-MST C] <7> [75.114871] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DDI TC2/PHY TC2] <7> [75.115276] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:230:DP-MST A] <7> [75.115684] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:231:DP-MST B] <7> [75.116052] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:232:DP-MST C] <7> [75.116422] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DDI TC3/PHY TC3] <7> [75.116843] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:238:DP-MST A] <7> [75.117197] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:239:DP-MST B] <7> [75.117616] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:240:DP-MST C] <7> [75.117961] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:208:eDP-1] <7> [75.118385] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [75.118772] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [75.119152] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [75.119722] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [75.120240] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:88:pipe A] <7> [75.120657] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [75.121056] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [75.121387] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [75.122305] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:146:pipe B] <7> [75.122751] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:204:pipe C] <7> [75.123072] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:146:pipe B] <7> [75.123149] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:208:eDP-1] <7> [75.123371] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:208:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [75.123869] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:207:DDI A/PHY A][CRTC:146:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 max link_bpp 30.0000 <7> [75.124249] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 link rate required 1303913 available 1728000 <7> [75.124723] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:146:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [75.125097] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:207:DDI A/PHY A] [CRTC:146:pipe B] <7> [75.125490] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [75.125900] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [75.126228] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [75.126584] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [75.126890] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [75.127186] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [75.127485] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [75.127772] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [75.128030] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [75.128287] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [75.128581] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [75.128813] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [75.129030] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [75.129256] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [75.129491] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [75.129697] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [75.129904] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [75.130090] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [75.130272] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [75.130536] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [75.130748] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [75.130923] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [75.131104] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [75.131268] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [75.131441] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [75.131589] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [75.131730] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [75.131903] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [75.132067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [75.132232] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [75.132398] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [75.132533] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [75.132666] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [75.132793] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [75.132918] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in dpll_hw_state.cx0pll C20 <7> [75.133034] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] expected: <7> [75.133151] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c20pll_hw_state: <7> [75.133281] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx[0] = 0x0000, tx[1] = 0x0000, tx[2] = 0x0000 <7> [75.133417] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] cmn[0] = 0x0000, cmn[1] = 0x0000, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [75.133557] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[0] = 0x0000 <7> [75.133683] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[1] = 0x0000 <7> [75.133792] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[2] = 0x0000 <7> [75.133898] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[3] = 0x0000 <7> [75.134004] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[4] = 0x0000 <7> [75.134106] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[5] = 0x0000 <7> [75.134210] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[6] = 0x0000 <7> [75.134320] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[7] = 0x0000 <7> [75.134424] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[8] = 0x0000 <7> [75.134527] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[9] = 0x0000 <7> [75.134624] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] found: <7> [75.134716] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_hw_state: fracen: no, <7> [75.134808] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] multiplier: 225, tx_clk_div: 1. <7> [75.134898] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_rawhw_state: <7> [75.134984] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx: 0x10, cmn: 0x21 <7> [75.135068] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [75.135152] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [75.135233] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [75.135328] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [75.135432] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [75.135536] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [75.135636] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [75.135716] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [75.135795] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [75.135875] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:146:pipe B] fastset requirement not met, forcing full modeset <7> [75.135984] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [75.136057] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:146:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [75.136157] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:91:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [75.136240] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:141:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [75.136339] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:91:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [75.136416] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:91:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [75.136490] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:91:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [75.136569] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:91:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [75.136655] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:146:pipe B] data rate 1390840 num active planes 1 <7> [75.136749] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [75.136830] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [75.136915] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [75.136997] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [75.137082] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [75.137164] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:146:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [75.137272] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [75.137383] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [75.137494] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [75.137613] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:146:pipe B] enable: yes [modeset] <7> [75.137700] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [75.137785] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [75.137884] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [75.137983] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [75.138080] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [75.138163] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [75.138234] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [75.138336] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [75.138429] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [75.138521] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [75.138602] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [75.138678] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [75.138753] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [75.138828] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [75.138900] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [75.138968] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [75.139036] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [75.139108] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [75.139184] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [75.139264] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [75.139355] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [75.139445] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [75.139534] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [75.139612] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [75.139680] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [75.139752] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [75.139830] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [75.139919] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [75.140013] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855 <7> [75.140104] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [75.140194] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [75.140304] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [75.140317] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [75.140397] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [75.140486] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0x69780, dpll_md: 0x42110, fp0: 0x1a2, fp1: 0x1000000 <7> [75.140472] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [75.140576] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [75.140604] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [75.140667] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [75.140756] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [75.140756] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [75.140844] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [75.140933] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [75.141021] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [75.141102] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [75.141176] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [75.141254] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [75.141343] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [75.141430] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [75.141517] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [75.141586] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [75.141653] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:91:plane 1B] fb: [FB:244] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [75.141725] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [75.141797] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [75.141869] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:101:plane 2B] fb: [NOFB], visible: no <7> [75.141941] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:111:plane 3B] fb: [NOFB], visible: no <7> [75.142012] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:121:plane 4B] fb: [NOFB], visible: no <7> [75.142081] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:131:plane 5B] fb: [NOFB], visible: no <7> [75.142149] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:141:cursor B] fb: [NOFB], visible: no <7> [75.142566] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [75.142648] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [75.142881] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [75.143015] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [75.143159] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [75.143312] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [75.143421] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [75.143527] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [75.143605] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:207:DDI A/PHY A] <7> [75.143672] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DDI TC1/PHY TC1] <7> [75.143737] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:218:DP-MST A] <7> [75.143801] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:219:DP-MST B] <7> [75.143864] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:220:DP-MST C] <7> [75.143925] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DDI TC2/PHY TC2] <7> [75.143987] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:230:DP-MST A] <7> [75.144048] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:231:DP-MST B] <7> [75.144108] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:232:DP-MST C] <7> [75.144166] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DDI TC3/PHY TC3] <7> [75.144232] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:238:DP-MST A] <7> [75.144309] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:239:DP-MST B] <7> [75.144385] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:240:DP-MST C] <7> [75.144458] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [75.144628] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [75.144690] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [75.144796] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [75.146130] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 turn panel power on <7> [75.146217] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 wait for panel power cycle (466 ms remaining) <7> [75.147209] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [75.147389] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:207:DDI A/PHY A] - long <7> [75.147486] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [75.147612] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:207:DDI A/PHY A] <7> [75.613139] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [75.704988] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [75.705408] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 wait for panel power on <7> [75.705762] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [75.741569] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [75.741908] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:207:DDI A/PHY A] - long <7> [75.742213] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [75.742563] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:207:DDI A/PHY A] <7> [75.914244] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [75.916501] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 turning VDD on <7> [75.916944] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [75.919452] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [75.920867] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [75.921951] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [75.923472] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [75.924957] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [75.926316] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Clock recovery OK <7> [75.926904] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [75.928624] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [75.929053] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:208:eDP-1][ENCODER:207:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [75.930013] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [75.930677] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [75.931121] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [75.931718] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:208:eDP-1] set backlight PWM = 13892 <7> [75.947558] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [75.949453] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:208:eDP-1] <7> [75.950030] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:146:pipe B] <7> [78.464629] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 turning VDD off <7> [78.465172] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:207:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [78.497501] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [78.498030] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [78.498507] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [78.541851] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

3.78 seconds

Hostname

shard-lnl-4

Igt-Version

IGT-Version: 2.2-geb100acf0 (x86_64) (Linux: 6.18.0-rc5-lgci-xe-xe-4099-3462442c8cd967b22+ x86_64)

Out

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

Err

Starting dynamic subtest: B-eDP1
(kms_flip:2070) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2070) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2070) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.719200
last_received_ts = 76.718384
last_seq = 33
current_ts = 76.735939
current_received_ts = 76.735146
current_seq = 34
count = 30
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 77us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.735939
last_received_ts = 76.735146
last_seq = 34
current_ts = 76.752670
current_received_ts = 76.751884
current_seq = 35
count = 31
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.752670
last_received_ts = 76.751884
last_seq = 35
current_ts = 76.769409
current_received_ts = 76.768623
current_seq = 36
count = 32
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 56us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.769409
last_received_ts = 76.768623
last_seq = 36
current_ts = 76.786156
current_received_ts = 76.785355
current_seq = 37
count = 33
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.786156
last_received_ts = 76.785355
last_seq = 37
current_ts = 76.802887
current_received_ts = 76.802094
current_seq = 38
count = 34
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 57us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.802887
last_received_ts = 76.802094
last_seq = 38
current_ts = 76.819626
current_received_ts = 76.818840
current_seq = 39
count = 35
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 56us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.819626
last_received_ts = 76.818840
last_seq = 39
current_ts = 76.836365
current_received_ts = 76.835579
current_seq = 40
count = 36
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 43us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.836365
last_received_ts = 76.835579
last_seq = 40
current_ts = 76.853111
current_received_ts = 76.852303
current_seq = 41
count = 37
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 56us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.853111
last_received_ts = 76.852303
last_seq = 41
current_ts = 76.869843
current_received_ts = 76.869057
current_seq = 42
count = 38
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.869843
last_received_ts = 76.869057
last_seq = 42
current_ts = 76.886581
current_received_ts = 76.885773
current_seq = 43
count = 39
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 43us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.886581
last_received_ts = 76.885773
last_seq = 43
current_ts = 76.903320
current_received_ts = 76.902527
current_seq = 44
count = 40
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 67us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.903320
last_received_ts = 76.902527
last_seq = 44
current_ts = 76.920059
current_received_ts = 76.919250
current_seq = 45
count = 41
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.920059
last_received_ts = 76.919250
last_seq = 45
current_ts = 76.936798
current_received_ts = 76.936028
current_seq = 46
count = 42
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.936798
last_received_ts = 76.936028
last_seq = 46
current_ts = 76.953545
current_received_ts = 76.952759
current_seq = 47
count = 43
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.953545
last_received_ts = 76.952759
last_seq = 47
current_ts = 76.970284
current_received_ts = 76.969498
current_seq = 48
count = 44
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 60us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.970284
last_received_ts = 76.969498
last_seq = 48
current_ts = 76.987015
current_received_ts = 76.986214
current_seq = 49
count = 45
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 76.987015
last_received_ts = 76.986214
last_seq = 49
current_ts = 77.003761
current_received_ts = 77.002975
current_seq = 50
count = 46
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 70us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.003761
last_received_ts = 77.002975
last_seq = 50
current_ts = 77.020493
current_received_ts = 77.019707
current_seq = 51
count = 47
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.020493
last_received_ts = 77.019707
last_seq = 51
current_ts = 77.037231
current_received_ts = 77.036446
current_seq = 52
count = 48
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.037231
last_received_ts = 77.036446
last_seq = 52
current_ts = 77.053978
current_received_ts = 77.053169
current_seq = 53
count = 49
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.053978
last_received_ts = 77.053169
last_seq = 53
current_ts = 77.070717
current_received_ts = 77.069916
current_seq = 54
count = 50
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.070717
last_received_ts = 77.069916
last_seq = 54
current_ts = 77.087456
current_received_ts = 77.086639
current_seq = 55
count = 51
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.087456
last_received_ts = 77.086639
last_seq = 55
current_ts = 77.104195
current_received_ts = 77.103416
current_seq = 56
count = 52
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 52us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.104195
last_received_ts = 77.103416
last_seq = 56
current_ts = 77.120934
current_received_ts = 77.120140
current_seq = 57
count = 53
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.120934
last_received_ts = 77.120140
last_seq = 57
current_ts = 77.137665
current_received_ts = 77.136879
current_seq = 58
count = 54
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.137665
last_received_ts = 77.136879
last_seq = 58
current_ts = 77.154411
current_received_ts = 77.153625
current_seq = 59
count = 55
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 57us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.154411
last_received_ts = 77.153625
last_seq = 59
current_ts = 77.171150
current_received_ts = 77.170349
current_seq = 60
count = 56
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.171150
last_received_ts = 77.170349
last_seq = 60
current_ts = 77.187881
current_received_ts = 77.187088
current_seq = 61
count = 57
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.187881
last_received_ts = 77.187088
last_seq = 61
current_ts = 77.204620
current_received_ts = 77.203842
current_seq = 62
count = 58
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.204620
last_received_ts = 77.203842
last_seq = 62
current_ts = 77.221367
current_received_ts = 77.220573
current_seq = 63
count = 59
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 42us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.221367
last_received_ts = 77.220573
last_seq = 63
current_ts = 77.238106
current_received_ts = 77.237297
current_seq = 64
count = 60
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 52us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.238106
last_received_ts = 77.237297
last_seq = 64
current_ts = 77.254845
current_received_ts = 77.254044
current_seq = 65
count = 61
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 58us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.254845
last_received_ts = 77.254044
last_seq = 65
current_ts = 77.271584
current_received_ts = 77.270813
current_seq = 66
count = 62
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 58us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.271584
last_received_ts = 77.270813
last_seq = 66
current_ts = 77.288322
current_received_ts = 77.287529
current_seq = 67
count = 63
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.288322
last_received_ts = 77.287529
last_seq = 67
current_ts = 77.305061
current_received_ts = 77.304253
current_seq = 68
count = 64
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 62us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.305061
last_received_ts = 77.304253
last_seq = 68
current_ts = 77.321800
current_received_ts = 77.321022
current_seq = 69
count = 65
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 50us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.321800
last_received_ts = 77.321022
last_seq = 69
current_ts = 77.338539
current_received_ts = 77.337753
current_seq = 70
count = 66
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.338539
last_received_ts = 77.337753
last_seq = 70
current_ts = 77.355278
current_received_ts = 77.354492
current_seq = 71
count = 67
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.355278
last_received_ts = 77.354492
last_seq = 71
current_ts = 77.372017
current_received_ts = 77.371208
current_seq = 72
count = 68
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.372017
last_received_ts = 77.371208
last_seq = 72
current_ts = 77.388756
current_received_ts = 77.387970
current_seq = 73
count = 69
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 67us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.388756
last_received_ts = 77.387970
last_seq = 73
current_ts = 77.405487
current_received_ts = 77.404709
current_seq = 74
count = 70
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 52us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.405487
last_received_ts = 77.404709
last_seq = 74
current_ts = 77.422218
current_received_ts = 77.421410
current_seq = 75
count = 71
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.422218
last_received_ts = 77.421410
last_seq = 75
current_ts = 77.438942
current_received_ts = 77.438164
current_seq = 76
count = 72
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 61us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.438942
last_received_ts = 77.438164
last_seq = 76
current_ts = 77.455673
current_received_ts = 77.454887
current_seq = 77
count = 73
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 56us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.455673
last_received_ts = 77.454887
last_seq = 77
current_ts = 77.472404
current_received_ts = 77.471619
current_seq = 78
count = 74
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.472404
last_received_ts = 77.471619
last_seq = 78
current_ts = 77.489136
current_received_ts = 77.488342
current_seq = 79
count = 75
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 61us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.489136
last_received_ts = 77.488342
last_seq = 79
current_ts = 77.505859
current_received_ts = 77.505066
current_seq = 80
count = 76
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.505859
last_received_ts = 77.505066
last_seq = 80
current_ts = 77.522591
current_received_ts = 77.521805
current_seq = 81
count = 77
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 56us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.522591
last_received_ts = 77.521805
last_seq = 81
current_ts = 77.539322
current_received_ts = 77.538536
current_seq = 82
count = 78
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 42us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.539322
last_received_ts = 77.538536
last_seq = 82
current_ts = 77.556053
current_received_ts = 77.555244
current_seq = 83
count = 79
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 56us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.556053
last_received_ts = 77.555244
last_seq = 83
current_ts = 77.572784
current_received_ts = 77.571976
current_seq = 84
count = 80
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 64us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.572784
last_received_ts = 77.571976
last_seq = 84
current_ts = 77.589508
current_received_ts = 77.588715
current_seq = 85
count = 81
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 56us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.589508
last_received_ts = 77.588715
last_seq = 85
current_ts = 77.606239
current_received_ts = 77.605453
current_seq = 86
count = 82
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 57us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.606239
last_received_ts = 77.605453
last_seq = 86
current_ts = 77.622971
current_received_ts = 77.622162
current_seq = 87
count = 83
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.622971
last_received_ts = 77.622162
last_seq = 87
current_ts = 77.639702
current_received_ts = 77.638916
current_seq = 88
count = 84
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.639702
last_received_ts = 77.638916
last_seq = 88
current_ts = 77.656425
current_received_ts = 77.655647
current_seq = 89
count = 85
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 59us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.656425
last_received_ts = 77.655647
last_seq = 89
current_ts = 77.673164
current_received_ts = 77.672363
current_seq = 90
count = 86
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 59us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.673164
last_received_ts = 77.672363
last_seq = 90
current_ts = 77.689888
current_received_ts = 77.689095
current_seq = 91
count = 87
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.689888
last_received_ts = 77.689095
last_seq = 91
current_ts = 77.706619
current_received_ts = 77.705833
current_seq = 92
count = 88
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.706619
last_received_ts = 77.705833
last_seq = 92
current_ts = 77.723351
current_received_ts = 77.722542
current_seq = 93
count = 89
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.723351
last_received_ts = 77.722542
last_seq = 93
current_ts = 77.740082
current_received_ts = 77.739273
current_seq = 94
count = 90
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 60us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.740082
last_received_ts = 77.739273
last_seq = 94
current_ts = 77.756805
current_received_ts = 77.756058
current_seq = 95
count = 91
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 56us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.756805
last_received_ts = 77.756058
last_seq = 95
current_ts = 77.773537
current_received_ts = 77.772751
current_seq = 96
count = 92
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 43us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.773537
last_received_ts = 77.772751
last_seq = 96
current_ts = 77.790268
current_received_ts = 77.789482
current_seq = 97
count = 93
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 56us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.790268
last_received_ts = 77.789482
last_seq = 97
current_ts = 77.806999
current_received_ts = 77.806190
current_seq = 98
count = 94
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 61us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.806999
last_received_ts = 77.806190
last_seq = 98
current_ts = 77.823723
current_received_ts = 77.822945
current_seq = 99
count = 95
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 84us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.823723
last_received_ts = 77.822945
last_seq = 99
current_ts = 77.840454
current_received_ts = 77.839676
current_seq = 100
count = 96
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 40us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.840454
last_received_ts = 77.839676
last_seq = 100
current_ts = 77.857185
current_received_ts = 77.856392
current_seq = 101
count = 97
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.857185
last_received_ts = 77.856392
last_seq = 101
current_ts = 77.873917
current_received_ts = 77.873108
current_seq = 102
count = 98
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.873917
last_received_ts = 77.873108
last_seq = 102
current_ts = 77.890640
current_received_ts = 77.889877
current_seq = 103
count = 99
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.890640
last_received_ts = 77.889877
last_seq = 103
current_ts = 77.907372
current_received_ts = 77.906593
current_seq = 104
count = 100
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 62us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.907372
last_received_ts = 77.906593
last_seq = 104
current_ts = 77.924103
current_received_ts = 77.923294
current_seq = 105
count = 101
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 52us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.924103
last_received_ts = 77.923294
last_seq = 105
current_ts = 77.940834
current_received_ts = 77.940056
current_seq = 106
count = 102
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 58us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.940834
last_received_ts = 77.940056
last_seq = 106
current_ts = 77.957558
current_received_ts = 77.956779
current_seq = 107
count = 103
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.957558
last_received_ts = 77.956779
last_seq = 107
current_ts = 77.974289
current_received_ts = 77.973511
current_seq = 108
count = 104
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 59us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.974289
last_received_ts = 77.973511
last_seq = 108
current_ts = 77.991020
current_received_ts = 77.990219
current_seq = 109
count = 105
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 77.991020
last_received_ts = 77.990219
last_seq = 109
current_ts = 78.007759
current_received_ts = 78.006966
current_seq = 110
count = 106
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 75us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.007759
last_received_ts = 78.006966
last_seq = 110
current_ts = 78.024483
current_received_ts = 78.023674
current_seq = 111
count = 107
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 42us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.024483
last_received_ts = 78.023674
last_seq = 111
current_ts = 78.041214
current_received_ts = 78.040428
current_seq = 112
count = 108
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.041214
last_received_ts = 78.040428
last_seq = 112
current_ts = 78.057938
current_received_ts = 78.057144
current_seq = 113
count = 109
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.057938
last_received_ts = 78.057144
last_seq = 113
current_ts = 78.074669
current_received_ts = 78.073891
current_seq = 114
count = 110
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 57us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.074669
last_received_ts = 78.073891
last_seq = 114
current_ts = 78.091400
current_received_ts = 78.090622
current_seq = 115
count = 111
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 57us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.091400
last_received_ts = 78.090622
last_seq = 115
current_ts = 78.108131
current_received_ts = 78.107323
current_seq = 116
count = 112
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.108131
last_received_ts = 78.107323
last_seq = 116
current_ts = 78.124855
current_received_ts = 78.124069
current_seq = 117
count = 113
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 60us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.124855
last_received_ts = 78.124069
last_seq = 117
current_ts = 78.141586
current_received_ts = 78.140808
current_seq = 118
count = 114
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 64us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.141586
last_received_ts = 78.140808
last_seq = 118
current_ts = 78.158318
current_received_ts = 78.157509
current_seq = 119
count = 115
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 48us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.158318
last_received_ts = 78.157509
last_seq = 119
current_ts = 78.175049
current_received_ts = 78.174225
current_seq = 120
count = 116
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.175049
last_received_ts = 78.174225
last_seq = 120
current_ts = 78.191772
current_received_ts = 78.190994
current_seq = 121
count = 117
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.191772
last_received_ts = 78.190994
last_seq = 121
current_ts = 78.208504
current_received_ts = 78.207726
current_seq = 122
count = 118
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 60us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.208504
last_received_ts = 78.207726
last_seq = 122
current_ts = 78.225235
current_received_ts = 78.224449
current_seq = 123
count = 119
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 42us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.225235
last_received_ts = 78.224449
last_seq = 123
current_ts = 78.241966
current_received_ts = 78.241165
current_seq = 124
count = 120
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 61us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.241966
last_received_ts = 78.241165
last_seq = 124
current_ts = 78.258698
current_received_ts = 78.257912
current_seq = 125
count = 121
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 56us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.258698
last_received_ts = 78.257912
last_seq = 125
current_ts = 78.275421
current_received_ts = 78.274651
current_seq = 126
count = 122
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.275421
last_received_ts = 78.274651
last_seq = 126
current_ts = 78.292152
current_received_ts = 78.291359
current_seq = 127
count = 123
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 41us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.292152
last_received_ts = 78.291359
last_seq = 127
current_ts = 78.308884
current_received_ts = 78.308090
current_seq = 128
count = 124
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 62us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.308884
last_received_ts = 78.308090
last_seq = 128
current_ts = 78.325607
current_received_ts = 78.324829
current_seq = 129
count = 125
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.325607
last_received_ts = 78.324829
last_seq = 129
current_ts = 78.342346
current_received_ts = 78.341560
current_seq = 130
count = 126
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 59us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.342346
last_received_ts = 78.341560
last_seq = 130
current_ts = 78.359077
current_received_ts = 78.358276
current_seq = 131
count = 127
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 46us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.359077
last_received_ts = 78.358276
last_seq = 131
current_ts = 78.375801
current_received_ts = 78.375038
current_seq = 132
count = 128
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.375801
last_received_ts = 78.375038
last_seq = 132
current_ts = 78.392532
current_received_ts = 78.391747
current_seq = 133
count = 129
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 49us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.392532
last_received_ts = 78.391747
last_seq = 133
current_ts = 78.409248
current_received_ts = 78.408478
current_seq = 134
count = 130
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 56us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.409248
last_received_ts = 78.408478
last_seq = 134
current_ts = 78.425980
current_received_ts = 78.425179
current_seq = 135
count = 131
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 60us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.425980
last_received_ts = 78.425179
last_seq = 135
current_ts = 78.442703
current_received_ts = 78.441895
current_seq = 136
count = 132
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 59us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.442703
last_received_ts = 78.441895
last_seq = 136
current_ts = 78.459419
current_received_ts = 78.458641
current_seq = 137
count = 133
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 52us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.459419
last_received_ts = 78.458641
last_seq = 137
current_ts = 78.476143
current_received_ts = 78.475357
current_seq = 138
count = 134
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 55us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.476143
last_received_ts = 78.475357
last_seq = 138
current_ts = 78.492859
current_received_ts = 78.492065
current_seq = 139
count = 135
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.492859
last_received_ts = 78.492065
last_seq = 139
current_ts = 78.509583
current_received_ts = 78.508804
current_seq = 140
count = 136
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.509583
last_received_ts = 78.508804
last_seq = 140
current_ts = 78.526299
current_received_ts = 78.525520
current_seq = 141
count = 137
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.526299
last_received_ts = 78.525520
last_seq = 141
current_ts = 78.543030
current_received_ts = 78.542221
current_seq = 142
count = 138
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.543030
last_received_ts = 78.542221
last_seq = 142
current_ts = 78.559746
current_received_ts = 78.558945
current_seq = 143
count = 139
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 95us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.559746
last_received_ts = 78.558945
last_seq = 143
current_ts = 78.576469
current_received_ts = 78.575676
current_seq = 144
count = 140
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.576469
last_received_ts = 78.575676
last_seq = 144
current_ts = 78.593193
current_received_ts = 78.592400
current_seq = 145
count = 141
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.593193
last_received_ts = 78.592400
last_seq = 145
current_ts = 78.609909
current_received_ts = 78.609116
current_seq = 146
count = 142
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 53us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.609909
last_received_ts = 78.609116
last_seq = 146
current_ts = 78.626633
current_received_ts = 78.625854
current_seq = 147
count = 143
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 58us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.626633
last_received_ts = 78.625854
last_seq = 147
current_ts = 78.643349
current_received_ts = 78.642578
current_seq = 148
count = 144
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 52us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.643349
last_received_ts = 78.642578
last_seq = 148
current_ts = 78.660080
current_received_ts = 78.659271
current_seq = 149
count = 145
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.660080
last_received_ts = 78.659271
last_seq = 149
current_ts = 78.676796
current_received_ts = 78.676033
current_seq = 150
count = 146
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.676796
last_received_ts = 78.676033
last_seq = 150
current_ts = 78.693520
current_received_ts = 78.692719
current_seq = 151
count = 147
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.693520
last_received_ts = 78.692719
last_seq = 151
current_ts = 78.710236
current_received_ts = 78.709465
current_seq = 152
count = 148
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 54us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.710236
last_received_ts = 78.709465
last_seq = 152
current_ts = 78.726967
current_received_ts = 78.726166
current_seq = 153
count = 149
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 59us
(kms_flip:2070) DEBUG: name = flip
last_ts = 78.726967
last_received_ts = 78.726166
last_seq = 153
current_ts = 78.743683
current_received_ts = 78.742935
current_seq = 154
count = 150
seq_step = 1
(kms_flip:2070) DEBUG: Vblank took 1660us
(kms_flip:2070) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:2070) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2070) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2070) igt_core-INFO: Stack trace:
(kms_flip:2070) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2070) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:2070) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:2070) igt_core-INFO:   #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
(kms_flip:2070) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:2070) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2070) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2070) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (3.780s)

Dmesg

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

<7> [74.764377] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:244]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [75.120657] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [75.132918] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:146:pipe B] fastset requirement not met in dpll_hw_state.cx0pll C20

<7> [75.133034] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] expected:

<7> [75.133151] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c20pll_hw_state:

<7> [75.133281] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx[0] = 0x0000, tx[1] = 0x0000, tx[2] = 0x0000

<7> [75.133417] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] cmn[0] = 0x0000, cmn[1] = 0x0000, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [75.133557] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[0] = 0x0000

<7> [75.133683] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[1] = 0x0000

<7> [75.133792] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[2] = 0x0000

<7> [75.133898] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[3] = 0x0000

<7> [75.134004] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[4] = 0x0000

<7> [75.134106] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[5] = 0x0000

<7> [75.134210] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[6] = 0x0000

<7> [75.134320] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[7] = 0x0000

<7> [75.134424] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[8] = 0x0000

<7> [75.134527] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] mplla[9] = 0x0000

<7> [75.134624] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] found:

<7> [75.134716] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_hw_state: fracen: no,

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

<7> [75.134898] xe 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [xe]] c10pll_rawhw_state:

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [75.138336] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0

<7> [75.138429] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [75.139612] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

<7> [75.139680] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

<7> [75.139752] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [75.139830] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa

<7> [75.139919] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [75.140013] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855

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

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

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

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

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

<7> [75.140486] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0x69780, dpll_md: 0x42110, fp0: 0x1a2, fp1: 0x1000000

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [75.143312] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [75.919452] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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