igt@kms_flip@flip-vs-expired-vblank-interruptible@b-dp2 on shard-bmg@IGTPW

Detail	Value
Duration	3.95 seconds
Hostname	shard-bmg-3
Igt-Version	IGT-Version: 2.4-g9187799ba (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5058-21b42374be17d486b-debug+ x86_64)
Out	Starting dynamic subtest: B-DP2 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2074 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-DP2: FAIL (3.953s)
Err	Starting dynamic subtest: B-DP2 [92.758048] (kms_flip:2268) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [92.758174] (kms_flip:2268) CRITICAL: Failed assertion: end - start < 500 [92.758237] (kms_flip:2268) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-DP2 failed. ** DEBUG [90.740345] (kms_flip:2268) DEBUG: Vblank took 26us [90.757056] (kms_flip:2268) DEBUG: name = flip last_ts = 92.252693 last_received_ts = 92.252251 last_seq = 1095 current_ts = 92.269363 current_received_ts = 92.268990 current_seq = 1096 count = 80 seq_step = 1 [90.757112] (kms_flip:2268) DEBUG: Vblank took 51us [90.773649] (kms_flip:2268) DEBUG: name = flip last_ts = 92.269363 last_received_ts = 92.268990 last_seq = 1096 current_ts = 92.286026 current_received_ts = 92.285583 current_seq = 1097 count = 81 seq_step = 1 [90.773680] (kms_flip:2268) DEBUG: Vblank took 27us [90.790315] (kms_flip:2268) DEBUG: name = flip last_ts = 92.286026 last_received_ts = 92.285583 last_seq = 1097 current_ts = 92.302696 current_received_ts = 92.302246 current_seq = 1098 count = 82 seq_step = 1 [90.790345] (kms_flip:2268) DEBUG: Vblank took 26us [90.807059] (kms_flip:2268) DEBUG: name = flip last_ts = 92.302696 last_received_ts = 92.302246 last_seq = 1098 current_ts = 92.319359 current_received_ts = 92.318993 current_seq = 1099 count = 83 seq_step = 1 [90.807127] (kms_flip:2268) DEBUG: Vblank took 32us [90.823651] (kms_flip:2268) DEBUG: name = flip last_ts = 92.319359 last_received_ts = 92.318993 last_seq = 1099 current_ts = 92.336029 current_received_ts = 92.335579 current_seq = 1100 count = 84 seq_step = 1 [90.823682] (kms_flip:2268) DEBUG: Vblank took 26us [90.840319] (kms_flip:2268) DEBUG: name = flip last_ts = 92.336029 last_received_ts = 92.335579 last_seq = 1100 current_ts = 92.352692 current_received_ts = 92.352249 current_seq = 1101 count = 85 seq_step = 1 [90.840349] (kms_flip:2268) DEBUG: Vblank took 26us [90.857062] (kms_flip:2268) DEBUG: name = flip last_ts = 92.352692 last_received_ts = 92.352249 last_seq = 1101 current_ts = 92.369362 current_received_ts = 92.368988 current_seq = 1102 count = 86 seq_step = 1 [90.857123] (kms_flip:2268) DEBUG: Vblank took 30us [90.873653] (kms_flip:2268) DEBUG: name = flip last_ts = 92.369362 last_received_ts = 92.368988 last_seq = 1102 current_ts = 92.386024 current_received_ts = 92.385582 current_seq = 1103 count = 87 seq_step = 1 [90.873684] (kms_flip:2268) DEBUG: Vblank took 26us [90.890391] (kms_flip:2268) DEBUG: name = flip last_ts = 92.386024 last_received_ts = 92.385582 last_seq = 1103 current_ts = 92.402695 current_received_ts = 92.402321 current_seq = 1104 count = 88 seq_step = 1 [90.890420] (kms_flip:2268) DEBUG: Vblank took 25us [90.907136] (kms_flip:2268) DEBUG: name = flip last_ts = 92.402695 last_received_ts = 92.402321 last_seq = 1104 current_ts = 92.419365 current_received_ts = 92.419067 current_seq = 1105 count = 89 seq_step = 1 [90.907165] (kms_flip:2268) DEBUG: Vblank took 25us [90.923802] (kms_flip:2268) DEBUG: name = flip last_ts = 92.419365 last_received_ts = 92.419067 last_seq = 1105 current_ts = 92.436035 current_received_ts = 92.435730 current_seq = 1106 count = 90 seq_step = 1 [90.923832] (kms_flip:2268) DEBUG: Vblank took 25us [90.940354] (kms_flip:2268) DEBUG: name = flip last_ts = 92.436035 last_received_ts = 92.435730 last_seq = 1106 current_ts = 92.452705 current_received_ts = 92.452278 current_seq = 1107 count = 91 seq_step = 1 [90.940383] (kms_flip:2268) DEBUG: Vblank took 25us [90.957144] (kms_flip:2268) DEBUG: name = flip last_ts = 92.452705 last_received_ts = 92.452278 last_seq = 1107 current_ts = 92.469376 current_received_ts = 92.469070 current_seq = 1108 count = 92 seq_step = 1 [90.957174] (kms_flip:2268) DEBUG: Vblank took 25us [90.973804] (kms_flip:2268) DEBUG: name = flip last_ts = 92.469376 last_received_ts = 92.469070 last_seq = 1108 current_ts = 92.486031 current_received_ts = 92.485733 current_seq = 1109 count = 93 seq_step = 1 [90.973834] (kms_flip:2268) DEBUG: Vblank took 25us [90.990470] (kms_flip:2268) DEBUG: name = flip last_ts = 92.486031 last_received_ts = 92.485733 last_seq = 1109 current_ts = 92.502701 current_received_ts = 92.502396 current_seq = 1110 count = 94 seq_step = 1 [90.990500] (kms_flip:2268) DEBUG: Vblank took 25us [91.007138] (kms_flip:2268) DEBUG: name = flip last_ts = 92.502701 last_received_ts = 92.502396 last_seq = 1110 current_ts = 92.519363 current_received_ts = 92.519066 current_seq = 1111 count = 95 seq_step = 1 [91.007169] (kms_flip:2268) DEBUG: Vblank took 25us [91.023810] (kms_flip:2268) DEBUG: name = flip last_ts = 92.519363 last_received_ts = 92.519066 last_seq = 1111 current_ts = 92.536041 current_received_ts = 92.535736 current_seq = 1112 count = 96 seq_step = 1 [91.023840] (kms_flip:2268) DEBUG: Vblank took 26us [91.040470] (kms_flip:2268) DEBUG: name = flip last_ts = 92.536041 last_received_ts = 92.535736 last_seq = 1112 current_ts = 92.552696 current_received_ts = 92.552391 current_seq = 1113 count = 97 seq_step = 1 [91.040509] (kms_flip:2268) DEBUG: Vblank took 24us [91.057140] (kms_flip:2268) DEBUG: name = flip last_ts = 92.552696 last_received_ts = 92.552391 last_seq = 1113 current_ts = 92.569366 current_received_ts = 92.569061 current_seq = 1114 count = 98 seq_step = 1 [91.057175] (kms_flip:2268) DEBUG: Vblank took 25us [91.073809] (kms_flip:2268) DEBUG: name = flip last_ts = 92.569366 last_received_ts = 92.569061 last_seq = 1114 current_ts = 92.586037 current_received_ts = 92.585732 current_seq = 1115 count = 99 seq_step = 1 [91.073838] (kms_flip:2268) DEBUG: Vblank took 26us [91.090483] (kms_flip:2268) DEBUG: name = flip last_ts = 92.586037 last_received_ts = 92.585732 last_seq = 1115 current_ts = 92.602707 current_received_ts = 92.602402 current_seq = 1116 count = 100 seq_step = 1 [91.090513] (kms_flip:2268) DEBUG: Vblank took 25us [91.107141] (kms_flip:2268) DEBUG: name = flip last_ts = 92.602707 last_received_ts = 92.602402 last_seq = 1116 current_ts = 92.619370 current_received_ts = 92.619064 current_seq = 1117 count = 101 seq_step = 1 [91.107170] (kms_flip:2268) DEBUG: Vblank took 25us [91.123736] (kms_flip:2268) DEBUG: name = flip last_ts = 92.619370 last_received_ts = 92.619064 last_seq = 1117 current_ts = 92.636040 current_received_ts = 92.635658 current_seq = 1118 count = 102 seq_step = 1 [91.123764] (kms_flip:2268) DEBUG: Vblank took 24us [91.140407] (kms_flip:2268) DEBUG: name = flip last_ts = 92.636040 last_received_ts = 92.635658 last_seq = 1118 current_ts = 92.652710 current_received_ts = 92.652328 current_seq = 1119 count = 103 seq_step = 1 [91.140436] (kms_flip:2268) DEBUG: Vblank took 26us [91.157143] (kms_flip:2268) DEBUG: name = flip last_ts = 92.652710 last_received_ts = 92.652328 last_seq = 1119 current_ts = 92.669365 current_received_ts = 92.669067 current_seq = 1120 count = 104 seq_step = 1 [91.157173] (kms_flip:2268) DEBUG: Vblank took 25us [91.173828] (kms_flip:2268) DEBUG: name = flip last_ts = 92.669365 last_received_ts = 92.669067 last_seq = 1120 current_ts = 92.686035 current_received_ts = 92.685745 current_seq = 1121 count = 105 seq_step = 1 [91.173857] (kms_flip:2268) DEBUG: Vblank took 25us [91.190364] (kms_flip:2268) DEBUG: name = flip last_ts = 92.686035 last_received_ts = 92.685745 last_seq = 1121 current_ts = 92.702705 current_received_ts = 92.702286 current_seq = 1122 count = 106 seq_step = 1 [91.190393] (kms_flip:2268) DEBUG: Vblank took 25us [91.207146] (kms_flip:2268) DEBUG: name = flip last_ts = 92.702705 last_received_ts = 92.702286 last_seq = 1122 current_ts = 92.719368 current_received_ts = 92.719070 current_seq = 1123 count = 107 seq_step = 1 [91.207175] (kms_flip:2268) DEBUG: Vblank took 25us [91.223742] (kms_flip:2268) DEBUG: name = flip last_ts = 92.719368 last_received_ts = 92.719070 last_seq = 1123 current_ts = 92.736038 current_received_ts = 92.735664 current_seq = 1124 count = 108 seq_step = 1 [91.223772] (kms_flip:2268) DEBUG: Vblank took 25us [91.240413] (kms_flip:2268) DEBUG: name = flip last_ts = 92.736038 last_received_ts = 92.735664 last_seq = 1124 current_ts = 92.752708 current_received_ts = 92.752335 current_seq = 1125 count = 109 seq_step = 1 [91.240442] (kms_flip:2268) DEBUG: Vblank took 25us [91.257175] (kms_flip:2268) DEBUG: name = flip last_ts = 92.752708 last_received_ts = 92.752335 last_seq = 1125 current_ts = 92.769371 current_received_ts = 92.769089 current_seq = 1126 count = 110 seq_step = 1 [91.257214] (kms_flip:2268) DEBUG: Vblank took 32us [91.273817] (kms_flip:2268) DEBUG: name = flip last_ts = 92.769371 last_received_ts = 92.769089 last_seq = 1126 current_ts = 92.786041 current_received_ts = 92.785736 current_seq = 1127 count = 111 seq_step = 1 [91.273848] (kms_flip:2268) DEBUG: Vblank took 26us [91.290487] (kms_flip:2268) DEBUG: name = flip last_ts = 92.786041 last_received_ts = 92.785736 last_seq = 1127 current_ts = 92.802711 current_received_ts = 92.802406 current_seq = 1128 count = 112 seq_step = 1 [91.290516] (kms_flip:2268) DEBUG: Vblank took 25us [91.307156] (kms_flip:2268) DEBUG: name = flip last_ts = 92.802711 last_received_ts = 92.802406 last_seq = 1128 current_ts = 92.819374 current_received_ts = 92.819077 current_seq = 1129 count = 113 seq_step = 1 [91.307185] (kms_flip:2268) DEBUG: Vblank took 26us [91.323824] (kms_flip:2268) DEBUG: name = flip last_ts = 92.819374 last_received_ts = 92.819077 last_seq = 1129 current_ts = 92.836044 current_received_ts = 92.835739 current_seq = 1130 count = 114 seq_step = 1 [91.323853] (kms_flip:2268) DEBUG: Vblank took 26us [91.340485] (kms_flip:2268) DEBUG: name = flip last_ts = 92.836044 last_received_ts = 92.835739 last_seq = 1130 current_ts = 92.852707 current_received_ts = 92.852402 current_seq = 1131 count = 115 seq_step = 1 [91.340515] (kms_flip:2268) DEBUG: Vblank took 26us [91.357154] (kms_flip:2268) DEBUG: name = flip last_ts = 92.852707 last_received_ts = 92.852402 last_seq = 1131 current_ts = 92.869377 current_received_ts = 92.869072 current_seq = 1132 count = 116 seq_step = 1 [91.357184] (kms_flip:2268) DEBUG: Vblank took 25us [91.373823] (kms_flip:2268) DEBUG: name = flip last_ts = 92.869377 last_received_ts = 92.869072 last_seq = 1132 current_ts = 92.886040 current_received_ts = 92.885742 current_seq = 1133 count = 117 seq_step = 1 [91.373852] (kms_flip:2268) DEBUG: Vblank took 25us [91.390453] (kms_flip:2268) DEBUG: name = flip last_ts = 92.886040 last_received_ts = 92.885742 last_seq = 1133 current_ts = 92.902718 current_received_ts = 92.902367 current_seq = 1134 count = 118 seq_step = 1 [91.390490] (kms_flip:2268) DEBUG: Vblank took 29us [91.407122] (kms_flip:2268) DEBUG: name = flip last_ts = 92.902718 last_received_ts = 92.902367 last_seq = 1134 current_ts = 92.919373 current_received_ts = 92.919029 current_seq = 1135 count = 119 seq_step = 1 [91.407162] (kms_flip:2268) DEBUG: Vblank took 34us [91.423683] (kms_flip:2268) DEBUG: name = flip last_ts = 92.919373 last_received_ts = 92.919029 last_seq = 1135 current_ts = 92.936043 current_received_ts = 92.935600 current_seq = 1136 count = 120 seq_step = 1 [91.423712] (kms_flip:2268) DEBUG: Vblank took 26us [91.440436] (kms_flip:2268) DEBUG: name = flip last_ts = 92.936043 last_received_ts = 92.935600 last_seq = 1136 current_ts = 92.952705 current_received_ts = 92.952347 current_seq = 1137 count = 121 seq_step = 1 [91.440467] (kms_flip:2268) DEBUG: Vblank took 26us [91.457046] (kms_flip:2268) DEBUG: name = flip last_ts = 92.952705 last_received_ts = 92.952347 last_seq = 1137 current_ts = 92.969383 current_received_ts = 92.968964 current_seq = 1138 count = 122 seq_step = 1 [91.457076] (kms_flip:2268) DEBUG: Vblank took 26us [91.473752] (kms_flip:2268) DEBUG: name = flip last_ts = 92.969383 last_received_ts = 92.968964 last_seq = 1138 current_ts = 92.986046 current_received_ts = 92.985664 current_seq = 1139 count = 123 seq_step = 1 [91.473783] (kms_flip:2268) DEBUG: Vblank took 26us [91.490466] (kms_flip:2268) DEBUG: name = flip last_ts = 92.986046 last_received_ts = 92.985664 last_seq = 1139 current_ts = 93.002724 current_received_ts = 93.002373 current_seq = 1140 count = 124 seq_step = 1 [91.490505] (kms_flip:2268) DEBUG: Vblank took 31us [91.507160] (kms_flip:2268) DEBUG: name = flip last_ts = 93.002724 last_received_ts = 93.002373 last_seq = 1140 current_ts = 93.019379 current_received_ts = 93.019058 current_seq = 1141 count = 125 seq_step = 1 [91.507206] (kms_flip:2268) DEBUG: Vblank took 35us [91.523834] (kms_flip:2268) DEBUG: name = flip last_ts = 93.019379 last_received_ts = 93.019058 last_seq = 1141 current_ts = 93.036041 current_received_ts = 93.035744 current_seq = 1142 count = 126 seq_step = 1 [91.523869] (kms_flip:2268) DEBUG: Vblank took 26us [91.540315] (kms_flip:2268) DEBUG: name = flip last_ts = 93.036041 last_received_ts = 93.035744 last_seq = 1142 current_ts = 93.052727 current_received_ts = 93.052231 current_seq = 1143 count = 127 seq_step = 1 [91.540333] (kms_flip:2268) DEBUG: Vblank took 16us [91.557058] (kms_flip:2268) DEBUG: name = flip last_ts = 93.052727 last_received_ts = 93.052231 last_seq = 1143 current_ts = 93.069389 current_received_ts = 93.068977 current_seq = 1144 count = 128 seq_step = 1 [91.557076] (kms_flip:2268) DEBUG: Vblank took 17us [91.573730] (kms_flip:2268) DEBUG: name = flip last_ts = 93.069389 last_received_ts = 93.068977 last_seq = 1144 current_ts = 93.086052 current_received_ts = 93.085640 current_seq = 1145 count = 129 seq_step = 1 [91.573753] (kms_flip:2268) DEBUG: Vblank took 20us [91.590404] (kms_flip:2268) DEBUG: name = flip last_ts = 93.086052 last_received_ts = 93.085640 last_seq = 1145 current_ts = 93.102722 current_received_ts = 93.102318 current_seq = 1146 count = 130 seq_step = 1 [91.590427] (kms_flip:2268) DEBUG: Vblank took 20us [91.607142] (kms_flip:2268) DEBUG: name = flip last_ts = 93.102722 last_received_ts = 93.102318 last_seq = 1146 current_ts = 93.119385 current_received_ts = 93.119049 current_seq = 1147 count = 131 seq_step = 1 [91.607185] (kms_flip:2268) DEBUG: Vblank took 33us [91.623840] (kms_flip:2268) DEBUG: name = flip last_ts = 93.119385 last_received_ts = 93.119049 last_seq = 1147 current_ts = 93.136047 current_received_ts = 93.135750 current_seq = 1148 count = 132 seq_step = 1 [91.623873] (kms_flip:2268) DEBUG: Vblank took 27us [91.640506] (kms_flip:2268) DEBUG: name = flip last_ts = 93.136047 last_received_ts = 93.135750 last_seq = 1148 current_ts = 93.152718 current_received_ts = 93.152412 current_seq = 1149 count = 133 seq_step = 1 [91.640537] (kms_flip:2268) DEBUG: Vblank took 26us [91.657179] (kms_flip:2268) DEBUG: name = flip last_ts = 93.152718 last_received_ts = 93.152412 last_seq = 1149 current_ts = 93.169380 current_received_ts = 93.169090 current_seq = 1150 count = 134 seq_step = 1 [91.657208] (kms_flip:2268) DEBUG: Vblank took 25us [91.673840] (kms_flip:2268) DEBUG: name = flip last_ts = 93.169380 last_received_ts = 93.169090 last_seq = 1150 current_ts = 93.186050 current_received_ts = 93.185745 current_seq = 1151 count = 135 seq_step = 1 [91.673869] (kms_flip:2268) DEBUG: Vblank took 26us [91.690514] (kms_flip:2268) DEBUG: name = flip last_ts = 93.186050 last_received_ts = 93.185745 last_seq = 1151 current_ts = 93.202728 current_received_ts = 93.202423 current_seq = 1152 count = 136 seq_step = 1 [91.690544] (kms_flip:2268) DEBUG: Vblank took 25us [91.707170] (kms_flip:2268) DEBUG: name = flip last_ts = 93.202728 last_received_ts = 93.202423 last_seq = 1152 current_ts = 93.219383 current_received_ts = 93.219078 current_seq = 1153 count = 137 seq_step = 1 [91.707199] (kms_flip:2268) DEBUG: Vblank took 25us [91.723729] (kms_flip:2268) DEBUG: name = flip last_ts = 93.219383 last_received_ts = 93.219078 last_seq = 1153 current_ts = 93.236061 current_received_ts = 93.235634 current_seq = 1154 count = 138 seq_step = 1 [91.723759] (kms_flip:2268) DEBUG: Vblank took 25us [91.740433] (kms_flip:2268) DEBUG: name = flip last_ts = 93.236061 last_received_ts = 93.235634 last_seq = 1154 current_ts = 93.252716 current_received_ts = 93.252342 current_seq = 1155 count = 139 seq_step = 1 [91.740463] (kms_flip:2268) DEBUG: Vblank took 26us [91.757059] (kms_flip:2268) DEBUG: name = flip last_ts = 93.252716 last_received_ts = 93.252342 last_seq = 1155 current_ts = 93.269386 current_received_ts = 93.268967 current_seq = 1156 count = 140 seq_step = 1 [91.757108] (kms_flip:2268) DEBUG: Vblank took 44us [91.773774] (kms_flip:2268) DEBUG: name = flip last_ts = 93.269386 last_received_ts = 93.268967 last_seq = 1156 current_ts = 93.286057 current_received_ts = 93.285683 current_seq = 1157 count = 141 seq_step = 1 [91.773804] (kms_flip:2268) DEBUG: Vblank took 25us [91.790431] (kms_flip:2268) DEBUG: name = flip last_ts = 93.286057 last_received_ts = 93.285683 last_seq = 1157 current_ts = 93.302727 current_received_ts = 93.302338 current_seq = 1158 count = 142 seq_step = 1 [91.790461] (kms_flip:2268) DEBUG: Vblank took 25us [91.807176] (kms_flip:2268) DEBUG: name = flip last_ts = 93.302727 last_received_ts = 93.302338 last_seq = 1158 current_ts = 93.319389 current_received_ts = 93.319084 current_seq = 1159 count = 143 seq_step = 1 [91.807206] (kms_flip:2268) DEBUG: Vblank took 25us [91.823731] (kms_flip:2268) DEBUG: name = flip last_ts = 93.319389 last_received_ts = 93.319084 last_seq = 1159 current_ts = 93.336060 current_received_ts = 93.335632 current_seq = 1160 count = 144 seq_step = 1 [91.823760] (kms_flip:2268) DEBUG: Vblank took 25us [91.840441] (kms_flip:2268) DEBUG: name = flip last_ts = 93.336060 last_received_ts = 93.335632 last_seq = 1160 current_ts = 93.352722 current_received_ts = 93.352348 current_seq = 1161 count = 145 seq_step = 1 [91.840471] (kms_flip:2268) DEBUG: Vblank took 25us [91.857069] (kms_flip:2268) DEBUG: name = flip last_ts = 93.352722 last_received_ts = 93.352348 last_seq = 1161 current_ts = 93.369392 current_received_ts = 93.368973 current_seq = 1162 count = 146 seq_step = 1 [91.857117] (kms_flip:2268) DEBUG: Vblank took 43us [91.873845] (kms_flip:2268) DEBUG: name = flip last_ts = 93.369392 last_received_ts = 93.368973 last_seq = 1162 current_ts = 93.386055 current_received_ts = 93.385750 current_seq = 1163 count = 147 seq_step = 1 [91.873874] (kms_flip:2268) DEBUG: Vblank took 26us [91.890516] (kms_flip:2268) DEBUG: name = flip last_ts = 93.386055 last_received_ts = 93.385750 last_seq = 1163 current_ts = 93.402725 current_received_ts = 93.402420 current_seq = 1164 count = 148 seq_step = 1 [91.890546] (kms_flip:2268) DEBUG: Vblank took 26us [91.907186] (kms_flip:2268) DEBUG: name = flip last_ts = 93.402725 last_received_ts = 93.402420 last_seq = 1164 current_ts = 93.419395 current_received_ts = 93.419090 current_seq = 1165 count = 149 seq_step = 1 [91.907215] (kms_flip:2268) DEBUG: Vblank took 25us [91.923855] (kms_flip:2268) DEBUG: name = flip last_ts = 93.419395 last_received_ts = 93.419090 last_seq = 1165 current_ts = 93.436058 current_received_ts = 93.435760 current_seq = 1166 count = 150 seq_step = 1 [91.923885] (kms_flip:2268) DEBUG: Vblank took 25us [91.940519] (kms_flip:2268) DEBUG: name = flip last_ts = 93.436058 last_received_ts = 93.435760 last_seq = 1166 current_ts = 93.452728 current_received_ts = 93.452423 current_seq = 1167 count = 151 seq_step = 1 [91.940548] (kms_flip:2268) DEBUG: Vblank took 25us [91.957183] (kms_flip:2268) DEBUG: name = flip last_ts = 93.452728 last_received_ts = 93.452423 last_seq = 1167 current_ts = 93.469391 current_received_ts = 93.469086 current_seq = 1168 count = 152 seq_step = 1 [91.957212] (kms_flip:2268) DEBUG: Vblank took 25us [91.973858] (kms_flip:2268) DEBUG: name = flip last_ts = 93.469391 last_received_ts = 93.469086 last_seq = 1168 current_ts = 93.486061 current_received_ts = 93.485756 current_seq = 1169 count = 153 seq_step = 1 [91.973887] (kms_flip:2268) DEBUG: Vblank took 25us [91.990526] (kms_flip:2268) DEBUG: name = flip last_ts = 93.486061 last_received_ts = 93.485756 last_seq = 1169 current_ts = 93.502731 current_received_ts = 93.502426 current_seq = 1170 count = 154 seq_step = 1 [91.990555] (kms_flip:2268) DEBUG: Vblank took 25us [92.007189] (kms_flip:2268) DEBUG: name = flip last_ts = 93.502731 last_received_ts = 93.502426 last_seq = 1170 current_ts = 93.519394 current_received_ts = 93.519089 current_seq = 1171 count = 155 seq_step = 1 [92.007218] (kms_flip:2268) DEBUG: Vblank took 25us [92.023855] (kms_flip:2268) DEBUG: name = flip last_ts = 93.519394 last_received_ts = 93.519089 last_seq = 1171 current_ts = 93.536057 current_received_ts = 93.535751 current_seq = 1172 count = 156 seq_step = 1 [92.023885] (kms_flip:2268) DEBUG: Vblank took 25us [92.040409] (kms_flip:2268) DEBUG: name = flip last_ts = 93.536057 last_received_ts = 93.535751 last_seq = 1172 current_ts = 93.552727 current_received_ts = 93.552307 current_seq = 1173 count = 157 seq_step = 1 [92.040438] (kms_flip:2268) DEBUG: Vblank took 25us [92.057192] (kms_flip:2268) DEBUG: name = flip last_ts = 93.552727 last_received_ts = 93.552307 last_seq = 1173 current_ts = 93.569397 current_received_ts = 93.569092 current_seq = 1174 count = 158 seq_step = 1 [92.057220] (kms_flip:2268) DEBUG: Vblank took 25us [92.073859] (kms_flip:2268) DEBUG: name = flip last_ts = 93.569397 last_received_ts = 93.569092 last_seq = 1174 current_ts = 93.586060 current_received_ts = 93.585754 current_seq = 1175 count = 159 seq_step = 1 [92.073888] (kms_flip:2268) DEBUG: Vblank took 25us [92.090412] (kms_flip:2268) DEBUG: name = flip last_ts = 93.586060 last_received_ts = 93.585754 last_seq = 1175 current_ts = 93.602730 current_received_ts = 93.602310 current_seq = 1176 count = 160 seq_step = 1 [92.090441] (kms_flip:2268) DEBUG: Vblank took 25us [92.107190] (kms_flip:2268) DEBUG: name = flip last_ts = 93.602730 last_received_ts = 93.602310 last_seq = 1176 current_ts = 93.619392 current_received_ts = 93.619087 current_seq = 1177 count = 161 seq_step = 1 [92.107219] (kms_flip:2268) DEBUG: Vblank took 25us [92.123867] (kms_flip:2268) DEBUG: name = flip last_ts = 93.619392 last_received_ts = 93.619087 last_seq = 1177 current_ts = 93.636070 current_received_ts = 93.635765 current_seq = 1178 count = 162 seq_step = 1 [92.123896] (kms_flip:2268) DEBUG: Vblank took 24us [92.140416] (kms_flip:2268) DEBUG: name = flip last_ts = 93.636070 last_received_ts = 93.635765 last_seq = 1178 current_ts = 93.652733 current_received_ts = 93.652313 current_seq = 1179 count = 163 seq_step = 1 [92.140445] (kms_flip:2268) DEBUG: Vblank took 25us [92.157204] (kms_flip:2268) DEBUG: name = flip last_ts = 93.652733 last_received_ts = 93.652313 last_seq = 1179 current_ts = 93.669403 current_received_ts = 93.669098 current_seq = 1180 count = 164 seq_step = 1 [92.157232] (kms_flip:2268) DEBUG: Vblank took 25us [92.173747] (kms_flip:2268) DEBUG: name = flip last_ts = 93.669403 last_received_ts = 93.669098 last_seq = 1180 current_ts = 93.686066 current_received_ts = 93.685646 current_seq = 1181 count = 165 seq_step = 1 [92.173777] (kms_flip:2268) DEBUG: Vblank took 25us [92.190455] (kms_flip:2268) DEBUG: name = flip last_ts = 93.686066 last_received_ts = 93.685646 last_seq = 1181 current_ts = 93.702728 current_received_ts = 93.702354 current_seq = 1182 count = 166 seq_step = 1 [92.190484] (kms_flip:2268) DEBUG: Vblank took 25us [92.207206] (kms_flip:2268) DEBUG: name = flip last_ts = 93.702728 last_received_ts = 93.702354 last_seq = 1182 current_ts = 93.719406 current_received_ts = 93.719101 current_seq = 1183 count = 167 seq_step = 1 [92.207234] (kms_flip:2268) DEBUG: Vblank took 25us [92.223865] (kms_flip:2268) DEBUG: name = flip last_ts = 93.719406 last_received_ts = 93.719101 last_seq = 1183 current_ts = 93.736061 current_received_ts = 93.735764 current_seq = 1184 count = 168 seq_step = 1 [92.223894] (kms_flip:2268) DEBUG: Vblank took 25us [92.240460] (kms_flip:2268) DEBUG: name = flip last_ts = 93.736061 last_received_ts = 93.735764 last_seq = 1184 current_ts = 93.752731 current_received_ts = 93.752357 current_seq = 1185 count = 169 seq_step = 1 [92.240489] (kms_flip:2268) DEBUG: Vblank took 25us [92.257206] (kms_flip:2268) DEBUG: name = flip last_ts = 93.752731 last_received_ts = 93.752357 last_seq = 1185 current_ts = 93.769402 current_received_ts = 93.769096 current_seq = 1186 count = 170 seq_step = 1 [92.257236] (kms_flip:2268) DEBUG: Vblank took 26us [92.273756] (kms_flip:2268) DEBUG: name = flip last_ts = 93.769402 last_received_ts = 93.769096 last_seq = 1186 current_ts = 93.786072 current_received_ts = 93.785652 current_seq = 1187 count = 171 seq_step = 1 [92.273785] (kms_flip:2268) DEBUG: Vblank took 25us [92.290461] (kms_flip:2268) DEBUG: name = flip last_ts = 93.786072 last_received_ts = 93.785652 last_seq = 1187 current_ts = 93.802734 current_received_ts = 93.802353 current_seq = 1188 count = 172 seq_step = 1 [92.290490] (kms_flip:2268) DEBUG: Vblank took 25us [92.307087] (kms_flip:2268) DEBUG: name = flip last_ts = 93.802734 last_received_ts = 93.802353 last_seq = 1188 current_ts = 93.819405 current_received_ts = 93.818977 current_seq = 1189 count = 173 seq_step = 1 [92.307138] (kms_flip:2268) DEBUG: Vblank took 46us [92.323796] (kms_flip:2268) DEBUG: name = flip last_ts = 93.819405 last_received_ts = 93.818977 last_seq = 1189 current_ts = 93.836067 current_received_ts = 93.835686 current_seq = 1190 count = 174 seq_step = 1 [92.323825] (kms_flip:2268) DEBUG: Vblank took 25us [92.340467] (kms_flip:2268) DEBUG: name = flip last_ts = 93.836067 last_received_ts = 93.835686 last_seq = 1190 current_ts = 93.852737 current_received_ts = 93.852364 current_seq = 1191 count = 175 seq_step = 1 [92.340497] (kms_flip:2268) DEBUG: Vblank took 25us [92.357204] (kms_flip:2268) DEBUG: name = flip last_ts = 93.852737 last_received_ts = 93.852364 last_seq = 1191 current_ts = 93.869400 current_received_ts = 93.869095 current_seq = 1192 count = 176 seq_step = 1 [92.357233] (kms_flip:2268) DEBUG: Vblank took 25us [92.373875] (kms_flip:2268) DEBUG: name = flip last_ts = 93.869400 last_received_ts = 93.869095 last_seq = 1192 current_ts = 93.886070 current_received_ts = 93.885765 current_seq = 1193 count = 177 seq_step = 1 [92.373904] (kms_flip:2268) DEBUG: Vblank took 25us [92.390466] (kms_flip:2268) DEBUG: name = flip last_ts = 93.886070 last_received_ts = 93.885765 last_seq = 1193 current_ts = 93.902733 current_received_ts = 93.902359 current_seq = 1194 count = 178 seq_step = 1 [92.390495] (kms_flip:2268) DEBUG: Vblank took 25us [92.407095] (kms_flip:2268) DEBUG: name = flip last_ts = 93.902733 last_received_ts = 93.902359 last_seq = 1194 current_ts = 93.919411 current_received_ts = 93.918983 current_seq = 1195 count = 179 seq_step = 1 [92.407158] (kms_flip:2268) DEBUG: Vblank took 58us [92.423875] (kms_flip:2268) DEBUG: name = flip last_ts = 93.919411 last_received_ts = 93.918983 last_seq = 1195 current_ts = 93.936066 current_received_ts = 93.935768 current_seq = 1196 count = 180 seq_step = 1 [92.423904] (kms_flip:2268) DEBUG: Vblank took 25us [92.440467] (kms_flip:2268) DEBUG: name = flip last_ts = 93.936066 last_received_ts = 93.935768 last_seq = 1196 current_ts = 93.952736 current_received_ts = 93.952354 current_seq = 1197 count = 181 seq_step = 1 [92.440497] (kms_flip:2268) DEBUG: Vblank took 25us [92.457208] (kms_flip:2268) DEBUG: name = flip last_ts = 93.952736 last_received_ts = 93.952354 last_seq = 1197 current_ts = 93.969398 current_received_ts = 93.969101 current_seq = 1198 count = 182 seq_step = 1 [92.457237] (kms_flip:2268) DEBUG: Vblank took 25us [92.473763] (kms_flip:2268) DEBUG: name = flip last_ts = 93.969398 last_received_ts = 93.969101 last_seq = 1198 current_ts = 93.986076 current_received_ts = 93.985649 current_seq = 1199 count = 183 seq_step = 1 [92.473792] (kms_flip:2268) DEBUG: Vblank took 25us [92.490465] (kms_flip:2268) DEBUG: name = flip last_ts = 93.986076 last_received_ts = 93.985649 last_seq = 1199 current_ts = 94.002747 current_received_ts = 94.002357 current_seq = 1200 count = 184 seq_step = 1 [92.490494] (kms_flip:2268) DEBUG: Vblank took 25us [92.507175] (kms_flip:2268) DEBUG: name = flip last_ts = 94.002747 last_received_ts = 94.002357 last_seq = 1200 current_ts = 94.019402 current_received_ts = 94.019058 current_seq = 1201 count = 185 seq_step = 1 [92.507205] (kms_flip:2268) DEBUG: Vblank took 25us [92.523804] (kms_flip:2268) DEBUG: name = flip last_ts = 94.019402 last_received_ts = 94.019058 last_seq = 1201 current_ts = 94.036072 current_received_ts = 94.035690 current_seq = 1202 count = 186 seq_step = 1 [92.523834] (kms_flip:2268) DEBUG: Vblank took 25us [92.540472] (kms_flip:2268) DEBUG: name = flip last_ts = 94.036072 last_received_ts = 94.035690 last_seq = 1202 current_ts = 94.052734 current_received_ts = 94.052361 current_seq = 1203 count = 187 seq_step = 1 [92.540502] (kms_flip:2268) DEBUG: Vblank took 25us [92.557214] (kms_flip:2268) DEBUG: name = flip last_ts = 94.052734 last_received_ts = 94.052361 last_seq = 1203 current_ts = 94.069405 current_received_ts = 94.069099 current_seq = 1204 count = 188 seq_step = 1 [92.557243] (kms_flip:2268) DEBUG: Vblank took 25us [92.573884] (kms_flip:2268) DEBUG: name = flip last_ts = 94.069405 last_received_ts = 94.069099 last_seq = 1204 current_ts = 94.086075 current_received_ts = 94.085770 current_seq = 1205 count = 189 seq_step = 1 [92.573913] (kms_flip:2268) DEBUG: Vblank took 25us [92.590430] (kms_flip:2268) DEBUG: name = flip last_ts = 94.086075 last_received_ts = 94.085770 last_seq = 1205 current_ts = 94.102737 current_received_ts = 94.102318 current_seq = 1206 count = 190 seq_step = 1 [92.590459] (kms_flip:2268) DEBUG: Vblank took 26us [92.607220] (kms_flip:2268) DEBUG: name = flip last_ts = 94.102737 last_received_ts = 94.102318 last_seq = 1206 current_ts = 94.119408 current_received_ts = 94.119110 current_seq = 1207 count = 191 seq_step = 1 [92.607250] (kms_flip:2268) DEBUG: Vblank took 25us [92.623811] (kms_flip:2268) DEBUG: name = flip last_ts = 94.119408 last_received_ts = 94.119110 last_seq = 1207 current_ts = 94.136070 current_received_ts = 94.135696 current_seq = 1208 count = 192 seq_step = 1 [92.623840] (kms_flip:2268) DEBUG: Vblank took 25us [92.640478] (kms_flip:2268) DEBUG: name = flip last_ts = 94.136070 last_received_ts = 94.135696 last_seq = 1208 current_ts = 94.152740 current_received_ts = 94.152367 current_seq = 1209 count = 193 seq_step = 1 [92.640508] (kms_flip:2268) DEBUG: Vblank took 25us [92.657106] (kms_flip:2268) DEBUG: name = flip last_ts = 94.152740 last_received_ts = 94.152367 last_seq = 1209 current_ts = 94.169411 current_received_ts = 94.168991 current_seq = 1210 count = 194 seq_step = 1 [92.657174] (kms_flip:2268) DEBUG: Vblank took 30us [92.673890] (kms_flip:2268) DEBUG: name = flip last_ts = 94.169411 last_received_ts = 94.168991 last_seq = 1210 current_ts = 94.186081 current_received_ts = 94.185776 current_seq = 1211 count = 195 seq_step = 1 [92.673919] (kms_flip:2268) DEBUG: Vblank took 25us [92.690480] (kms_flip:2268) DEBUG: name = flip last_ts = 94.186081 last_received_ts = 94.185776 last_seq = 1211 current_ts = 94.202744 current_received_ts = 94.202362 current_seq = 1212 count = 196 seq_step = 1 [92.690509] (kms_flip:2268) DEBUG: Vblank took 26us [92.707108] (kms_flip:2268) DEBUG: name = flip last_ts = 94.202744 last_received_ts = 94.202362 last_seq = 1212 current_ts = 94.219414 current_received_ts = 94.218994 current_seq = 1213 count = 197 seq_step = 1 [92.707160] (kms_flip:2268) DEBUG: Vblank took 31us [92.723891] (kms_flip:2268) DEBUG: name = flip last_ts = 94.219414 last_received_ts = 94.218994 last_seq = 1213 current_ts = 94.236076 current_received_ts = 94.235779 current_seq = 1214 count = 198 seq_step = 1 [92.723921] (kms_flip:2268) DEBUG: Vblank took 25us [92.740442] (kms_flip:2268) DEBUG: name = flip last_ts = 94.236076 last_received_ts = 94.235779 last_seq = 1214 current_ts = 94.252747 current_received_ts = 94.252327 current_seq = 1215 count = 199 seq_step = 1 [92.740472] (kms_flip:2268) DEBUG: Vblank took 25us [92.757103] (kms_flip:2268) DEBUG: name = flip last_ts = 94.252747 last_received_ts = 94.252327 last_seq = 1215 current_ts = 94.269409 current_received_ts = 94.268990 current_seq = 1216 count = 200 seq_step = 1 [92.758042] (kms_flip:2268) DEBUG: Vblank took 933us [92.758048] (kms_flip:2268) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [92.758174] (kms_flip:2268) CRITICAL: Failed assertion: end - start < 500 [92.758237] (kms_flip:2268) CRITICAL: Last errno: 4, Interrupted system call [92.772093] (kms_flip:2268) igt_core-INFO: Stack trace: [92.790554] (kms_flip:2268) igt_core-INFO: #0 ../lib/igt_core.c:2074 __igt_fail_assert() [92.792207] (kms_flip:2268) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [92.792343] (kms_flip:2268) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [92.792388] (kms_flip:2268) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() [92.792439] (kms_flip:2268) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [92.800554] (kms_flip:2268) igt_core-INFO: #5 [__libc_init_first+0x8a] [92.803584] (kms_flip:2268) igt_core-INFO: #6 [__libc_start_main+0x8b] [92.804356] (kms_flip:2268) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-DP2: FAIL (3.953s)
Dmesg	<6> [90.750923] [IGT] kms_flip: starting dynamic subtest B-DP2 <7> [90.753985] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:554] <7> [90.755849] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:558] <7> [90.797643] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [90.797722] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [90.797850] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [90.797958] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [90.798075] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [90.798175] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 5190451/8388608 link 288358/524288, found tu 0, data 0/0 link 0/0) <7> [90.798275] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000080, found 0x00000000) <7> [90.798372] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [90.798468] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [90.798565] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [90.798660] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [90.798755] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [90.798849] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [90.798943] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [90.799053] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [90.799149] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [90.799244] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [90.799338] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [90.799433] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [90.799527] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [90.799620] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [90.799715] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [90.799816] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [90.799910] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [90.800028] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [90.800123] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [90.800217] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [90.800310] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [90.800404] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [90.800497] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [90.800590] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [90.800683] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [90.800776] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [90.800869] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [90.800961] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [90.801067] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [90.801162] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [90.801255] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [90.801349] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [90.801442] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 270000, found 0) <7> [90.801535] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [90.801631] xe 0000:03:00.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing TC PLL 2 <7> [90.801755] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [90.801837] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [90.801933] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4037 - 4096) -> ( 0 - 0), size 59 -> 0 <7> [90.802022] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 192000 kHz -> 0 kHz <7> [90.802158] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [90.802264] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [90.802368] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [90.802470] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [90.802571] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [90.802672] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [90.802771] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [90.803182] xe 0000:03:00.0: [drm:intel_audio_codec_disable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Disable audio codec on [CRTC:151:pipe A] <7> [90.828700] xe 0000:03:00.0: [drm:intel_audio_component_get_eld [xe]] Not valid for port E <7> [90.829680] xe 0000:03:00.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [90.845262] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [90.848179] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disable TC PLL 2 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [90.850746] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disabling TC PLL 2 <7> [90.851606] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [90.852060] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [90.852461] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [90.852851] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [90.853253] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [90.853619] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <6> [90.853957] pcieport 0000:00:01.0: PME: Spurious native interrupt! <7> [90.853804] xe 0000:03:00.0: [drm:intel_audio_component_get_power [xe]] restored AUD_FREQ_CNTRL to 0x8010 <7> [90.854218] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [90.854547] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [90.854850] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [90.855178] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [90.855467] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [90.855738] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [90.856006] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [90.856268] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [90.856512] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [90.856744] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [90.856975] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [90.857474] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [90.857902] xe 0000:03:00.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [90.858133] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [90.858680] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [90.859135] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [90.859400] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [90.860031] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe C] <7> [90.860775] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe B] <7> [90.860936] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D] <7> [90.861100] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe C] <7> [90.861130] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:527:DP-2] <7> [90.861231] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:526:DDI TC2/PHY G][CRTC:269:pipe C] DP link limits: pixel clock 148500 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 36 min link_bpp 18.0000 max link_bpp 36.0000 <7> [90.861424] xe 0000:03:00.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 270000 bpp input 36 compressed 0.0000 HDR no link rate required 668250 available 1080000 <7> [90.861601] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe C] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [90.861783] xe 0000:03:00.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:526:DDI TC2/PHY G] [CRTC:269:pipe C] <7> [90.861954] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [90.862129] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [90.862279] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [90.862427] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [90.862573] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 5190451/8388608 link 288358/524288) <7> [90.862713] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000080) <7> [90.862845] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [90.862976] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [90.863123] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [90.863254] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [90.863377] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [90.863498] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [90.863621] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [90.863736] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [90.863848] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [90.863967] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [90.864083] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [90.864191] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [90.864296] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [90.864401] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [90.864505] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [90.864609] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [90.864703] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [90.864799] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [90.864892] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [90.864986] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [90.865093] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [90.865188] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [90.865280] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [90.865374] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [90.865468] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [90.865561] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [90.865655] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [90.865749] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [90.865843] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [90.865936] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in dpll_hw_state <7> [90.866040] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] expected: <7> [90.866143] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [90.866241] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: <7> [90.866337] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000 <7> [90.866431] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [90.866526] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x40e8 <7> [90.866618] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[1] = 0x7d20 <7> [90.866712] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[2] = 0x0a06 <7> [90.866806] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[3] = 0x8f1c <7> [90.866899] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[4] = 0x0000 <7> [90.866990] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[5] = 0x0000 <7> [90.867098] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[6] = 0x2200 <7> [90.867196] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[7] = 0xffff <7> [90.867288] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[8] = 0x0400 <7> [90.867381] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[9] = 0x0000 <7> [90.867473] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0001 <7> [90.867566] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00 <7> [90.867658] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] found: <7> [90.867750] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [90.867843] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: <7> [90.867935] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000 <7> [90.868033] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [90.868125] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x308c <7> [90.868184] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_2 <7> [90.868217] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[1] = 0x2110 <7> [90.868307] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[2] = 0xcc9c <7> [90.868397] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[3] = 0xbfc1 <7> [90.868488] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[4] = 0x4b9a <7> [90.868581] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[5] = 0x3f81 <7> [90.868673] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[6] = 0x2000 <7> [90.868765] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[7] = 0x0001 <7> [90.868855] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[8] = 0x5000 <7> [90.868946] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[9] = 0x0000 <7> [90.869045] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000 <7> [90.869136] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x42, hdmi rate: 0x00 <7> [90.869227] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [90.869320] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [90.869411] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [90.869502] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in port_clock (expected 0, found 270000) <7> [90.869593] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe C] fastset requirement not met, forcing full modeset <7> [90.869707] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no <7> [90.869790] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:269:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4 <7> [90.869889] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:153:plane 1C] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989 <7> [90.869963] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:263:cursor C] ddb ( 0 - 0) -> (1989 - 2048), size 0 -> 59 <7> [90.870048] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [90.870121] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 9, 9, 17, 17, 17, 17, 0, 15, 0 <7> [90.870194] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 139, 139, 261, 261, 261, 261, 137, 230, 244 <7> [90.870269] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:153:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 245, 245, 367, 367, 0, 0, 138, 306, 306 <7> [90.870355] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:269:pipe C] data rate 594000 num active planes 1 <7> [90.870462] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 33600 required 624 qgv_peak_bw: 48000 <7> [90.870567] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 53000 required 624 qgv_peak_bw: 48000 <7> [90.870669] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 48000 for required data rate: 624 <7> [90.870782] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:269:pipe C] min cdclk: 0 kHz -> 192000 kHz <7> [90.870908] xe 0000:03:00.0: [drm:intel_find_dpll [xe]] [CRTC:269:pipe C] allocated TC PLL 2 <7> [90.871044] xe 0000:03:00.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:269:pipe C] reserving TC PLL 2 <7> [90.871137] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:269:pipe C] enable: yes [modeset] <7> [90.871241] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: DP (0x80), output format: RGB, sink format: RGB <7> [90.871344] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: C, pipe bpp: 36, dithering: 0 <7> [90.871443] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [90.871543] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [90.871640] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [90.871739] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [90.871836] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 5190451, data_n: 8388608, link_m: 288358, link_n: 524288, tu: 64 <7> [90.871934] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [90.872041] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled <7> [90.872139] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [90.872236] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] psr: disabled, selective update: disabled, panel replay: disabled, selective fetch: disabled <7> [90.872334] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [90.872431] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] audio: 1, infoframes: 0, infoframes enabled: 0x0 <7> [90.872529] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 10 00 09 00 68 36 00 01 00 00 00 00 00 00 00 00 <7> [90.872626] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 61 a4 9a 00 44 50 46 39 30 34 33 35 09 07 07 11 <7> [90.872722] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00 <7> [90.872819] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [90.872915] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [90.873015] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 42 vsync start: 41, vsync end: 36 <7> [90.873113] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1083, vmax vblank: 1083, vmin vtotal: 1125, vmax vtotal: 1125 <7> [90.873209] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [90.873305] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [90.873402] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [90.873499] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [90.873597] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5 <7> [90.873694] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [90.873791] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 270000, pixel rate 148500, min cdclk 192000, min voltage level 0 <7> [90.873887] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] linetime: 119, ips linetime: 0 <7> [90.873983] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [90.874093] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe src: 1920x1080+0+0 <7> [90.874193] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [90.874288] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [90.874383] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [90.874476] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [90.874573] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] c20pll_hw_state: <7> [90.874675] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000 <7> [90.874774] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [90.874873] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[0] = 0x308c <7> [90.874971] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[1] = 0x2110 <7> [90.875079] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[2] = 0xcc9c <7> [90.875180] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[3] = 0xbfc1 <7> [90.875276] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[4] = 0x4b9a <7> [90.875372] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[5] = 0x3f81 <7> [90.875468] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[6] = 0x2000 <7> [90.875563] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[7] = 0x0001 <7> [90.875659] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[8] = 0x5000 <7> [90.875754] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[9] = 0x0000 <7> [90.875850] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[10] = 0x0000 <7> [90.875946] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vdr: custom width: 0x00, serdes rate: 0x42, hdmi rate: 0x00 <7> [90.876051] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [90.876148] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [90.876243] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [90.876339] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.876435] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.876530] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.876624] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [90.876720] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [90.876815] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.876911] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.877010] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [90.877106] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [90.877202] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:153:plane 1C] fb: [FB:554] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [90.877298] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [90.877392] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [90.877489] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:183:plane 2C] fb: [NOFB], visible: no <7> [90.877584] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:213:plane 3C] fb: [NOFB], visible: no <7> [90.877680] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:243:plane 4C] fb: [NOFB], visible: no <7> [90.877773] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:253:plane 5C] fb: [NOFB], visible: no <7> [90.877869] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:263:cursor C] fb: [NOFB], visible: no <7> [90.878489] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [90.878602] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_C <7> [90.878721] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x4 (CLKGATE_DIS_DSSDSC=0x8a000000) <7> [90.878831] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [90.878922] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [90.879021] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [90.879110] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [90.879196] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [90.879280] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [90.879363] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [90.879446] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [90.879530] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [90.879612] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [90.879692] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [90.879772] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [90.879851] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [90.879931] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [90.880015] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [90.880093] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [90.880181] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xd <7> [90.880350] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [90.880450] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enable TC PLL 2 (active 0x4, on? 0) for [CRTC:269:pipe C] <7> [90.880547] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enabling TC PLL 2 <7> [90.884432] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01 <7> [90.889199] xe 0000:03:00.0: [drm:intel_dp_init_lttpr_and_dprx_caps [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] LTTPR common capabilities: 00 00 00 00 00 00 00 00 <7> [90.890220] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01 <7> [90.890663] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 0a <7> [90.892168] xe 0000:03:00.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [90.892727] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS1 <7> [90.898939] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Clock recovery OK <7> [90.899072] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS3 <7> [90.905948] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Channel EQ done. DP Training successful <7> [90.906189] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Link Training passed at link rate = 270000, lane count = 4 <7> [90.907520] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe C <7> [90.942128] xe 0000:03:00.0: [drm:intel_audio_codec_enable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Enable audio codec on [CRTC:269:pipe C], 40 bytes ELD <7> [90.955892] xe 0000:03:00.0: [drm:intel_audio_component_get_power [xe]] restored AUD_FREQ_CNTRL to 0x8010 <7> [90.958707] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [90.959646] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe C] <7> [91.016166] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <7> [92.943112] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [93.047171] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <7> [93.136525] xe 0000:03:00.0: [drm:xe_hwmon_read [xe]] thermal data for group 0 val 0x27272728 <7> [93.136701] xe 0000:03:00.0: [drm:xe_hwmon_read [xe]] thermal data for group 1 val 0x2a282828 <6> [94.711064] [IGT] kms_flip: finished subtest B-DP2, FAIL

Detail

Value

Duration

3.95 seconds

Hostname

shard-bmg-3

Igt-Version

IGT-Version: 2.4-g9187799ba (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5058-21b42374be17d486b-debug+ x86_64)

Out

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

Err

Starting dynamic subtest: B-DP2
[92.758048] (kms_flip:2268) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[92.758174] (kms_flip:2268) CRITICAL: Failed assertion: end - start < 500
[92.758237] (kms_flip:2268) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-DP2 failed.
**** DEBUG ****
[90.740345] (kms_flip:2268) DEBUG: Vblank took 26us
[90.757056] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.252693
last_received_ts = 92.252251
last_seq = 1095
current_ts = 92.269363
current_received_ts = 92.268990
current_seq = 1096
count = 80
seq_step = 1
[90.757112] (kms_flip:2268) DEBUG: Vblank took 51us
[90.773649] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.269363
last_received_ts = 92.268990
last_seq = 1096
current_ts = 92.286026
current_received_ts = 92.285583
current_seq = 1097
count = 81
seq_step = 1
[90.773680] (kms_flip:2268) DEBUG: Vblank took 27us
[90.790315] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.286026
last_received_ts = 92.285583
last_seq = 1097
current_ts = 92.302696
current_received_ts = 92.302246
current_seq = 1098
count = 82
seq_step = 1
[90.790345] (kms_flip:2268) DEBUG: Vblank took 26us
[90.807059] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.302696
last_received_ts = 92.302246
last_seq = 1098
current_ts = 92.319359
current_received_ts = 92.318993
current_seq = 1099
count = 83
seq_step = 1
[90.807127] (kms_flip:2268) DEBUG: Vblank took 32us
[90.823651] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.319359
last_received_ts = 92.318993
last_seq = 1099
current_ts = 92.336029
current_received_ts = 92.335579
current_seq = 1100
count = 84
seq_step = 1
[90.823682] (kms_flip:2268) DEBUG: Vblank took 26us
[90.840319] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.336029
last_received_ts = 92.335579
last_seq = 1100
current_ts = 92.352692
current_received_ts = 92.352249
current_seq = 1101
count = 85
seq_step = 1
[90.840349] (kms_flip:2268) DEBUG: Vblank took 26us
[90.857062] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.352692
last_received_ts = 92.352249
last_seq = 1101
current_ts = 92.369362
current_received_ts = 92.368988
current_seq = 1102
count = 86
seq_step = 1
[90.857123] (kms_flip:2268) DEBUG: Vblank took 30us
[90.873653] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.369362
last_received_ts = 92.368988
last_seq = 1102
current_ts = 92.386024
current_received_ts = 92.385582
current_seq = 1103
count = 87
seq_step = 1
[90.873684] (kms_flip:2268) DEBUG: Vblank took 26us
[90.890391] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.386024
last_received_ts = 92.385582
last_seq = 1103
current_ts = 92.402695
current_received_ts = 92.402321
current_seq = 1104
count = 88
seq_step = 1
[90.890420] (kms_flip:2268) DEBUG: Vblank took 25us
[90.907136] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.402695
last_received_ts = 92.402321
last_seq = 1104
current_ts = 92.419365
current_received_ts = 92.419067
current_seq = 1105
count = 89
seq_step = 1
[90.907165] (kms_flip:2268) DEBUG: Vblank took 25us
[90.923802] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.419365
last_received_ts = 92.419067
last_seq = 1105
current_ts = 92.436035
current_received_ts = 92.435730
current_seq = 1106
count = 90
seq_step = 1
[90.923832] (kms_flip:2268) DEBUG: Vblank took 25us
[90.940354] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.436035
last_received_ts = 92.435730
last_seq = 1106
current_ts = 92.452705
current_received_ts = 92.452278
current_seq = 1107
count = 91
seq_step = 1
[90.940383] (kms_flip:2268) DEBUG: Vblank took 25us
[90.957144] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.452705
last_received_ts = 92.452278
last_seq = 1107
current_ts = 92.469376
current_received_ts = 92.469070
current_seq = 1108
count = 92
seq_step = 1
[90.957174] (kms_flip:2268) DEBUG: Vblank took 25us
[90.973804] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.469376
last_received_ts = 92.469070
last_seq = 1108
current_ts = 92.486031
current_received_ts = 92.485733
current_seq = 1109
count = 93
seq_step = 1
[90.973834] (kms_flip:2268) DEBUG: Vblank took 25us
[90.990470] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.486031
last_received_ts = 92.485733
last_seq = 1109
current_ts = 92.502701
current_received_ts = 92.502396
current_seq = 1110
count = 94
seq_step = 1
[90.990500] (kms_flip:2268) DEBUG: Vblank took 25us
[91.007138] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.502701
last_received_ts = 92.502396
last_seq = 1110
current_ts = 92.519363
current_received_ts = 92.519066
current_seq = 1111
count = 95
seq_step = 1
[91.007169] (kms_flip:2268) DEBUG: Vblank took 25us
[91.023810] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.519363
last_received_ts = 92.519066
last_seq = 1111
current_ts = 92.536041
current_received_ts = 92.535736
current_seq = 1112
count = 96
seq_step = 1
[91.023840] (kms_flip:2268) DEBUG: Vblank took 26us
[91.040470] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.536041
last_received_ts = 92.535736
last_seq = 1112
current_ts = 92.552696
current_received_ts = 92.552391
current_seq = 1113
count = 97
seq_step = 1
[91.040509] (kms_flip:2268) DEBUG: Vblank took 24us
[91.057140] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.552696
last_received_ts = 92.552391
last_seq = 1113
current_ts = 92.569366
current_received_ts = 92.569061
current_seq = 1114
count = 98
seq_step = 1
[91.057175] (kms_flip:2268) DEBUG: Vblank took 25us
[91.073809] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.569366
last_received_ts = 92.569061
last_seq = 1114
current_ts = 92.586037
current_received_ts = 92.585732
current_seq = 1115
count = 99
seq_step = 1
[91.073838] (kms_flip:2268) DEBUG: Vblank took 26us
[91.090483] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.586037
last_received_ts = 92.585732
last_seq = 1115
current_ts = 92.602707
current_received_ts = 92.602402
current_seq = 1116
count = 100
seq_step = 1
[91.090513] (kms_flip:2268) DEBUG: Vblank took 25us
[91.107141] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.602707
last_received_ts = 92.602402
last_seq = 1116
current_ts = 92.619370
current_received_ts = 92.619064
current_seq = 1117
count = 101
seq_step = 1
[91.107170] (kms_flip:2268) DEBUG: Vblank took 25us
[91.123736] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.619370
last_received_ts = 92.619064
last_seq = 1117
current_ts = 92.636040
current_received_ts = 92.635658
current_seq = 1118
count = 102
seq_step = 1
[91.123764] (kms_flip:2268) DEBUG: Vblank took 24us
[91.140407] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.636040
last_received_ts = 92.635658
last_seq = 1118
current_ts = 92.652710
current_received_ts = 92.652328
current_seq = 1119
count = 103
seq_step = 1
[91.140436] (kms_flip:2268) DEBUG: Vblank took 26us
[91.157143] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.652710
last_received_ts = 92.652328
last_seq = 1119
current_ts = 92.669365
current_received_ts = 92.669067
current_seq = 1120
count = 104
seq_step = 1
[91.157173] (kms_flip:2268) DEBUG: Vblank took 25us
[91.173828] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.669365
last_received_ts = 92.669067
last_seq = 1120
current_ts = 92.686035
current_received_ts = 92.685745
current_seq = 1121
count = 105
seq_step = 1
[91.173857] (kms_flip:2268) DEBUG: Vblank took 25us
[91.190364] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.686035
last_received_ts = 92.685745
last_seq = 1121
current_ts = 92.702705
current_received_ts = 92.702286
current_seq = 1122
count = 106
seq_step = 1
[91.190393] (kms_flip:2268) DEBUG: Vblank took 25us
[91.207146] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.702705
last_received_ts = 92.702286
last_seq = 1122
current_ts = 92.719368
current_received_ts = 92.719070
current_seq = 1123
count = 107
seq_step = 1
[91.207175] (kms_flip:2268) DEBUG: Vblank took 25us
[91.223742] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.719368
last_received_ts = 92.719070
last_seq = 1123
current_ts = 92.736038
current_received_ts = 92.735664
current_seq = 1124
count = 108
seq_step = 1
[91.223772] (kms_flip:2268) DEBUG: Vblank took 25us
[91.240413] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.736038
last_received_ts = 92.735664
last_seq = 1124
current_ts = 92.752708
current_received_ts = 92.752335
current_seq = 1125
count = 109
seq_step = 1
[91.240442] (kms_flip:2268) DEBUG: Vblank took 25us
[91.257175] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.752708
last_received_ts = 92.752335
last_seq = 1125
current_ts = 92.769371
current_received_ts = 92.769089
current_seq = 1126
count = 110
seq_step = 1
[91.257214] (kms_flip:2268) DEBUG: Vblank took 32us
[91.273817] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.769371
last_received_ts = 92.769089
last_seq = 1126
current_ts = 92.786041
current_received_ts = 92.785736
current_seq = 1127
count = 111
seq_step = 1
[91.273848] (kms_flip:2268) DEBUG: Vblank took 26us
[91.290487] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.786041
last_received_ts = 92.785736
last_seq = 1127
current_ts = 92.802711
current_received_ts = 92.802406
current_seq = 1128
count = 112
seq_step = 1
[91.290516] (kms_flip:2268) DEBUG: Vblank took 25us
[91.307156] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.802711
last_received_ts = 92.802406
last_seq = 1128
current_ts = 92.819374
current_received_ts = 92.819077
current_seq = 1129
count = 113
seq_step = 1
[91.307185] (kms_flip:2268) DEBUG: Vblank took 26us
[91.323824] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.819374
last_received_ts = 92.819077
last_seq = 1129
current_ts = 92.836044
current_received_ts = 92.835739
current_seq = 1130
count = 114
seq_step = 1
[91.323853] (kms_flip:2268) DEBUG: Vblank took 26us
[91.340485] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.836044
last_received_ts = 92.835739
last_seq = 1130
current_ts = 92.852707
current_received_ts = 92.852402
current_seq = 1131
count = 115
seq_step = 1
[91.340515] (kms_flip:2268) DEBUG: Vblank took 26us
[91.357154] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.852707
last_received_ts = 92.852402
last_seq = 1131
current_ts = 92.869377
current_received_ts = 92.869072
current_seq = 1132
count = 116
seq_step = 1
[91.357184] (kms_flip:2268) DEBUG: Vblank took 25us
[91.373823] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.869377
last_received_ts = 92.869072
last_seq = 1132
current_ts = 92.886040
current_received_ts = 92.885742
current_seq = 1133
count = 117
seq_step = 1
[91.373852] (kms_flip:2268) DEBUG: Vblank took 25us
[91.390453] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.886040
last_received_ts = 92.885742
last_seq = 1133
current_ts = 92.902718
current_received_ts = 92.902367
current_seq = 1134
count = 118
seq_step = 1
[91.390490] (kms_flip:2268) DEBUG: Vblank took 29us
[91.407122] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.902718
last_received_ts = 92.902367
last_seq = 1134
current_ts = 92.919373
current_received_ts = 92.919029
current_seq = 1135
count = 119
seq_step = 1
[91.407162] (kms_flip:2268) DEBUG: Vblank took 34us
[91.423683] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.919373
last_received_ts = 92.919029
last_seq = 1135
current_ts = 92.936043
current_received_ts = 92.935600
current_seq = 1136
count = 120
seq_step = 1
[91.423712] (kms_flip:2268) DEBUG: Vblank took 26us
[91.440436] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.936043
last_received_ts = 92.935600
last_seq = 1136
current_ts = 92.952705
current_received_ts = 92.952347
current_seq = 1137
count = 121
seq_step = 1
[91.440467] (kms_flip:2268) DEBUG: Vblank took 26us
[91.457046] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.952705
last_received_ts = 92.952347
last_seq = 1137
current_ts = 92.969383
current_received_ts = 92.968964
current_seq = 1138
count = 122
seq_step = 1
[91.457076] (kms_flip:2268) DEBUG: Vblank took 26us
[91.473752] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.969383
last_received_ts = 92.968964
last_seq = 1138
current_ts = 92.986046
current_received_ts = 92.985664
current_seq = 1139
count = 123
seq_step = 1
[91.473783] (kms_flip:2268) DEBUG: Vblank took 26us
[91.490466] (kms_flip:2268) DEBUG: name = flip
last_ts = 92.986046
last_received_ts = 92.985664
last_seq = 1139
current_ts = 93.002724
current_received_ts = 93.002373
current_seq = 1140
count = 124
seq_step = 1
[91.490505] (kms_flip:2268) DEBUG: Vblank took 31us
[91.507160] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.002724
last_received_ts = 93.002373
last_seq = 1140
current_ts = 93.019379
current_received_ts = 93.019058
current_seq = 1141
count = 125
seq_step = 1
[91.507206] (kms_flip:2268) DEBUG: Vblank took 35us
[91.523834] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.019379
last_received_ts = 93.019058
last_seq = 1141
current_ts = 93.036041
current_received_ts = 93.035744
current_seq = 1142
count = 126
seq_step = 1
[91.523869] (kms_flip:2268) DEBUG: Vblank took 26us
[91.540315] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.036041
last_received_ts = 93.035744
last_seq = 1142
current_ts = 93.052727
current_received_ts = 93.052231
current_seq = 1143
count = 127
seq_step = 1
[91.540333] (kms_flip:2268) DEBUG: Vblank took 16us
[91.557058] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.052727
last_received_ts = 93.052231
last_seq = 1143
current_ts = 93.069389
current_received_ts = 93.068977
current_seq = 1144
count = 128
seq_step = 1
[91.557076] (kms_flip:2268) DEBUG: Vblank took 17us
[91.573730] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.069389
last_received_ts = 93.068977
last_seq = 1144
current_ts = 93.086052
current_received_ts = 93.085640
current_seq = 1145
count = 129
seq_step = 1
[91.573753] (kms_flip:2268) DEBUG: Vblank took 20us
[91.590404] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.086052
last_received_ts = 93.085640
last_seq = 1145
current_ts = 93.102722
current_received_ts = 93.102318
current_seq = 1146
count = 130
seq_step = 1
[91.590427] (kms_flip:2268) DEBUG: Vblank took 20us
[91.607142] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.102722
last_received_ts = 93.102318
last_seq = 1146
current_ts = 93.119385
current_received_ts = 93.119049
current_seq = 1147
count = 131
seq_step = 1
[91.607185] (kms_flip:2268) DEBUG: Vblank took 33us
[91.623840] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.119385
last_received_ts = 93.119049
last_seq = 1147
current_ts = 93.136047
current_received_ts = 93.135750
current_seq = 1148
count = 132
seq_step = 1
[91.623873] (kms_flip:2268) DEBUG: Vblank took 27us
[91.640506] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.136047
last_received_ts = 93.135750
last_seq = 1148
current_ts = 93.152718
current_received_ts = 93.152412
current_seq = 1149
count = 133
seq_step = 1
[91.640537] (kms_flip:2268) DEBUG: Vblank took 26us
[91.657179] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.152718
last_received_ts = 93.152412
last_seq = 1149
current_ts = 93.169380
current_received_ts = 93.169090
current_seq = 1150
count = 134
seq_step = 1
[91.657208] (kms_flip:2268) DEBUG: Vblank took 25us
[91.673840] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.169380
last_received_ts = 93.169090
last_seq = 1150
current_ts = 93.186050
current_received_ts = 93.185745
current_seq = 1151
count = 135
seq_step = 1
[91.673869] (kms_flip:2268) DEBUG: Vblank took 26us
[91.690514] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.186050
last_received_ts = 93.185745
last_seq = 1151
current_ts = 93.202728
current_received_ts = 93.202423
current_seq = 1152
count = 136
seq_step = 1
[91.690544] (kms_flip:2268) DEBUG: Vblank took 25us
[91.707170] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.202728
last_received_ts = 93.202423
last_seq = 1152
current_ts = 93.219383
current_received_ts = 93.219078
current_seq = 1153
count = 137
seq_step = 1
[91.707199] (kms_flip:2268) DEBUG: Vblank took 25us
[91.723729] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.219383
last_received_ts = 93.219078
last_seq = 1153
current_ts = 93.236061
current_received_ts = 93.235634
current_seq = 1154
count = 138
seq_step = 1
[91.723759] (kms_flip:2268) DEBUG: Vblank took 25us
[91.740433] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.236061
last_received_ts = 93.235634
last_seq = 1154
current_ts = 93.252716
current_received_ts = 93.252342
current_seq = 1155
count = 139
seq_step = 1
[91.740463] (kms_flip:2268) DEBUG: Vblank took 26us
[91.757059] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.252716
last_received_ts = 93.252342
last_seq = 1155
current_ts = 93.269386
current_received_ts = 93.268967
current_seq = 1156
count = 140
seq_step = 1
[91.757108] (kms_flip:2268) DEBUG: Vblank took 44us
[91.773774] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.269386
last_received_ts = 93.268967
last_seq = 1156
current_ts = 93.286057
current_received_ts = 93.285683
current_seq = 1157
count = 141
seq_step = 1
[91.773804] (kms_flip:2268) DEBUG: Vblank took 25us
[91.790431] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.286057
last_received_ts = 93.285683
last_seq = 1157
current_ts = 93.302727
current_received_ts = 93.302338
current_seq = 1158
count = 142
seq_step = 1
[91.790461] (kms_flip:2268) DEBUG: Vblank took 25us
[91.807176] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.302727
last_received_ts = 93.302338
last_seq = 1158
current_ts = 93.319389
current_received_ts = 93.319084
current_seq = 1159
count = 143
seq_step = 1
[91.807206] (kms_flip:2268) DEBUG: Vblank took 25us
[91.823731] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.319389
last_received_ts = 93.319084
last_seq = 1159
current_ts = 93.336060
current_received_ts = 93.335632
current_seq = 1160
count = 144
seq_step = 1
[91.823760] (kms_flip:2268) DEBUG: Vblank took 25us
[91.840441] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.336060
last_received_ts = 93.335632
last_seq = 1160
current_ts = 93.352722
current_received_ts = 93.352348
current_seq = 1161
count = 145
seq_step = 1
[91.840471] (kms_flip:2268) DEBUG: Vblank took 25us
[91.857069] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.352722
last_received_ts = 93.352348
last_seq = 1161
current_ts = 93.369392
current_received_ts = 93.368973
current_seq = 1162
count = 146
seq_step = 1
[91.857117] (kms_flip:2268) DEBUG: Vblank took 43us
[91.873845] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.369392
last_received_ts = 93.368973
last_seq = 1162
current_ts = 93.386055
current_received_ts = 93.385750
current_seq = 1163
count = 147
seq_step = 1
[91.873874] (kms_flip:2268) DEBUG: Vblank took 26us
[91.890516] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.386055
last_received_ts = 93.385750
last_seq = 1163
current_ts = 93.402725
current_received_ts = 93.402420
current_seq = 1164
count = 148
seq_step = 1
[91.890546] (kms_flip:2268) DEBUG: Vblank took 26us
[91.907186] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.402725
last_received_ts = 93.402420
last_seq = 1164
current_ts = 93.419395
current_received_ts = 93.419090
current_seq = 1165
count = 149
seq_step = 1
[91.907215] (kms_flip:2268) DEBUG: Vblank took 25us
[91.923855] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.419395
last_received_ts = 93.419090
last_seq = 1165
current_ts = 93.436058
current_received_ts = 93.435760
current_seq = 1166
count = 150
seq_step = 1
[91.923885] (kms_flip:2268) DEBUG: Vblank took 25us
[91.940519] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.436058
last_received_ts = 93.435760
last_seq = 1166
current_ts = 93.452728
current_received_ts = 93.452423
current_seq = 1167
count = 151
seq_step = 1
[91.940548] (kms_flip:2268) DEBUG: Vblank took 25us
[91.957183] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.452728
last_received_ts = 93.452423
last_seq = 1167
current_ts = 93.469391
current_received_ts = 93.469086
current_seq = 1168
count = 152
seq_step = 1
[91.957212] (kms_flip:2268) DEBUG: Vblank took 25us
[91.973858] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.469391
last_received_ts = 93.469086
last_seq = 1168
current_ts = 93.486061
current_received_ts = 93.485756
current_seq = 1169
count = 153
seq_step = 1
[91.973887] (kms_flip:2268) DEBUG: Vblank took 25us
[91.990526] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.486061
last_received_ts = 93.485756
last_seq = 1169
current_ts = 93.502731
current_received_ts = 93.502426
current_seq = 1170
count = 154
seq_step = 1
[91.990555] (kms_flip:2268) DEBUG: Vblank took 25us
[92.007189] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.502731
last_received_ts = 93.502426
last_seq = 1170
current_ts = 93.519394
current_received_ts = 93.519089
current_seq = 1171
count = 155
seq_step = 1
[92.007218] (kms_flip:2268) DEBUG: Vblank took 25us
[92.023855] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.519394
last_received_ts = 93.519089
last_seq = 1171
current_ts = 93.536057
current_received_ts = 93.535751
current_seq = 1172
count = 156
seq_step = 1
[92.023885] (kms_flip:2268) DEBUG: Vblank took 25us
[92.040409] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.536057
last_received_ts = 93.535751
last_seq = 1172
current_ts = 93.552727
current_received_ts = 93.552307
current_seq = 1173
count = 157
seq_step = 1
[92.040438] (kms_flip:2268) DEBUG: Vblank took 25us
[92.057192] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.552727
last_received_ts = 93.552307
last_seq = 1173
current_ts = 93.569397
current_received_ts = 93.569092
current_seq = 1174
count = 158
seq_step = 1
[92.057220] (kms_flip:2268) DEBUG: Vblank took 25us
[92.073859] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.569397
last_received_ts = 93.569092
last_seq = 1174
current_ts = 93.586060
current_received_ts = 93.585754
current_seq = 1175
count = 159
seq_step = 1
[92.073888] (kms_flip:2268) DEBUG: Vblank took 25us
[92.090412] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.586060
last_received_ts = 93.585754
last_seq = 1175
current_ts = 93.602730
current_received_ts = 93.602310
current_seq = 1176
count = 160
seq_step = 1
[92.090441] (kms_flip:2268) DEBUG: Vblank took 25us
[92.107190] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.602730
last_received_ts = 93.602310
last_seq = 1176
current_ts = 93.619392
current_received_ts = 93.619087
current_seq = 1177
count = 161
seq_step = 1
[92.107219] (kms_flip:2268) DEBUG: Vblank took 25us
[92.123867] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.619392
last_received_ts = 93.619087
last_seq = 1177
current_ts = 93.636070
current_received_ts = 93.635765
current_seq = 1178
count = 162
seq_step = 1
[92.123896] (kms_flip:2268) DEBUG: Vblank took 24us
[92.140416] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.636070
last_received_ts = 93.635765
last_seq = 1178
current_ts = 93.652733
current_received_ts = 93.652313
current_seq = 1179
count = 163
seq_step = 1
[92.140445] (kms_flip:2268) DEBUG: Vblank took 25us
[92.157204] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.652733
last_received_ts = 93.652313
last_seq = 1179
current_ts = 93.669403
current_received_ts = 93.669098
current_seq = 1180
count = 164
seq_step = 1
[92.157232] (kms_flip:2268) DEBUG: Vblank took 25us
[92.173747] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.669403
last_received_ts = 93.669098
last_seq = 1180
current_ts = 93.686066
current_received_ts = 93.685646
current_seq = 1181
count = 165
seq_step = 1
[92.173777] (kms_flip:2268) DEBUG: Vblank took 25us
[92.190455] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.686066
last_received_ts = 93.685646
last_seq = 1181
current_ts = 93.702728
current_received_ts = 93.702354
current_seq = 1182
count = 166
seq_step = 1
[92.190484] (kms_flip:2268) DEBUG: Vblank took 25us
[92.207206] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.702728
last_received_ts = 93.702354
last_seq = 1182
current_ts = 93.719406
current_received_ts = 93.719101
current_seq = 1183
count = 167
seq_step = 1
[92.207234] (kms_flip:2268) DEBUG: Vblank took 25us
[92.223865] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.719406
last_received_ts = 93.719101
last_seq = 1183
current_ts = 93.736061
current_received_ts = 93.735764
current_seq = 1184
count = 168
seq_step = 1
[92.223894] (kms_flip:2268) DEBUG: Vblank took 25us
[92.240460] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.736061
last_received_ts = 93.735764
last_seq = 1184
current_ts = 93.752731
current_received_ts = 93.752357
current_seq = 1185
count = 169
seq_step = 1
[92.240489] (kms_flip:2268) DEBUG: Vblank took 25us
[92.257206] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.752731
last_received_ts = 93.752357
last_seq = 1185
current_ts = 93.769402
current_received_ts = 93.769096
current_seq = 1186
count = 170
seq_step = 1
[92.257236] (kms_flip:2268) DEBUG: Vblank took 26us
[92.273756] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.769402
last_received_ts = 93.769096
last_seq = 1186
current_ts = 93.786072
current_received_ts = 93.785652
current_seq = 1187
count = 171
seq_step = 1
[92.273785] (kms_flip:2268) DEBUG: Vblank took 25us
[92.290461] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.786072
last_received_ts = 93.785652
last_seq = 1187
current_ts = 93.802734
current_received_ts = 93.802353
current_seq = 1188
count = 172
seq_step = 1
[92.290490] (kms_flip:2268) DEBUG: Vblank took 25us
[92.307087] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.802734
last_received_ts = 93.802353
last_seq = 1188
current_ts = 93.819405
current_received_ts = 93.818977
current_seq = 1189
count = 173
seq_step = 1
[92.307138] (kms_flip:2268) DEBUG: Vblank took 46us
[92.323796] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.819405
last_received_ts = 93.818977
last_seq = 1189
current_ts = 93.836067
current_received_ts = 93.835686
current_seq = 1190
count = 174
seq_step = 1
[92.323825] (kms_flip:2268) DEBUG: Vblank took 25us
[92.340467] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.836067
last_received_ts = 93.835686
last_seq = 1190
current_ts = 93.852737
current_received_ts = 93.852364
current_seq = 1191
count = 175
seq_step = 1
[92.340497] (kms_flip:2268) DEBUG: Vblank took 25us
[92.357204] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.852737
last_received_ts = 93.852364
last_seq = 1191
current_ts = 93.869400
current_received_ts = 93.869095
current_seq = 1192
count = 176
seq_step = 1
[92.357233] (kms_flip:2268) DEBUG: Vblank took 25us
[92.373875] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.869400
last_received_ts = 93.869095
last_seq = 1192
current_ts = 93.886070
current_received_ts = 93.885765
current_seq = 1193
count = 177
seq_step = 1
[92.373904] (kms_flip:2268) DEBUG: Vblank took 25us
[92.390466] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.886070
last_received_ts = 93.885765
last_seq = 1193
current_ts = 93.902733
current_received_ts = 93.902359
current_seq = 1194
count = 178
seq_step = 1
[92.390495] (kms_flip:2268) DEBUG: Vblank took 25us
[92.407095] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.902733
last_received_ts = 93.902359
last_seq = 1194
current_ts = 93.919411
current_received_ts = 93.918983
current_seq = 1195
count = 179
seq_step = 1
[92.407158] (kms_flip:2268) DEBUG: Vblank took 58us
[92.423875] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.919411
last_received_ts = 93.918983
last_seq = 1195
current_ts = 93.936066
current_received_ts = 93.935768
current_seq = 1196
count = 180
seq_step = 1
[92.423904] (kms_flip:2268) DEBUG: Vblank took 25us
[92.440467] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.936066
last_received_ts = 93.935768
last_seq = 1196
current_ts = 93.952736
current_received_ts = 93.952354
current_seq = 1197
count = 181
seq_step = 1
[92.440497] (kms_flip:2268) DEBUG: Vblank took 25us
[92.457208] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.952736
last_received_ts = 93.952354
last_seq = 1197
current_ts = 93.969398
current_received_ts = 93.969101
current_seq = 1198
count = 182
seq_step = 1
[92.457237] (kms_flip:2268) DEBUG: Vblank took 25us
[92.473763] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.969398
last_received_ts = 93.969101
last_seq = 1198
current_ts = 93.986076
current_received_ts = 93.985649
current_seq = 1199
count = 183
seq_step = 1
[92.473792] (kms_flip:2268) DEBUG: Vblank took 25us
[92.490465] (kms_flip:2268) DEBUG: name = flip
last_ts = 93.986076
last_received_ts = 93.985649
last_seq = 1199
current_ts = 94.002747
current_received_ts = 94.002357
current_seq = 1200
count = 184
seq_step = 1
[92.490494] (kms_flip:2268) DEBUG: Vblank took 25us
[92.507175] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.002747
last_received_ts = 94.002357
last_seq = 1200
current_ts = 94.019402
current_received_ts = 94.019058
current_seq = 1201
count = 185
seq_step = 1
[92.507205] (kms_flip:2268) DEBUG: Vblank took 25us
[92.523804] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.019402
last_received_ts = 94.019058
last_seq = 1201
current_ts = 94.036072
current_received_ts = 94.035690
current_seq = 1202
count = 186
seq_step = 1
[92.523834] (kms_flip:2268) DEBUG: Vblank took 25us
[92.540472] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.036072
last_received_ts = 94.035690
last_seq = 1202
current_ts = 94.052734
current_received_ts = 94.052361
current_seq = 1203
count = 187
seq_step = 1
[92.540502] (kms_flip:2268) DEBUG: Vblank took 25us
[92.557214] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.052734
last_received_ts = 94.052361
last_seq = 1203
current_ts = 94.069405
current_received_ts = 94.069099
current_seq = 1204
count = 188
seq_step = 1
[92.557243] (kms_flip:2268) DEBUG: Vblank took 25us
[92.573884] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.069405
last_received_ts = 94.069099
last_seq = 1204
current_ts = 94.086075
current_received_ts = 94.085770
current_seq = 1205
count = 189
seq_step = 1
[92.573913] (kms_flip:2268) DEBUG: Vblank took 25us
[92.590430] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.086075
last_received_ts = 94.085770
last_seq = 1205
current_ts = 94.102737
current_received_ts = 94.102318
current_seq = 1206
count = 190
seq_step = 1
[92.590459] (kms_flip:2268) DEBUG: Vblank took 26us
[92.607220] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.102737
last_received_ts = 94.102318
last_seq = 1206
current_ts = 94.119408
current_received_ts = 94.119110
current_seq = 1207
count = 191
seq_step = 1
[92.607250] (kms_flip:2268) DEBUG: Vblank took 25us
[92.623811] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.119408
last_received_ts = 94.119110
last_seq = 1207
current_ts = 94.136070
current_received_ts = 94.135696
current_seq = 1208
count = 192
seq_step = 1
[92.623840] (kms_flip:2268) DEBUG: Vblank took 25us
[92.640478] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.136070
last_received_ts = 94.135696
last_seq = 1208
current_ts = 94.152740
current_received_ts = 94.152367
current_seq = 1209
count = 193
seq_step = 1
[92.640508] (kms_flip:2268) DEBUG: Vblank took 25us
[92.657106] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.152740
last_received_ts = 94.152367
last_seq = 1209
current_ts = 94.169411
current_received_ts = 94.168991
current_seq = 1210
count = 194
seq_step = 1
[92.657174] (kms_flip:2268) DEBUG: Vblank took 30us
[92.673890] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.169411
last_received_ts = 94.168991
last_seq = 1210
current_ts = 94.186081
current_received_ts = 94.185776
current_seq = 1211
count = 195
seq_step = 1
[92.673919] (kms_flip:2268) DEBUG: Vblank took 25us
[92.690480] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.186081
last_received_ts = 94.185776
last_seq = 1211
current_ts = 94.202744
current_received_ts = 94.202362
current_seq = 1212
count = 196
seq_step = 1
[92.690509] (kms_flip:2268) DEBUG: Vblank took 26us
[92.707108] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.202744
last_received_ts = 94.202362
last_seq = 1212
current_ts = 94.219414
current_received_ts = 94.218994
current_seq = 1213
count = 197
seq_step = 1
[92.707160] (kms_flip:2268) DEBUG: Vblank took 31us
[92.723891] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.219414
last_received_ts = 94.218994
last_seq = 1213
current_ts = 94.236076
current_received_ts = 94.235779
current_seq = 1214
count = 198
seq_step = 1
[92.723921] (kms_flip:2268) DEBUG: Vblank took 25us
[92.740442] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.236076
last_received_ts = 94.235779
last_seq = 1214
current_ts = 94.252747
current_received_ts = 94.252327
current_seq = 1215
count = 199
seq_step = 1
[92.740472] (kms_flip:2268) DEBUG: Vblank took 25us
[92.757103] (kms_flip:2268) DEBUG: name = flip
last_ts = 94.252747
last_received_ts = 94.252327
last_seq = 1215
current_ts = 94.269409
current_received_ts = 94.268990
current_seq = 1216
count = 200
seq_step = 1
[92.758042] (kms_flip:2268) DEBUG: Vblank took 933us
[92.758048] (kms_flip:2268) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[92.758174] (kms_flip:2268) CRITICAL: Failed assertion: end - start < 500
[92.758237] (kms_flip:2268) CRITICAL: Last errno: 4, Interrupted system call
[92.772093] (kms_flip:2268) igt_core-INFO: Stack trace:
[92.790554] (kms_flip:2268) igt_core-INFO:   #0 ../lib/igt_core.c:2074 __igt_fail_assert()
[92.792207] (kms_flip:2268) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[92.792343] (kms_flip:2268) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[92.792388] (kms_flip:2268) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
[92.792439] (kms_flip:2268) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[92.800554] (kms_flip:2268) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[92.803584] (kms_flip:2268) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[92.804356] (kms_flip:2268) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-DP2: FAIL (3.953s)

Dmesg

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

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

<7> [90.755849] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:558]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<6> [90.853957] pcieport 0000:00:01.0: PME: Spurious native interrupt!

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [90.861424] xe 0000:03:00.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 270000 bpp input 36 compressed 0.0000 HDR no link rate required 668250 available 1080000

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [90.868125] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x308c

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [90.874873] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[0] = 0x308c

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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