igt@kms_flip@flip-vs-expired-vblank@a-edp1 on shard-lnl@xe-pw-167474v1 Test details

Detail	Value
Duration	5.09 seconds
Hostname	shard-lnl-3
Igt-Version	IGT-Version: 2.4-g0e365bfe5 (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-pw-167474v1-debug+ x86_64)
Out	Using IGT_SRANDOM=1780008533 for randomisation Opened device: /dev/dri/card0 Using monotonic timestamps Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2106 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2184 __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 A-eDP1: FAIL (5.088s)
Err	Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 [359.421573] (kms_flip:7409) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [359.421701] (kms_flip:7409) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest A-eDP1 failed. ** DEBUG [357.403966] (kms_flip:7409) DEBUG: name = flip last_ts = 359.511688 last_received_ts = 359.510864 last_seq = 1210 current_ts = 359.528381 current_received_ts = 359.527557 current_seq = 1211 count = 100 seq_step = 1 [357.404028] (kms_flip:7409) DEBUG: Vblank took 58us [357.420619] (kms_flip:7409) DEBUG: name = flip last_ts = 359.528381 last_received_ts = 359.527557 last_seq = 1211 current_ts = 359.545044 current_received_ts = 359.544220 current_seq = 1212 count = 101 seq_step = 1 [357.420682] (kms_flip:7409) DEBUG: Vblank took 58us [357.437295] (kms_flip:7409) DEBUG: name = flip last_ts = 359.545044 last_received_ts = 359.544220 last_seq = 1212 current_ts = 359.561737 current_received_ts = 359.560913 current_seq = 1213 count = 102 seq_step = 1 [357.437358] (kms_flip:7409) DEBUG: Vblank took 58us [357.453963] (kms_flip:7409) DEBUG: name = flip last_ts = 359.561737 last_received_ts = 359.560913 last_seq = 1213 current_ts = 359.578430 current_received_ts = 359.577606 current_seq = 1214 count = 103 seq_step = 1 [357.454030] (kms_flip:7409) DEBUG: Vblank took 62us [357.470621] (kms_flip:7409) DEBUG: name = flip last_ts = 359.578430 last_received_ts = 359.577606 last_seq = 1214 current_ts = 359.595093 current_received_ts = 359.594299 current_seq = 1215 count = 104 seq_step = 1 [357.470689] (kms_flip:7409) DEBUG: Vblank took 63us [357.487291] (kms_flip:7409) DEBUG: name = flip last_ts = 359.595093 last_received_ts = 359.594299 last_seq = 1215 current_ts = 359.611786 current_received_ts = 359.610962 current_seq = 1216 count = 105 seq_step = 1 [357.487383] (kms_flip:7409) DEBUG: Vblank took 86us [357.503958] (kms_flip:7409) DEBUG: name = flip last_ts = 359.611786 last_received_ts = 359.610962 last_seq = 1216 current_ts = 359.628479 current_received_ts = 359.627655 current_seq = 1217 count = 106 seq_step = 1 [357.504024] (kms_flip:7409) DEBUG: Vblank took 62us [357.520608] (kms_flip:7409) DEBUG: name = flip last_ts = 359.628479 last_received_ts = 359.627655 last_seq = 1217 current_ts = 359.645142 current_received_ts = 359.644318 current_seq = 1218 count = 107 seq_step = 1 [357.520675] (kms_flip:7409) DEBUG: Vblank took 63us [357.537296] (kms_flip:7409) DEBUG: name = flip last_ts = 359.645142 last_received_ts = 359.644318 last_seq = 1218 current_ts = 359.661835 current_received_ts = 359.661041 current_seq = 1219 count = 108 seq_step = 1 [357.537362] (kms_flip:7409) DEBUG: Vblank took 62us [357.553948] (kms_flip:7409) DEBUG: name = flip last_ts = 359.661835 last_received_ts = 359.661041 last_seq = 1219 current_ts = 359.678528 current_received_ts = 359.677704 current_seq = 1220 count = 109 seq_step = 1 [357.554015] (kms_flip:7409) DEBUG: Vblank took 61us [357.570604] (kms_flip:7409) DEBUG: name = flip last_ts = 359.678528 last_received_ts = 359.677704 last_seq = 1220 current_ts = 359.695190 current_received_ts = 359.694397 current_seq = 1221 count = 110 seq_step = 1 [357.570671] (kms_flip:7409) DEBUG: Vblank took 63us [357.587267] (kms_flip:7409) DEBUG: name = flip last_ts = 359.695190 last_received_ts = 359.694397 last_seq = 1221 current_ts = 359.711884 current_received_ts = 359.711060 current_seq = 1222 count = 111 seq_step = 1 [357.587330] (kms_flip:7409) DEBUG: Vblank took 57us [357.603939] (kms_flip:7409) DEBUG: name = flip last_ts = 359.711884 last_received_ts = 359.711060 last_seq = 1222 current_ts = 359.728577 current_received_ts = 359.727753 current_seq = 1223 count = 112 seq_step = 1 [357.604005] (kms_flip:7409) DEBUG: Vblank took 62us [357.620602] (kms_flip:7409) DEBUG: name = flip last_ts = 359.728577 last_received_ts = 359.727753 last_seq = 1223 current_ts = 359.745239 current_received_ts = 359.744446 current_seq = 1224 count = 113 seq_step = 1 [357.620669] (kms_flip:7409) DEBUG: Vblank took 62us [357.637278] (kms_flip:7409) DEBUG: name = flip last_ts = 359.745239 last_received_ts = 359.744446 last_seq = 1224 current_ts = 359.761932 current_received_ts = 359.761139 current_seq = 1225 count = 114 seq_step = 1 [357.637340] (kms_flip:7409) DEBUG: Vblank took 58us [357.653926] (kms_flip:7409) DEBUG: name = flip last_ts = 359.761932 last_received_ts = 359.761139 last_seq = 1225 current_ts = 359.778625 current_received_ts = 359.777802 current_seq = 1226 count = 115 seq_step = 1 [357.653990] (kms_flip:7409) DEBUG: Vblank took 58us [357.670597] (kms_flip:7409) DEBUG: name = flip last_ts = 359.778625 last_received_ts = 359.777802 last_seq = 1226 current_ts = 359.795288 current_received_ts = 359.794495 current_seq = 1227 count = 116 seq_step = 1 [357.670664] (kms_flip:7409) DEBUG: Vblank took 62us [357.687252] (kms_flip:7409) DEBUG: name = flip last_ts = 359.795288 last_received_ts = 359.794495 last_seq = 1227 current_ts = 359.811981 current_received_ts = 359.811157 current_seq = 1228 count = 117 seq_step = 1 [357.687320] (kms_flip:7409) DEBUG: Vblank took 62us [357.703925] (kms_flip:7409) DEBUG: name = flip last_ts = 359.811981 last_received_ts = 359.811157 last_seq = 1228 current_ts = 359.828674 current_received_ts = 359.827850 current_seq = 1229 count = 118 seq_step = 1 [357.703994] (kms_flip:7409) DEBUG: Vblank took 63us [357.720590] (kms_flip:7409) DEBUG: name = flip last_ts = 359.828674 last_received_ts = 359.827850 last_seq = 1229 current_ts = 359.845337 current_received_ts = 359.844543 current_seq = 1230 count = 119 seq_step = 1 [357.720657] (kms_flip:7409) DEBUG: Vblank took 63us [357.737245] (kms_flip:7409) DEBUG: name = flip last_ts = 359.845337 last_received_ts = 359.844543 last_seq = 1230 current_ts = 359.862030 current_received_ts = 359.861206 current_seq = 1231 count = 120 seq_step = 1 [357.737313] (kms_flip:7409) DEBUG: Vblank took 63us [357.753911] (kms_flip:7409) DEBUG: name = flip last_ts = 359.862030 last_received_ts = 359.861206 last_seq = 1231 current_ts = 359.878723 current_received_ts = 359.877899 current_seq = 1232 count = 121 seq_step = 1 [357.753979] (kms_flip:7409) DEBUG: Vblank took 63us [357.770577] (kms_flip:7409) DEBUG: name = flip last_ts = 359.878723 last_received_ts = 359.877899 last_seq = 1232 current_ts = 359.895386 current_received_ts = 359.894592 current_seq = 1233 count = 122 seq_step = 1 [357.770646] (kms_flip:7409) DEBUG: Vblank took 63us [357.787226] (kms_flip:7409) DEBUG: name = flip last_ts = 359.895386 last_received_ts = 359.894592 last_seq = 1233 current_ts = 359.912079 current_received_ts = 359.911255 current_seq = 1234 count = 123 seq_step = 1 [357.787290] (kms_flip:7409) DEBUG: Vblank took 59us [357.803896] (kms_flip:7409) DEBUG: name = flip last_ts = 359.912079 last_received_ts = 359.911255 last_seq = 1234 current_ts = 359.928772 current_received_ts = 359.927948 current_seq = 1235 count = 124 seq_step = 1 [357.803978] (kms_flip:7409) DEBUG: Vblank took 77us [357.820564] (kms_flip:7409) DEBUG: name = flip last_ts = 359.928772 last_received_ts = 359.927948 last_seq = 1235 current_ts = 359.945435 current_received_ts = 359.944641 current_seq = 1236 count = 125 seq_step = 1 [357.820628] (kms_flip:7409) DEBUG: Vblank took 58us [357.837227] (kms_flip:7409) DEBUG: name = flip last_ts = 359.945435 last_received_ts = 359.944641 last_seq = 1236 current_ts = 359.962128 current_received_ts = 359.961304 current_seq = 1237 count = 126 seq_step = 1 [357.837295] (kms_flip:7409) DEBUG: Vblank took 62us [357.853922] (kms_flip:7409) DEBUG: name = flip last_ts = 359.962128 last_received_ts = 359.961304 last_seq = 1237 current_ts = 359.978790 current_received_ts = 359.977997 current_seq = 1238 count = 127 seq_step = 1 [357.853990] (kms_flip:7409) DEBUG: Vblank took 63us [357.870594] (kms_flip:7409) DEBUG: name = flip last_ts = 359.978790 last_received_ts = 359.977997 last_seq = 1238 current_ts = 359.995483 current_received_ts = 359.994690 current_seq = 1239 count = 128 seq_step = 1 [357.870678] (kms_flip:7409) DEBUG: Vblank took 74us [357.887251] (kms_flip:7409) DEBUG: name = flip last_ts = 359.995483 last_received_ts = 359.994690 last_seq = 1239 current_ts = 360.012177 current_received_ts = 360.011383 current_seq = 1240 count = 129 seq_step = 1 [357.887331] (kms_flip:7409) DEBUG: Vblank took 72us [357.903894] (kms_flip:7409) DEBUG: name = flip last_ts = 360.012177 last_received_ts = 360.011383 last_seq = 1240 current_ts = 360.028870 current_received_ts = 360.028046 current_seq = 1241 count = 130 seq_step = 1 [357.903962] (kms_flip:7409) DEBUG: Vblank took 62us [357.920555] (kms_flip:7409) DEBUG: name = flip last_ts = 360.028870 last_received_ts = 360.028046 last_seq = 1241 current_ts = 360.045532 current_received_ts = 360.044739 current_seq = 1242 count = 131 seq_step = 1 [357.920621] (kms_flip:7409) DEBUG: Vblank took 61us [357.937212] (kms_flip:7409) DEBUG: name = flip last_ts = 360.045532 last_received_ts = 360.044739 last_seq = 1242 current_ts = 360.062225 current_received_ts = 360.061401 current_seq = 1243 count = 132 seq_step = 1 [357.937280] (kms_flip:7409) DEBUG: Vblank took 62us [357.953882] (kms_flip:7409) DEBUG: name = flip last_ts = 360.062225 last_received_ts = 360.061401 last_seq = 1243 current_ts = 360.078888 current_received_ts = 360.078094 current_seq = 1244 count = 133 seq_step = 1 [357.953949] (kms_flip:7409) DEBUG: Vblank took 63us [357.970546] (kms_flip:7409) DEBUG: name = flip last_ts = 360.078888 last_received_ts = 360.078094 last_seq = 1244 current_ts = 360.095581 current_received_ts = 360.094757 current_seq = 1245 count = 134 seq_step = 1 [357.970612] (kms_flip:7409) DEBUG: Vblank took 62us [357.987212] (kms_flip:7409) DEBUG: name = flip last_ts = 360.095581 last_received_ts = 360.094757 last_seq = 1245 current_ts = 360.112244 current_received_ts = 360.111450 current_seq = 1246 count = 135 seq_step = 1 [357.987280] (kms_flip:7409) DEBUG: Vblank took 62us [358.003875] (kms_flip:7409) DEBUG: name = flip last_ts = 360.112244 last_received_ts = 360.111450 last_seq = 1246 current_ts = 360.128937 current_received_ts = 360.128143 current_seq = 1247 count = 136 seq_step = 1 [358.003943] (kms_flip:7409) DEBUG: Vblank took 63us [358.020542] (kms_flip:7409) DEBUG: name = flip last_ts = 360.128937 last_received_ts = 360.128143 last_seq = 1247 current_ts = 360.145630 current_received_ts = 360.144806 current_seq = 1248 count = 137 seq_step = 1 [358.020609] (kms_flip:7409) DEBUG: Vblank took 62us [358.037205] (kms_flip:7409) DEBUG: name = flip last_ts = 360.145630 last_received_ts = 360.144806 last_seq = 1248 current_ts = 360.162323 current_received_ts = 360.161499 current_seq = 1249 count = 138 seq_step = 1 [358.037273] (kms_flip:7409) DEBUG: Vblank took 63us [358.053853] (kms_flip:7409) DEBUG: name = flip last_ts = 360.162323 last_received_ts = 360.161499 last_seq = 1249 current_ts = 360.178986 current_received_ts = 360.178162 current_seq = 1250 count = 139 seq_step = 1 [358.053914] (kms_flip:7409) DEBUG: Vblank took 57us [358.070529] (kms_flip:7409) DEBUG: name = flip last_ts = 360.178986 last_received_ts = 360.178162 last_seq = 1250 current_ts = 360.195679 current_received_ts = 360.194855 current_seq = 1251 count = 140 seq_step = 1 [358.070595] (kms_flip:7409) DEBUG: Vblank took 61us [358.087193] (kms_flip:7409) DEBUG: name = flip last_ts = 360.195679 last_received_ts = 360.194855 last_seq = 1251 current_ts = 360.212341 current_received_ts = 360.211548 current_seq = 1252 count = 141 seq_step = 1 [358.087262] (kms_flip:7409) DEBUG: Vblank took 64us [358.103851] (kms_flip:7409) DEBUG: name = flip last_ts = 360.212341 last_received_ts = 360.211548 last_seq = 1252 current_ts = 360.229034 current_received_ts = 360.228210 current_seq = 1253 count = 142 seq_step = 1 [358.103918] (kms_flip:7409) DEBUG: Vblank took 63us [358.120520] (kms_flip:7409) DEBUG: name = flip last_ts = 360.229034 last_received_ts = 360.228210 last_seq = 1253 current_ts = 360.245728 current_received_ts = 360.244904 current_seq = 1254 count = 143 seq_step = 1 [358.120586] (kms_flip:7409) DEBUG: Vblank took 62us [358.137187] (kms_flip:7409) DEBUG: name = flip last_ts = 360.245728 last_received_ts = 360.244904 last_seq = 1254 current_ts = 360.262390 current_received_ts = 360.261597 current_seq = 1255 count = 144 seq_step = 1 [358.137255] (kms_flip:7409) DEBUG: Vblank took 64us [358.153842] (kms_flip:7409) DEBUG: name = flip last_ts = 360.262390 last_received_ts = 360.261597 last_seq = 1255 current_ts = 360.279083 current_received_ts = 360.278259 current_seq = 1256 count = 145 seq_step = 1 [358.153909] (kms_flip:7409) DEBUG: Vblank took 62us [358.170514] (kms_flip:7409) DEBUG: name = flip last_ts = 360.279083 last_received_ts = 360.278259 last_seq = 1256 current_ts = 360.295776 current_received_ts = 360.294952 current_seq = 1257 count = 146 seq_step = 1 [358.170602] (kms_flip:7409) DEBUG: Vblank took 82us [358.187179] (kms_flip:7409) DEBUG: name = flip last_ts = 360.295776 last_received_ts = 360.294952 last_seq = 1257 current_ts = 360.312439 current_received_ts = 360.311646 current_seq = 1258 count = 147 seq_step = 1 [358.187245] (kms_flip:7409) DEBUG: Vblank took 61us [358.203835] (kms_flip:7409) DEBUG: name = flip last_ts = 360.312439 last_received_ts = 360.311646 last_seq = 1258 current_ts = 360.329132 current_received_ts = 360.328308 current_seq = 1259 count = 148 seq_step = 1 [358.203902] (kms_flip:7409) DEBUG: Vblank took 63us [358.220528] (kms_flip:7409) DEBUG: name = flip last_ts = 360.329132 last_received_ts = 360.328308 last_seq = 1259 current_ts = 360.345795 current_received_ts = 360.345001 current_seq = 1260 count = 149 seq_step = 1 [358.220595] (kms_flip:7409) DEBUG: Vblank took 62us [358.237254] (kms_flip:7409) DEBUG: name = flip last_ts = 360.345795 last_received_ts = 360.345001 last_seq = 1260 current_ts = 360.362488 current_received_ts = 360.361755 current_seq = 1261 count = 150 seq_step = 1 [358.237361] (kms_flip:7409) DEBUG: Vblank took 93us [358.253875] (kms_flip:7409) DEBUG: name = flip last_ts = 360.362488 last_received_ts = 360.361755 last_seq = 1261 current_ts = 360.379181 current_received_ts = 360.378387 current_seq = 1262 count = 151 seq_step = 1 [358.253962] (kms_flip:7409) DEBUG: Vblank took 79us [358.270512] (kms_flip:7409) DEBUG: name = flip last_ts = 360.379181 last_received_ts = 360.378387 last_seq = 1262 current_ts = 360.395844 current_received_ts = 360.395050 current_seq = 1263 count = 152 seq_step = 1 [358.270586] (kms_flip:7409) DEBUG: Vblank took 69us [358.287170] (kms_flip:7409) DEBUG: name = flip last_ts = 360.395844 last_received_ts = 360.395050 last_seq = 1263 current_ts = 360.412537 current_received_ts = 360.411743 current_seq = 1264 count = 153 seq_step = 1 [358.287243] (kms_flip:7409) DEBUG: Vblank took 68us [358.303825] (kms_flip:7409) DEBUG: name = flip last_ts = 360.412537 last_received_ts = 360.411743 last_seq = 1264 current_ts = 360.429199 current_received_ts = 360.428406 current_seq = 1265 count = 154 seq_step = 1 [358.303898] (kms_flip:7409) DEBUG: Vblank took 68us [358.320496] (kms_flip:7409) DEBUG: name = flip last_ts = 360.429199 last_received_ts = 360.428406 last_seq = 1265 current_ts = 360.445892 current_received_ts = 360.445099 current_seq = 1266 count = 155 seq_step = 1 [358.320564] (kms_flip:7409) DEBUG: Vblank took 63us [358.337154] (kms_flip:7409) DEBUG: name = flip last_ts = 360.445892 last_received_ts = 360.445099 last_seq = 1266 current_ts = 360.462585 current_received_ts = 360.461761 current_seq = 1267 count = 156 seq_step = 1 [358.337222] (kms_flip:7409) DEBUG: Vblank took 63us [358.353820] (kms_flip:7409) DEBUG: name = flip last_ts = 360.462585 last_received_ts = 360.461761 last_seq = 1267 current_ts = 360.479248 current_received_ts = 360.478455 current_seq = 1268 count = 157 seq_step = 1 [358.353889] (kms_flip:7409) DEBUG: Vblank took 63us [358.370483] (kms_flip:7409) DEBUG: name = flip last_ts = 360.479248 last_received_ts = 360.478455 last_seq = 1268 current_ts = 360.495941 current_received_ts = 360.495117 current_seq = 1269 count = 158 seq_step = 1 [358.370551] (kms_flip:7409) DEBUG: Vblank took 62us [358.387148] (kms_flip:7409) DEBUG: name = flip last_ts = 360.495941 last_received_ts = 360.495117 last_seq = 1269 current_ts = 360.512634 current_received_ts = 360.511810 current_seq = 1270 count = 159 seq_step = 1 [358.387215] (kms_flip:7409) DEBUG: Vblank took 62us [358.403811] (kms_flip:7409) DEBUG: name = flip last_ts = 360.512634 last_received_ts = 360.511810 last_seq = 1270 current_ts = 360.529297 current_received_ts = 360.528503 current_seq = 1271 count = 160 seq_step = 1 [358.403880] (kms_flip:7409) DEBUG: Vblank took 63us [358.420470] (kms_flip:7409) DEBUG: name = flip last_ts = 360.529297 last_received_ts = 360.528503 last_seq = 1271 current_ts = 360.545990 current_received_ts = 360.545166 current_seq = 1272 count = 161 seq_step = 1 [358.420537] (kms_flip:7409) DEBUG: Vblank took 62us [358.437139] (kms_flip:7409) DEBUG: name = flip last_ts = 360.545990 last_received_ts = 360.545166 last_seq = 1272 current_ts = 360.562683 current_received_ts = 360.561859 current_seq = 1273 count = 162 seq_step = 1 [358.437206] (kms_flip:7409) DEBUG: Vblank took 63us [358.453798] (kms_flip:7409) DEBUG: name = flip last_ts = 360.562683 last_received_ts = 360.561859 last_seq = 1273 current_ts = 360.579346 current_received_ts = 360.578522 current_seq = 1274 count = 163 seq_step = 1 [358.453863] (kms_flip:7409) DEBUG: Vblank took 59us [358.470452] (kms_flip:7409) DEBUG: name = flip last_ts = 360.579346 last_received_ts = 360.578522 last_seq = 1274 current_ts = 360.596039 current_received_ts = 360.595215 current_seq = 1275 count = 164 seq_step = 1 [358.470516] (kms_flip:7409) DEBUG: Vblank took 59us [358.487134] (kms_flip:7409) DEBUG: name = flip last_ts = 360.596039 last_received_ts = 360.595215 last_seq = 1275 current_ts = 360.612701 current_received_ts = 360.611908 current_seq = 1276 count = 165 seq_step = 1 [358.487201] (kms_flip:7409) DEBUG: Vblank took 62us [358.503795] (kms_flip:7409) DEBUG: name = flip last_ts = 360.612701 last_received_ts = 360.611908 last_seq = 1276 current_ts = 360.629395 current_received_ts = 360.628571 current_seq = 1277 count = 166 seq_step = 1 [358.503863] (kms_flip:7409) DEBUG: Vblank took 62us [358.520452] (kms_flip:7409) DEBUG: name = flip last_ts = 360.629395 last_received_ts = 360.628571 last_seq = 1277 current_ts = 360.646057 current_received_ts = 360.645264 current_seq = 1278 count = 167 seq_step = 1 [358.520519] (kms_flip:7409) DEBUG: Vblank took 62us [358.537123] (kms_flip:7409) DEBUG: name = flip last_ts = 360.646057 last_received_ts = 360.645264 last_seq = 1278 current_ts = 360.662750 current_received_ts = 360.661957 current_seq = 1279 count = 168 seq_step = 1 [358.537212] (kms_flip:7409) DEBUG: Vblank took 84us [358.553791] (kms_flip:7409) DEBUG: name = flip last_ts = 360.662750 last_received_ts = 360.661957 last_seq = 1279 current_ts = 360.679443 current_received_ts = 360.678619 current_seq = 1280 count = 169 seq_step = 1 [358.553841] (kms_flip:7409) DEBUG: Vblank took 45us [358.570446] (kms_flip:7409) DEBUG: name = flip last_ts = 360.679443 last_received_ts = 360.678619 last_seq = 1280 current_ts = 360.696106 current_received_ts = 360.695312 current_seq = 1281 count = 170 seq_step = 1 [358.570513] (kms_flip:7409) DEBUG: Vblank took 61us [358.587116] (kms_flip:7409) DEBUG: name = flip last_ts = 360.696106 last_received_ts = 360.695312 last_seq = 1281 current_ts = 360.712799 current_received_ts = 360.712006 current_seq = 1282 count = 171 seq_step = 1 [358.587208] (kms_flip:7409) DEBUG: Vblank took 62us [358.603782] (kms_flip:7409) DEBUG: name = flip last_ts = 360.712799 last_received_ts = 360.712006 last_seq = 1282 current_ts = 360.729492 current_received_ts = 360.728668 current_seq = 1283 count = 172 seq_step = 1 [358.603850] (kms_flip:7409) DEBUG: Vblank took 63us [358.620436] (kms_flip:7409) DEBUG: name = flip last_ts = 360.729492 last_received_ts = 360.728668 last_seq = 1283 current_ts = 360.746155 current_received_ts = 360.745331 current_seq = 1284 count = 173 seq_step = 1 [358.620504] (kms_flip:7409) DEBUG: Vblank took 63us [358.637107] (kms_flip:7409) DEBUG: name = flip last_ts = 360.746155 last_received_ts = 360.745331 last_seq = 1284 current_ts = 360.762848 current_received_ts = 360.762024 current_seq = 1285 count = 174 seq_step = 1 [358.637175] (kms_flip:7409) DEBUG: Vblank took 62us [358.653779] (kms_flip:7409) DEBUG: name = flip last_ts = 360.762848 last_received_ts = 360.762024 last_seq = 1285 current_ts = 360.779510 current_received_ts = 360.778717 current_seq = 1286 count = 175 seq_step = 1 [358.653847] (kms_flip:7409) DEBUG: Vblank took 62us [358.670428] (kms_flip:7409) DEBUG: name = flip last_ts = 360.779510 last_received_ts = 360.778717 last_seq = 1286 current_ts = 360.796204 current_received_ts = 360.795380 current_seq = 1287 count = 176 seq_step = 1 [358.670495] (kms_flip:7409) DEBUG: Vblank took 62us [358.687099] (kms_flip:7409) DEBUG: name = flip last_ts = 360.796204 last_received_ts = 360.795380 last_seq = 1287 current_ts = 360.812897 current_received_ts = 360.812073 current_seq = 1288 count = 177 seq_step = 1 [358.687166] (kms_flip:7409) DEBUG: Vblank took 62us [358.703760] (kms_flip:7409) DEBUG: name = flip last_ts = 360.812897 last_received_ts = 360.812073 last_seq = 1288 current_ts = 360.829590 current_received_ts = 360.828766 current_seq = 1289 count = 178 seq_step = 1 [358.703827] (kms_flip:7409) DEBUG: Vblank took 62us [358.720431] (kms_flip:7409) DEBUG: name = flip last_ts = 360.829590 last_received_ts = 360.828766 last_seq = 1289 current_ts = 360.846252 current_received_ts = 360.845459 current_seq = 1290 count = 179 seq_step = 1 [358.720500] (kms_flip:7409) DEBUG: Vblank took 65us [358.737089] (kms_flip:7409) DEBUG: name = flip last_ts = 360.846252 last_received_ts = 360.845459 last_seq = 1290 current_ts = 360.862946 current_received_ts = 360.862122 current_seq = 1291 count = 180 seq_step = 1 [358.737156] (kms_flip:7409) DEBUG: Vblank took 61us [358.753755] (kms_flip:7409) DEBUG: name = flip last_ts = 360.862946 last_received_ts = 360.862122 last_seq = 1291 current_ts = 360.879608 current_received_ts = 360.878815 current_seq = 1292 count = 181 seq_step = 1 [358.753822] (kms_flip:7409) DEBUG: Vblank took 62us [358.770419] (kms_flip:7409) DEBUG: name = flip last_ts = 360.879608 last_received_ts = 360.878815 last_seq = 1292 current_ts = 360.896301 current_received_ts = 360.895477 current_seq = 1293 count = 182 seq_step = 1 [358.770485] (kms_flip:7409) DEBUG: Vblank took 62us [358.787080] (kms_flip:7409) DEBUG: name = flip last_ts = 360.896301 last_received_ts = 360.895477 last_seq = 1293 current_ts = 360.912964 current_received_ts = 360.912170 current_seq = 1294 count = 183 seq_step = 1 [358.787148] (kms_flip:7409) DEBUG: Vblank took 63us [358.803748] (kms_flip:7409) DEBUG: name = flip last_ts = 360.912964 last_received_ts = 360.912170 last_seq = 1294 current_ts = 360.929657 current_received_ts = 360.928864 current_seq = 1295 count = 184 seq_step = 1 [358.803815] (kms_flip:7409) DEBUG: Vblank took 63us [358.820412] (kms_flip:7409) DEBUG: name = flip last_ts = 360.929657 last_received_ts = 360.928864 last_seq = 1295 current_ts = 360.946350 current_received_ts = 360.945526 current_seq = 1296 count = 185 seq_step = 1 [358.820479] (kms_flip:7409) DEBUG: Vblank took 62us [358.837073] (kms_flip:7409) DEBUG: name = flip last_ts = 360.946350 last_received_ts = 360.945526 last_seq = 1296 current_ts = 360.963013 current_received_ts = 360.962219 current_seq = 1297 count = 186 seq_step = 1 [358.837145] (kms_flip:7409) DEBUG: Vblank took 65us [358.853753] (kms_flip:7409) DEBUG: name = flip last_ts = 360.963013 last_received_ts = 360.962219 last_seq = 1297 current_ts = 360.979706 current_received_ts = 360.978912 current_seq = 1298 count = 187 seq_step = 1 [358.853827] (kms_flip:7409) DEBUG: Vblank took 68us [358.870409] (kms_flip:7409) DEBUG: name = flip last_ts = 360.979706 last_received_ts = 360.978912 last_seq = 1298 current_ts = 360.996368 current_received_ts = 360.995575 current_seq = 1299 count = 188 seq_step = 1 [358.870476] (kms_flip:7409) DEBUG: Vblank took 62us [358.887061] (kms_flip:7409) DEBUG: name = flip last_ts = 360.996368 last_received_ts = 360.995575 last_seq = 1299 current_ts = 361.013062 current_received_ts = 361.012238 current_seq = 1300 count = 189 seq_step = 1 [358.887127] (kms_flip:7409) DEBUG: Vblank took 62us [358.903732] (kms_flip:7409) DEBUG: name = flip last_ts = 361.013062 last_received_ts = 361.012238 last_seq = 1300 current_ts = 361.029755 current_received_ts = 361.028931 current_seq = 1301 count = 190 seq_step = 1 [358.903820] (kms_flip:7409) DEBUG: Vblank took 84us [358.920396] (kms_flip:7409) DEBUG: name = flip last_ts = 361.029755 last_received_ts = 361.028931 last_seq = 1301 current_ts = 361.046417 current_received_ts = 361.045624 current_seq = 1302 count = 191 seq_step = 1 [358.920463] (kms_flip:7409) DEBUG: Vblank took 62us [358.937079] (kms_flip:7409) DEBUG: name = flip last_ts = 361.046417 last_received_ts = 361.045624 last_seq = 1302 current_ts = 361.063110 current_received_ts = 361.062317 current_seq = 1303 count = 192 seq_step = 1 [358.937159] (kms_flip:7409) DEBUG: Vblank took 71us [358.953765] (kms_flip:7409) DEBUG: name = flip last_ts = 361.063110 last_received_ts = 361.062317 last_seq = 1303 current_ts = 361.079773 current_received_ts = 361.078979 current_seq = 1304 count = 193 seq_step = 1 [358.953841] (kms_flip:7409) DEBUG: Vblank took 70us [358.970397] (kms_flip:7409) DEBUG: name = flip last_ts = 361.079773 last_received_ts = 361.078979 last_seq = 1304 current_ts = 361.096466 current_received_ts = 361.095673 current_seq = 1305 count = 194 seq_step = 1 [358.970473] (kms_flip:7409) DEBUG: Vblank took 69us [358.987055] (kms_flip:7409) DEBUG: name = flip last_ts = 361.096466 last_received_ts = 361.095673 last_seq = 1305 current_ts = 361.113129 current_received_ts = 361.112335 current_seq = 1306 count = 195 seq_step = 1 [358.987129] (kms_flip:7409) DEBUG: Vblank took 67us [359.003737] (kms_flip:7409) DEBUG: name = flip last_ts = 361.113129 last_received_ts = 361.112335 last_seq = 1306 current_ts = 361.129822 current_received_ts = 361.129028 current_seq = 1307 count = 196 seq_step = 1 [359.003807] (kms_flip:7409) DEBUG: Vblank took 64us [359.020384] (kms_flip:7409) DEBUG: name = flip last_ts = 361.129822 last_received_ts = 361.129028 last_seq = 1307 current_ts = 361.146515 current_received_ts = 361.145691 current_seq = 1308 count = 197 seq_step = 1 [359.020452] (kms_flip:7409) DEBUG: Vblank took 63us [359.037039] (kms_flip:7409) DEBUG: name = flip last_ts = 361.146515 last_received_ts = 361.145691 last_seq = 1308 current_ts = 361.163177 current_received_ts = 361.162384 current_seq = 1309 count = 198 seq_step = 1 [359.037108] (kms_flip:7409) DEBUG: Vblank took 63us [359.053710] (kms_flip:7409) DEBUG: name = flip last_ts = 361.163177 last_received_ts = 361.162384 last_seq = 1309 current_ts = 361.179871 current_received_ts = 361.179047 current_seq = 1310 count = 199 seq_step = 1 [359.053778] (kms_flip:7409) DEBUG: Vblank took 63us [359.070407] (kms_flip:7409) DEBUG: name = flip last_ts = 361.179871 last_received_ts = 361.179047 last_seq = 1310 current_ts = 361.196533 current_received_ts = 361.195770 current_seq = 1311 count = 200 seq_step = 1 [359.070485] (kms_flip:7409) DEBUG: Vblank took 69us [359.087054] (kms_flip:7409) DEBUG: name = flip last_ts = 361.196533 last_received_ts = 361.195770 last_seq = 1311 current_ts = 361.213226 current_received_ts = 361.212433 current_seq = 1312 count = 201 seq_step = 1 [359.087130] (kms_flip:7409) DEBUG: Vblank took 69us [359.103710] (kms_flip:7409) DEBUG: name = flip last_ts = 361.213226 last_received_ts = 361.212433 last_seq = 1312 current_ts = 361.229889 current_received_ts = 361.229095 current_seq = 1313 count = 202 seq_step = 1 [359.103786] (kms_flip:7409) DEBUG: Vblank took 68us [359.120372] (kms_flip:7409) DEBUG: name = flip last_ts = 361.229889 last_received_ts = 361.229095 last_seq = 1313 current_ts = 361.246582 current_received_ts = 361.245789 current_seq = 1314 count = 203 seq_step = 1 [359.120446] (kms_flip:7409) DEBUG: Vblank took 69us [359.137030] (kms_flip:7409) DEBUG: name = flip last_ts = 361.246582 last_received_ts = 361.245789 last_seq = 1314 current_ts = 361.263245 current_received_ts = 361.262451 current_seq = 1315 count = 204 seq_step = 1 [359.137097] (kms_flip:7409) DEBUG: Vblank took 62us [359.153692] (kms_flip:7409) DEBUG: name = flip last_ts = 361.263245 last_received_ts = 361.262451 last_seq = 1315 current_ts = 361.279938 current_received_ts = 361.279144 current_seq = 1316 count = 205 seq_step = 1 [359.153759] (kms_flip:7409) DEBUG: Vblank took 62us [359.170357] (kms_flip:7409) DEBUG: name = flip last_ts = 361.279938 last_received_ts = 361.279144 last_seq = 1316 current_ts = 361.296631 current_received_ts = 361.295807 current_seq = 1317 count = 206 seq_step = 1 [359.170424] (kms_flip:7409) DEBUG: Vblank took 63us [359.187028] (kms_flip:7409) DEBUG: name = flip last_ts = 361.296631 last_received_ts = 361.295807 last_seq = 1317 current_ts = 361.313293 current_received_ts = 361.312500 current_seq = 1318 count = 207 seq_step = 1 [359.187102] (kms_flip:7409) DEBUG: Vblank took 68us [359.203691] (kms_flip:7409) DEBUG: name = flip last_ts = 361.313293 last_received_ts = 361.312500 last_seq = 1318 current_ts = 361.329987 current_received_ts = 361.329163 current_seq = 1319 count = 208 seq_step = 1 [359.203765] (kms_flip:7409) DEBUG: Vblank took 68us [359.220356] (kms_flip:7409) DEBUG: name = flip last_ts = 361.329987 last_received_ts = 361.329163 last_seq = 1319 current_ts = 361.346680 current_received_ts = 361.345856 current_seq = 1320 count = 209 seq_step = 1 [359.220430] (kms_flip:7409) DEBUG: Vblank took 68us [359.237020] (kms_flip:7409) DEBUG: name = flip last_ts = 361.346680 last_received_ts = 361.345856 last_seq = 1320 current_ts = 361.363342 current_received_ts = 361.362549 current_seq = 1321 count = 210 seq_step = 1 [359.237093] (kms_flip:7409) DEBUG: Vblank took 67us [359.253668] (kms_flip:7409) DEBUG: name = flip last_ts = 361.363342 last_received_ts = 361.362549 last_seq = 1321 current_ts = 361.380005 current_received_ts = 361.379211 current_seq = 1322 count = 211 seq_step = 1 [359.253737] (kms_flip:7409) DEBUG: Vblank took 63us [359.270340] (kms_flip:7409) DEBUG: name = flip last_ts = 361.380005 last_received_ts = 361.379211 last_seq = 1322 current_ts = 361.396698 current_received_ts = 361.395905 current_seq = 1323 count = 212 seq_step = 1 [359.270407] (kms_flip:7409) DEBUG: Vblank took 63us [359.287004] (kms_flip:7409) DEBUG: name = flip last_ts = 361.396698 last_received_ts = 361.395905 last_seq = 1323 current_ts = 361.413391 current_received_ts = 361.412567 current_seq = 1324 count = 213 seq_step = 1 [359.287072] (kms_flip:7409) DEBUG: Vblank took 62us [359.303681] (kms_flip:7409) DEBUG: name = flip last_ts = 361.413391 last_received_ts = 361.412567 last_seq = 1324 current_ts = 361.430054 current_received_ts = 361.429260 current_seq = 1325 count = 214 seq_step = 1 [359.303754] (kms_flip:7409) DEBUG: Vblank took 65us [359.320495] (kms_flip:7409) DEBUG: name = flip last_ts = 361.430054 last_received_ts = 361.429260 last_seq = 1325 current_ts = 361.446747 current_received_ts = 361.445984 current_seq = 1326 count = 215 seq_step = 1 [359.320611] (kms_flip:7409) DEBUG: Vblank took 95us [359.337032] (kms_flip:7409) DEBUG: name = flip last_ts = 361.446747 last_received_ts = 361.445984 last_seq = 1326 current_ts = 361.463409 current_received_ts = 361.462646 current_seq = 1327 count = 216 seq_step = 1 [359.337115] (kms_flip:7409) DEBUG: Vblank took 73us [359.353668] (kms_flip:7409) DEBUG: name = flip last_ts = 361.463409 last_received_ts = 361.462646 last_seq = 1327 current_ts = 361.480103 current_received_ts = 361.479309 current_seq = 1328 count = 217 seq_step = 1 [359.353744] (kms_flip:7409) DEBUG: Vblank took 70us [359.370344] (kms_flip:7409) DEBUG: name = flip last_ts = 361.480103 last_received_ts = 361.479309 last_seq = 1328 current_ts = 361.496765 current_received_ts = 361.496002 current_seq = 1329 count = 218 seq_step = 1 [359.370443] (kms_flip:7409) DEBUG: Vblank took 69us [359.386987] (kms_flip:7409) DEBUG: name = flip last_ts = 361.496765 last_received_ts = 361.496002 last_seq = 1329 current_ts = 361.513458 current_received_ts = 361.512634 current_seq = 1330 count = 219 seq_step = 1 [359.387055] (kms_flip:7409) DEBUG: Vblank took 63us [359.403647] (kms_flip:7409) DEBUG: name = flip last_ts = 361.513458 last_received_ts = 361.512634 last_seq = 1330 current_ts = 361.530121 current_received_ts = 361.529327 current_seq = 1331 count = 220 seq_step = 1 [359.403715] (kms_flip:7409) DEBUG: Vblank took 63us [359.420343] (kms_flip:7409) DEBUG: name = flip last_ts = 361.530121 last_received_ts = 361.529327 last_seq = 1331 current_ts = 361.546814 current_received_ts = 361.546021 current_seq = 1332 count = 221 seq_step = 1 [359.421552] (kms_flip:7409) DEBUG: Vblank took 1183us [359.421573] (kms_flip:7409) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [359.421701] (kms_flip:7409) CRITICAL: Failed assertion: end - start < 500 [359.436809] (kms_flip:7409) igt_core-INFO: Stack trace: [359.450848] (kms_flip:7409) igt_core-INFO: #0 ../lib/igt_core.c:2106 __igt_fail_assert() [359.452031] (kms_flip:7409) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [359.452103] (kms_flip:7409) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [359.452134] (kms_flip:7409) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() [359.452160] (kms_flip:7409) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [359.455516] (kms_flip:7409) igt_core-INFO: #5 [__libc_init_first+0x8a] [359.456152] (kms_flip:7409) igt_core-INFO: #6 [__libc_start_main+0x8b] [359.456365] (kms_flip:7409) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-eDP1: FAIL (5.088s)
Dmesg	<6> [371.266145] Console: switching to colour dummy device 80x25 <6> [371.266478] [IGT] kms_flip: executing <7> [371.274144] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [371.274153] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [371.274314] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [371.274427] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [371.274696] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [371.274700] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [371.274829] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [371.274923] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [371.275167] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [371.275170] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [371.275302] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [371.275395] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <7> [371.275682] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] <7> [371.275687] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:393:eDP-1] <7> [371.276146] xe 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [xe]] DSC DPCD: 00 11 00 76 0b 01 01 80 00 01 06 66 08 00 00 00 <7> [371.276543] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000 <7> [371.276664] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [371.276781] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [371.276903] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Supported Monitor Refresh rate range is 40 Hz - 120 Hz <5> [371.276907] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [371.276909] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [371.276910] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00 <7> [371.276912] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc. <5> [371.276913] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [371.276915] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor <5> [371.276917] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [371.276918] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0 <5> [371.276920] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [371.276932] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes <7> [371.277036] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps <7> [371.277131] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no <5> [371.277441] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [371.277444] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [371.277446] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [371.277487] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes: <7> [371.277491] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [371.277495] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 120 695310 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [371.277507] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [371.277510] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [371.277647] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [371.277657] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [371.277660] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [371.277781] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [371.277789] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [371.277791] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [371.277907] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <6> [371.278484] [IGT] kms_flip: starting subtest flip-vs-expired-vblank <6> [371.279912] [IGT] kms_flip: starting dynamic subtest A-eDP1 <7> [371.281050] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431] <7> [371.281522] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [371.358148] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [371.358391] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [371.358717] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [371.358968] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [371.359210] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [371.359509] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [371.359740] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [371.359959] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [371.360166] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [371.360390] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [371.360585] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [371.360772] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [371.360953] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [371.361121] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [371.361299] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [371.361467] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [371.361628] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [371.361786] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [371.361942] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [371.362092] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [371.362248] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [371.362392] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [371.362534] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [371.362674] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [371.362829] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [371.362985] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [371.363121] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [371.363264] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [371.363409] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [371.363538] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [371.363662] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [371.363787] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [371.363906] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [371.364025] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [371.364145] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [371.364271] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [371.364389] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [371.364505] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [371.364622] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [371.364741] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [371.364855] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [371.365029] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [371.365128] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [371.365268] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0 <7> [371.365355] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [371.365434] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm <7> [371.365511] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 1, 13, 13, 13, 13, 13, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [371.365586] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 24, 313, 313, 313, 313, 313, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [371.365658] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 28, 346, 346, 346, 346, 346, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [371.365752] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [371.365875] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 34060 required 0 qgv_peak_bw: 38400 <7> [371.365985] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [371.366092] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [371.366197] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [371.366322] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [371.366435] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [371.366571] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [371.366696] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [371.366809] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [371.366906] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [371.367031] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [371.367126] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [371.367220] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [371.367366] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [371.367474] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [371.367573] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [371.367660] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [371.367800] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [371.367900] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [371.368035] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [371.368668] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [371.368793] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [371.574151] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [371.574846] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [371.580307] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [371.580696] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [371.580755] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [371.581110] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [371.581365] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [371.633284] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [371.633671] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [371.640911] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [371.641350] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [371.641520] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [371.642052] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [371.642878] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [371.643410] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [371.643959] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [371.644307] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [371.644627] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [371.645030] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [371.645340] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [371.645646] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [371.646027] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [371.646321] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [371.646610] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [371.646917] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [371.647204] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [371.647482] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [371.647764] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [371.648106] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [371.648482] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [371.648757] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [371.649107] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [371.649588] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [371.650021] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [371.650494] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [371.650882] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [371.651321] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [371.651631] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [371.652502] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [371.652894] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [371.653196] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [371.653266] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [371.653448] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [371.653895] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:151:pipe A] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [371.654232] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [371.654557] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [371.654890] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:151:pipe A] <7> [371.655196] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [371.655490] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [371.655766] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [371.656125] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [371.656387] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [371.656639] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [371.656904] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [371.657173] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [371.657390] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [371.657619] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [371.657816] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [371.658050] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [371.658279] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [371.658471] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [371.658645] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [371.658850] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [371.659028] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [371.659186] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [371.659348] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [371.659506] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [371.659653] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [371.659802] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [371.659970] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [371.660108] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [371.660263] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [371.660418] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [371.660562] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [371.660701] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [371.660843] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [371.660988] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [371.661132] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [371.661253] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [371.661383] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [371.661516] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [371.661646] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [371.661760] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [371.661980] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [371.662087] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 0, found 432000) <7> [371.662190] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [371.662330] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [371.662417] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x1 <7> [371.662517] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [371.662605] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [371.662688] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [371.662760] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [371.662846] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [371.662923] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [371.663014] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1 <7> [371.663138] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23529 required 1461 qgv_peak_bw: 38400 <7> [371.663235] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36259 required 1461 qgv_peak_bw: 38400 <7> [371.663327] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [371.663416] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [371.663504] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [371.663590] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 0 kHz -> 173855 kHz <7> [371.663694] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [371.663789] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [371.663910] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [371.664024] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [371.664141] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0 <7> [371.664222] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0 <7> [371.664306] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: yes [modeset] <7> [371.664393] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [371.664479] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: A, pipe bpp: 30, dithering: 0 <7> [371.664560] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [371.664658] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [371.664764] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [371.664872] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [371.664989] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [371.665110] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [371.665231] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [371.665331] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [371.665429] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [371.665522] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [371.665607] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [371.665694] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [371.665778] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [371.665901] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [371.666017] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [371.666119] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [371.666204] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [371.666288] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [371.666371] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [371.666452] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 37 vsync start: 103, vsync end: 97 <7> [371.666528] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1869, vmax vblank: 1869, vmin vtotal: 1906, vmax vtotal: 1906 <7> [371.666603] xe 0000:00:02.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> [371.666683] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [371.666776] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [371.666892] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [371.667003] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [371.667108] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [371.667214] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0 <7> [371.667327] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [371.667428] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [371.667516] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [371.667600] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [371.667677] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [371.667755] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [371.667864] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [371.667983] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [371.668098] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [371.668192] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [371.668274] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [371.668356] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [371.668434] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [371.668510] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [371.668584] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [371.668659] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [371.668739] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [371.668834] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [371.668953] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [371.669067] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [371.669178] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [371.669273] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [371.669370] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [371.669464] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [371.669544] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [371.669682] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [371.669762] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [371.669873] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [371.669986] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [FB:431] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [371.670089] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [371.670176] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [371.670257] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [371.670337] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [371.670419] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [371.670495] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [371.670572] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [371.670858] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [371.671033] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [371.671177] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [371.671337] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [371.671465] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [371.671636] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A <7> [371.671784] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xa8000000) <7> [371.671963] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [371.672108] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [371.672210] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [371.672303] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [371.672381] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [371.672452] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [371.672520] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [371.672588] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [371.672655] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [371.672732] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [371.672829] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [371.672936] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [371.672899] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [371.673032] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [371.673054] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [371.673130] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [371.673156] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [371.673218] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [371.673266] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [371.673306] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [371.673415] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [371.673584] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [371.673654] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [371.673761] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [371.674844] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A] <7> [371.674976] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [371.677004] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [371.677124] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (465 ms remaining) <7> [372.149405] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [372.180194] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [372.180601] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [372.180957] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [372.217633] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [372.218152] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [372.218558] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [372.219188] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [372.333157] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [372.333242] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [372.333257] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [372.390168] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [372.390587] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [372.390967] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [372.393040] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [372.394534] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [372.395274] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [372.396375] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [372.397669] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [372.398733] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [372.399085] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [372.400480] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [372.400793] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [372.401589] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A <7> [372.402136] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [372.402510] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A <7> [372.402906] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [372.435841] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [372.437457] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [372.437765] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [374.953967] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off <7> [374.954565] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [376.171687] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [376.172390] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [376.173034] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [376.368526] [IGT] kms_flip: finished subtest A-eDP1, FAIL

Detail

Value

Duration

5.09 seconds

Hostname

shard-lnl-3

Igt-Version

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

Out

Using IGT_SRANDOM=1780008533 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2106 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2184 __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 A-eDP1: FAIL (5.088s)

Err

Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
[359.421573] (kms_flip:7409) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[359.421701] (kms_flip:7409) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
[357.403966] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.511688
last_received_ts = 359.510864
last_seq = 1210
current_ts = 359.528381
current_received_ts = 359.527557
current_seq = 1211
count = 100
seq_step = 1
[357.404028] (kms_flip:7409) DEBUG: Vblank took 58us
[357.420619] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.528381
last_received_ts = 359.527557
last_seq = 1211
current_ts = 359.545044
current_received_ts = 359.544220
current_seq = 1212
count = 101
seq_step = 1
[357.420682] (kms_flip:7409) DEBUG: Vblank took 58us
[357.437295] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.545044
last_received_ts = 359.544220
last_seq = 1212
current_ts = 359.561737
current_received_ts = 359.560913
current_seq = 1213
count = 102
seq_step = 1
[357.437358] (kms_flip:7409) DEBUG: Vblank took 58us
[357.453963] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.561737
last_received_ts = 359.560913
last_seq = 1213
current_ts = 359.578430
current_received_ts = 359.577606
current_seq = 1214
count = 103
seq_step = 1
[357.454030] (kms_flip:7409) DEBUG: Vblank took 62us
[357.470621] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.578430
last_received_ts = 359.577606
last_seq = 1214
current_ts = 359.595093
current_received_ts = 359.594299
current_seq = 1215
count = 104
seq_step = 1
[357.470689] (kms_flip:7409) DEBUG: Vblank took 63us
[357.487291] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.595093
last_received_ts = 359.594299
last_seq = 1215
current_ts = 359.611786
current_received_ts = 359.610962
current_seq = 1216
count = 105
seq_step = 1
[357.487383] (kms_flip:7409) DEBUG: Vblank took 86us
[357.503958] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.611786
last_received_ts = 359.610962
last_seq = 1216
current_ts = 359.628479
current_received_ts = 359.627655
current_seq = 1217
count = 106
seq_step = 1
[357.504024] (kms_flip:7409) DEBUG: Vblank took 62us
[357.520608] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.628479
last_received_ts = 359.627655
last_seq = 1217
current_ts = 359.645142
current_received_ts = 359.644318
current_seq = 1218
count = 107
seq_step = 1
[357.520675] (kms_flip:7409) DEBUG: Vblank took 63us
[357.537296] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.645142
last_received_ts = 359.644318
last_seq = 1218
current_ts = 359.661835
current_received_ts = 359.661041
current_seq = 1219
count = 108
seq_step = 1
[357.537362] (kms_flip:7409) DEBUG: Vblank took 62us
[357.553948] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.661835
last_received_ts = 359.661041
last_seq = 1219
current_ts = 359.678528
current_received_ts = 359.677704
current_seq = 1220
count = 109
seq_step = 1
[357.554015] (kms_flip:7409) DEBUG: Vblank took 61us
[357.570604] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.678528
last_received_ts = 359.677704
last_seq = 1220
current_ts = 359.695190
current_received_ts = 359.694397
current_seq = 1221
count = 110
seq_step = 1
[357.570671] (kms_flip:7409) DEBUG: Vblank took 63us
[357.587267] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.695190
last_received_ts = 359.694397
last_seq = 1221
current_ts = 359.711884
current_received_ts = 359.711060
current_seq = 1222
count = 111
seq_step = 1
[357.587330] (kms_flip:7409) DEBUG: Vblank took 57us
[357.603939] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.711884
last_received_ts = 359.711060
last_seq = 1222
current_ts = 359.728577
current_received_ts = 359.727753
current_seq = 1223
count = 112
seq_step = 1
[357.604005] (kms_flip:7409) DEBUG: Vblank took 62us
[357.620602] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.728577
last_received_ts = 359.727753
last_seq = 1223
current_ts = 359.745239
current_received_ts = 359.744446
current_seq = 1224
count = 113
seq_step = 1
[357.620669] (kms_flip:7409) DEBUG: Vblank took 62us
[357.637278] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.745239
last_received_ts = 359.744446
last_seq = 1224
current_ts = 359.761932
current_received_ts = 359.761139
current_seq = 1225
count = 114
seq_step = 1
[357.637340] (kms_flip:7409) DEBUG: Vblank took 58us
[357.653926] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.761932
last_received_ts = 359.761139
last_seq = 1225
current_ts = 359.778625
current_received_ts = 359.777802
current_seq = 1226
count = 115
seq_step = 1
[357.653990] (kms_flip:7409) DEBUG: Vblank took 58us
[357.670597] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.778625
last_received_ts = 359.777802
last_seq = 1226
current_ts = 359.795288
current_received_ts = 359.794495
current_seq = 1227
count = 116
seq_step = 1
[357.670664] (kms_flip:7409) DEBUG: Vblank took 62us
[357.687252] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.795288
last_received_ts = 359.794495
last_seq = 1227
current_ts = 359.811981
current_received_ts = 359.811157
current_seq = 1228
count = 117
seq_step = 1
[357.687320] (kms_flip:7409) DEBUG: Vblank took 62us
[357.703925] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.811981
last_received_ts = 359.811157
last_seq = 1228
current_ts = 359.828674
current_received_ts = 359.827850
current_seq = 1229
count = 118
seq_step = 1
[357.703994] (kms_flip:7409) DEBUG: Vblank took 63us
[357.720590] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.828674
last_received_ts = 359.827850
last_seq = 1229
current_ts = 359.845337
current_received_ts = 359.844543
current_seq = 1230
count = 119
seq_step = 1
[357.720657] (kms_flip:7409) DEBUG: Vblank took 63us
[357.737245] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.845337
last_received_ts = 359.844543
last_seq = 1230
current_ts = 359.862030
current_received_ts = 359.861206
current_seq = 1231
count = 120
seq_step = 1
[357.737313] (kms_flip:7409) DEBUG: Vblank took 63us
[357.753911] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.862030
last_received_ts = 359.861206
last_seq = 1231
current_ts = 359.878723
current_received_ts = 359.877899
current_seq = 1232
count = 121
seq_step = 1
[357.753979] (kms_flip:7409) DEBUG: Vblank took 63us
[357.770577] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.878723
last_received_ts = 359.877899
last_seq = 1232
current_ts = 359.895386
current_received_ts = 359.894592
current_seq = 1233
count = 122
seq_step = 1
[357.770646] (kms_flip:7409) DEBUG: Vblank took 63us
[357.787226] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.895386
last_received_ts = 359.894592
last_seq = 1233
current_ts = 359.912079
current_received_ts = 359.911255
current_seq = 1234
count = 123
seq_step = 1
[357.787290] (kms_flip:7409) DEBUG: Vblank took 59us
[357.803896] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.912079
last_received_ts = 359.911255
last_seq = 1234
current_ts = 359.928772
current_received_ts = 359.927948
current_seq = 1235
count = 124
seq_step = 1
[357.803978] (kms_flip:7409) DEBUG: Vblank took 77us
[357.820564] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.928772
last_received_ts = 359.927948
last_seq = 1235
current_ts = 359.945435
current_received_ts = 359.944641
current_seq = 1236
count = 125
seq_step = 1
[357.820628] (kms_flip:7409) DEBUG: Vblank took 58us
[357.837227] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.945435
last_received_ts = 359.944641
last_seq = 1236
current_ts = 359.962128
current_received_ts = 359.961304
current_seq = 1237
count = 126
seq_step = 1
[357.837295] (kms_flip:7409) DEBUG: Vblank took 62us
[357.853922] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.962128
last_received_ts = 359.961304
last_seq = 1237
current_ts = 359.978790
current_received_ts = 359.977997
current_seq = 1238
count = 127
seq_step = 1
[357.853990] (kms_flip:7409) DEBUG: Vblank took 63us
[357.870594] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.978790
last_received_ts = 359.977997
last_seq = 1238
current_ts = 359.995483
current_received_ts = 359.994690
current_seq = 1239
count = 128
seq_step = 1
[357.870678] (kms_flip:7409) DEBUG: Vblank took 74us
[357.887251] (kms_flip:7409) DEBUG: name = flip
last_ts = 359.995483
last_received_ts = 359.994690
last_seq = 1239
current_ts = 360.012177
current_received_ts = 360.011383
current_seq = 1240
count = 129
seq_step = 1
[357.887331] (kms_flip:7409) DEBUG: Vblank took 72us
[357.903894] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.012177
last_received_ts = 360.011383
last_seq = 1240
current_ts = 360.028870
current_received_ts = 360.028046
current_seq = 1241
count = 130
seq_step = 1
[357.903962] (kms_flip:7409) DEBUG: Vblank took 62us
[357.920555] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.028870
last_received_ts = 360.028046
last_seq = 1241
current_ts = 360.045532
current_received_ts = 360.044739
current_seq = 1242
count = 131
seq_step = 1
[357.920621] (kms_flip:7409) DEBUG: Vblank took 61us
[357.937212] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.045532
last_received_ts = 360.044739
last_seq = 1242
current_ts = 360.062225
current_received_ts = 360.061401
current_seq = 1243
count = 132
seq_step = 1
[357.937280] (kms_flip:7409) DEBUG: Vblank took 62us
[357.953882] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.062225
last_received_ts = 360.061401
last_seq = 1243
current_ts = 360.078888
current_received_ts = 360.078094
current_seq = 1244
count = 133
seq_step = 1
[357.953949] (kms_flip:7409) DEBUG: Vblank took 63us
[357.970546] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.078888
last_received_ts = 360.078094
last_seq = 1244
current_ts = 360.095581
current_received_ts = 360.094757
current_seq = 1245
count = 134
seq_step = 1
[357.970612] (kms_flip:7409) DEBUG: Vblank took 62us
[357.987212] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.095581
last_received_ts = 360.094757
last_seq = 1245
current_ts = 360.112244
current_received_ts = 360.111450
current_seq = 1246
count = 135
seq_step = 1
[357.987280] (kms_flip:7409) DEBUG: Vblank took 62us
[358.003875] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.112244
last_received_ts = 360.111450
last_seq = 1246
current_ts = 360.128937
current_received_ts = 360.128143
current_seq = 1247
count = 136
seq_step = 1
[358.003943] (kms_flip:7409) DEBUG: Vblank took 63us
[358.020542] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.128937
last_received_ts = 360.128143
last_seq = 1247
current_ts = 360.145630
current_received_ts = 360.144806
current_seq = 1248
count = 137
seq_step = 1
[358.020609] (kms_flip:7409) DEBUG: Vblank took 62us
[358.037205] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.145630
last_received_ts = 360.144806
last_seq = 1248
current_ts = 360.162323
current_received_ts = 360.161499
current_seq = 1249
count = 138
seq_step = 1
[358.037273] (kms_flip:7409) DEBUG: Vblank took 63us
[358.053853] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.162323
last_received_ts = 360.161499
last_seq = 1249
current_ts = 360.178986
current_received_ts = 360.178162
current_seq = 1250
count = 139
seq_step = 1
[358.053914] (kms_flip:7409) DEBUG: Vblank took 57us
[358.070529] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.178986
last_received_ts = 360.178162
last_seq = 1250
current_ts = 360.195679
current_received_ts = 360.194855
current_seq = 1251
count = 140
seq_step = 1
[358.070595] (kms_flip:7409) DEBUG: Vblank took 61us
[358.087193] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.195679
last_received_ts = 360.194855
last_seq = 1251
current_ts = 360.212341
current_received_ts = 360.211548
current_seq = 1252
count = 141
seq_step = 1
[358.087262] (kms_flip:7409) DEBUG: Vblank took 64us
[358.103851] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.212341
last_received_ts = 360.211548
last_seq = 1252
current_ts = 360.229034
current_received_ts = 360.228210
current_seq = 1253
count = 142
seq_step = 1
[358.103918] (kms_flip:7409) DEBUG: Vblank took 63us
[358.120520] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.229034
last_received_ts = 360.228210
last_seq = 1253
current_ts = 360.245728
current_received_ts = 360.244904
current_seq = 1254
count = 143
seq_step = 1
[358.120586] (kms_flip:7409) DEBUG: Vblank took 62us
[358.137187] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.245728
last_received_ts = 360.244904
last_seq = 1254
current_ts = 360.262390
current_received_ts = 360.261597
current_seq = 1255
count = 144
seq_step = 1
[358.137255] (kms_flip:7409) DEBUG: Vblank took 64us
[358.153842] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.262390
last_received_ts = 360.261597
last_seq = 1255
current_ts = 360.279083
current_received_ts = 360.278259
current_seq = 1256
count = 145
seq_step = 1
[358.153909] (kms_flip:7409) DEBUG: Vblank took 62us
[358.170514] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.279083
last_received_ts = 360.278259
last_seq = 1256
current_ts = 360.295776
current_received_ts = 360.294952
current_seq = 1257
count = 146
seq_step = 1
[358.170602] (kms_flip:7409) DEBUG: Vblank took 82us
[358.187179] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.295776
last_received_ts = 360.294952
last_seq = 1257
current_ts = 360.312439
current_received_ts = 360.311646
current_seq = 1258
count = 147
seq_step = 1
[358.187245] (kms_flip:7409) DEBUG: Vblank took 61us
[358.203835] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.312439
last_received_ts = 360.311646
last_seq = 1258
current_ts = 360.329132
current_received_ts = 360.328308
current_seq = 1259
count = 148
seq_step = 1
[358.203902] (kms_flip:7409) DEBUG: Vblank took 63us
[358.220528] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.329132
last_received_ts = 360.328308
last_seq = 1259
current_ts = 360.345795
current_received_ts = 360.345001
current_seq = 1260
count = 149
seq_step = 1
[358.220595] (kms_flip:7409) DEBUG: Vblank took 62us
[358.237254] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.345795
last_received_ts = 360.345001
last_seq = 1260
current_ts = 360.362488
current_received_ts = 360.361755
current_seq = 1261
count = 150
seq_step = 1
[358.237361] (kms_flip:7409) DEBUG: Vblank took 93us
[358.253875] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.362488
last_received_ts = 360.361755
last_seq = 1261
current_ts = 360.379181
current_received_ts = 360.378387
current_seq = 1262
count = 151
seq_step = 1
[358.253962] (kms_flip:7409) DEBUG: Vblank took 79us
[358.270512] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.379181
last_received_ts = 360.378387
last_seq = 1262
current_ts = 360.395844
current_received_ts = 360.395050
current_seq = 1263
count = 152
seq_step = 1
[358.270586] (kms_flip:7409) DEBUG: Vblank took 69us
[358.287170] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.395844
last_received_ts = 360.395050
last_seq = 1263
current_ts = 360.412537
current_received_ts = 360.411743
current_seq = 1264
count = 153
seq_step = 1
[358.287243] (kms_flip:7409) DEBUG: Vblank took 68us
[358.303825] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.412537
last_received_ts = 360.411743
last_seq = 1264
current_ts = 360.429199
current_received_ts = 360.428406
current_seq = 1265
count = 154
seq_step = 1
[358.303898] (kms_flip:7409) DEBUG: Vblank took 68us
[358.320496] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.429199
last_received_ts = 360.428406
last_seq = 1265
current_ts = 360.445892
current_received_ts = 360.445099
current_seq = 1266
count = 155
seq_step = 1
[358.320564] (kms_flip:7409) DEBUG: Vblank took 63us
[358.337154] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.445892
last_received_ts = 360.445099
last_seq = 1266
current_ts = 360.462585
current_received_ts = 360.461761
current_seq = 1267
count = 156
seq_step = 1
[358.337222] (kms_flip:7409) DEBUG: Vblank took 63us
[358.353820] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.462585
last_received_ts = 360.461761
last_seq = 1267
current_ts = 360.479248
current_received_ts = 360.478455
current_seq = 1268
count = 157
seq_step = 1
[358.353889] (kms_flip:7409) DEBUG: Vblank took 63us
[358.370483] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.479248
last_received_ts = 360.478455
last_seq = 1268
current_ts = 360.495941
current_received_ts = 360.495117
current_seq = 1269
count = 158
seq_step = 1
[358.370551] (kms_flip:7409) DEBUG: Vblank took 62us
[358.387148] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.495941
last_received_ts = 360.495117
last_seq = 1269
current_ts = 360.512634
current_received_ts = 360.511810
current_seq = 1270
count = 159
seq_step = 1
[358.387215] (kms_flip:7409) DEBUG: Vblank took 62us
[358.403811] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.512634
last_received_ts = 360.511810
last_seq = 1270
current_ts = 360.529297
current_received_ts = 360.528503
current_seq = 1271
count = 160
seq_step = 1
[358.403880] (kms_flip:7409) DEBUG: Vblank took 63us
[358.420470] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.529297
last_received_ts = 360.528503
last_seq = 1271
current_ts = 360.545990
current_received_ts = 360.545166
current_seq = 1272
count = 161
seq_step = 1
[358.420537] (kms_flip:7409) DEBUG: Vblank took 62us
[358.437139] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.545990
last_received_ts = 360.545166
last_seq = 1272
current_ts = 360.562683
current_received_ts = 360.561859
current_seq = 1273
count = 162
seq_step = 1
[358.437206] (kms_flip:7409) DEBUG: Vblank took 63us
[358.453798] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.562683
last_received_ts = 360.561859
last_seq = 1273
current_ts = 360.579346
current_received_ts = 360.578522
current_seq = 1274
count = 163
seq_step = 1
[358.453863] (kms_flip:7409) DEBUG: Vblank took 59us
[358.470452] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.579346
last_received_ts = 360.578522
last_seq = 1274
current_ts = 360.596039
current_received_ts = 360.595215
current_seq = 1275
count = 164
seq_step = 1
[358.470516] (kms_flip:7409) DEBUG: Vblank took 59us
[358.487134] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.596039
last_received_ts = 360.595215
last_seq = 1275
current_ts = 360.612701
current_received_ts = 360.611908
current_seq = 1276
count = 165
seq_step = 1
[358.487201] (kms_flip:7409) DEBUG: Vblank took 62us
[358.503795] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.612701
last_received_ts = 360.611908
last_seq = 1276
current_ts = 360.629395
current_received_ts = 360.628571
current_seq = 1277
count = 166
seq_step = 1
[358.503863] (kms_flip:7409) DEBUG: Vblank took 62us
[358.520452] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.629395
last_received_ts = 360.628571
last_seq = 1277
current_ts = 360.646057
current_received_ts = 360.645264
current_seq = 1278
count = 167
seq_step = 1
[358.520519] (kms_flip:7409) DEBUG: Vblank took 62us
[358.537123] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.646057
last_received_ts = 360.645264
last_seq = 1278
current_ts = 360.662750
current_received_ts = 360.661957
current_seq = 1279
count = 168
seq_step = 1
[358.537212] (kms_flip:7409) DEBUG: Vblank took 84us
[358.553791] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.662750
last_received_ts = 360.661957
last_seq = 1279
current_ts = 360.679443
current_received_ts = 360.678619
current_seq = 1280
count = 169
seq_step = 1
[358.553841] (kms_flip:7409) DEBUG: Vblank took 45us
[358.570446] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.679443
last_received_ts = 360.678619
last_seq = 1280
current_ts = 360.696106
current_received_ts = 360.695312
current_seq = 1281
count = 170
seq_step = 1
[358.570513] (kms_flip:7409) DEBUG: Vblank took 61us
[358.587116] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.696106
last_received_ts = 360.695312
last_seq = 1281
current_ts = 360.712799
current_received_ts = 360.712006
current_seq = 1282
count = 171
seq_step = 1
[358.587208] (kms_flip:7409) DEBUG: Vblank took 62us
[358.603782] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.712799
last_received_ts = 360.712006
last_seq = 1282
current_ts = 360.729492
current_received_ts = 360.728668
current_seq = 1283
count = 172
seq_step = 1
[358.603850] (kms_flip:7409) DEBUG: Vblank took 63us
[358.620436] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.729492
last_received_ts = 360.728668
last_seq = 1283
current_ts = 360.746155
current_received_ts = 360.745331
current_seq = 1284
count = 173
seq_step = 1
[358.620504] (kms_flip:7409) DEBUG: Vblank took 63us
[358.637107] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.746155
last_received_ts = 360.745331
last_seq = 1284
current_ts = 360.762848
current_received_ts = 360.762024
current_seq = 1285
count = 174
seq_step = 1
[358.637175] (kms_flip:7409) DEBUG: Vblank took 62us
[358.653779] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.762848
last_received_ts = 360.762024
last_seq = 1285
current_ts = 360.779510
current_received_ts = 360.778717
current_seq = 1286
count = 175
seq_step = 1
[358.653847] (kms_flip:7409) DEBUG: Vblank took 62us
[358.670428] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.779510
last_received_ts = 360.778717
last_seq = 1286
current_ts = 360.796204
current_received_ts = 360.795380
current_seq = 1287
count = 176
seq_step = 1
[358.670495] (kms_flip:7409) DEBUG: Vblank took 62us
[358.687099] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.796204
last_received_ts = 360.795380
last_seq = 1287
current_ts = 360.812897
current_received_ts = 360.812073
current_seq = 1288
count = 177
seq_step = 1
[358.687166] (kms_flip:7409) DEBUG: Vblank took 62us
[358.703760] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.812897
last_received_ts = 360.812073
last_seq = 1288
current_ts = 360.829590
current_received_ts = 360.828766
current_seq = 1289
count = 178
seq_step = 1
[358.703827] (kms_flip:7409) DEBUG: Vblank took 62us
[358.720431] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.829590
last_received_ts = 360.828766
last_seq = 1289
current_ts = 360.846252
current_received_ts = 360.845459
current_seq = 1290
count = 179
seq_step = 1
[358.720500] (kms_flip:7409) DEBUG: Vblank took 65us
[358.737089] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.846252
last_received_ts = 360.845459
last_seq = 1290
current_ts = 360.862946
current_received_ts = 360.862122
current_seq = 1291
count = 180
seq_step = 1
[358.737156] (kms_flip:7409) DEBUG: Vblank took 61us
[358.753755] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.862946
last_received_ts = 360.862122
last_seq = 1291
current_ts = 360.879608
current_received_ts = 360.878815
current_seq = 1292
count = 181
seq_step = 1
[358.753822] (kms_flip:7409) DEBUG: Vblank took 62us
[358.770419] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.879608
last_received_ts = 360.878815
last_seq = 1292
current_ts = 360.896301
current_received_ts = 360.895477
current_seq = 1293
count = 182
seq_step = 1
[358.770485] (kms_flip:7409) DEBUG: Vblank took 62us
[358.787080] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.896301
last_received_ts = 360.895477
last_seq = 1293
current_ts = 360.912964
current_received_ts = 360.912170
current_seq = 1294
count = 183
seq_step = 1
[358.787148] (kms_flip:7409) DEBUG: Vblank took 63us
[358.803748] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.912964
last_received_ts = 360.912170
last_seq = 1294
current_ts = 360.929657
current_received_ts = 360.928864
current_seq = 1295
count = 184
seq_step = 1
[358.803815] (kms_flip:7409) DEBUG: Vblank took 63us
[358.820412] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.929657
last_received_ts = 360.928864
last_seq = 1295
current_ts = 360.946350
current_received_ts = 360.945526
current_seq = 1296
count = 185
seq_step = 1
[358.820479] (kms_flip:7409) DEBUG: Vblank took 62us
[358.837073] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.946350
last_received_ts = 360.945526
last_seq = 1296
current_ts = 360.963013
current_received_ts = 360.962219
current_seq = 1297
count = 186
seq_step = 1
[358.837145] (kms_flip:7409) DEBUG: Vblank took 65us
[358.853753] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.963013
last_received_ts = 360.962219
last_seq = 1297
current_ts = 360.979706
current_received_ts = 360.978912
current_seq = 1298
count = 187
seq_step = 1
[358.853827] (kms_flip:7409) DEBUG: Vblank took 68us
[358.870409] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.979706
last_received_ts = 360.978912
last_seq = 1298
current_ts = 360.996368
current_received_ts = 360.995575
current_seq = 1299
count = 188
seq_step = 1
[358.870476] (kms_flip:7409) DEBUG: Vblank took 62us
[358.887061] (kms_flip:7409) DEBUG: name = flip
last_ts = 360.996368
last_received_ts = 360.995575
last_seq = 1299
current_ts = 361.013062
current_received_ts = 361.012238
current_seq = 1300
count = 189
seq_step = 1
[358.887127] (kms_flip:7409) DEBUG: Vblank took 62us
[358.903732] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.013062
last_received_ts = 361.012238
last_seq = 1300
current_ts = 361.029755
current_received_ts = 361.028931
current_seq = 1301
count = 190
seq_step = 1
[358.903820] (kms_flip:7409) DEBUG: Vblank took 84us
[358.920396] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.029755
last_received_ts = 361.028931
last_seq = 1301
current_ts = 361.046417
current_received_ts = 361.045624
current_seq = 1302
count = 191
seq_step = 1
[358.920463] (kms_flip:7409) DEBUG: Vblank took 62us
[358.937079] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.046417
last_received_ts = 361.045624
last_seq = 1302
current_ts = 361.063110
current_received_ts = 361.062317
current_seq = 1303
count = 192
seq_step = 1
[358.937159] (kms_flip:7409) DEBUG: Vblank took 71us
[358.953765] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.063110
last_received_ts = 361.062317
last_seq = 1303
current_ts = 361.079773
current_received_ts = 361.078979
current_seq = 1304
count = 193
seq_step = 1
[358.953841] (kms_flip:7409) DEBUG: Vblank took 70us
[358.970397] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.079773
last_received_ts = 361.078979
last_seq = 1304
current_ts = 361.096466
current_received_ts = 361.095673
current_seq = 1305
count = 194
seq_step = 1
[358.970473] (kms_flip:7409) DEBUG: Vblank took 69us
[358.987055] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.096466
last_received_ts = 361.095673
last_seq = 1305
current_ts = 361.113129
current_received_ts = 361.112335
current_seq = 1306
count = 195
seq_step = 1
[358.987129] (kms_flip:7409) DEBUG: Vblank took 67us
[359.003737] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.113129
last_received_ts = 361.112335
last_seq = 1306
current_ts = 361.129822
current_received_ts = 361.129028
current_seq = 1307
count = 196
seq_step = 1
[359.003807] (kms_flip:7409) DEBUG: Vblank took 64us
[359.020384] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.129822
last_received_ts = 361.129028
last_seq = 1307
current_ts = 361.146515
current_received_ts = 361.145691
current_seq = 1308
count = 197
seq_step = 1
[359.020452] (kms_flip:7409) DEBUG: Vblank took 63us
[359.037039] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.146515
last_received_ts = 361.145691
last_seq = 1308
current_ts = 361.163177
current_received_ts = 361.162384
current_seq = 1309
count = 198
seq_step = 1
[359.037108] (kms_flip:7409) DEBUG: Vblank took 63us
[359.053710] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.163177
last_received_ts = 361.162384
last_seq = 1309
current_ts = 361.179871
current_received_ts = 361.179047
current_seq = 1310
count = 199
seq_step = 1
[359.053778] (kms_flip:7409) DEBUG: Vblank took 63us
[359.070407] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.179871
last_received_ts = 361.179047
last_seq = 1310
current_ts = 361.196533
current_received_ts = 361.195770
current_seq = 1311
count = 200
seq_step = 1
[359.070485] (kms_flip:7409) DEBUG: Vblank took 69us
[359.087054] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.196533
last_received_ts = 361.195770
last_seq = 1311
current_ts = 361.213226
current_received_ts = 361.212433
current_seq = 1312
count = 201
seq_step = 1
[359.087130] (kms_flip:7409) DEBUG: Vblank took 69us
[359.103710] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.213226
last_received_ts = 361.212433
last_seq = 1312
current_ts = 361.229889
current_received_ts = 361.229095
current_seq = 1313
count = 202
seq_step = 1
[359.103786] (kms_flip:7409) DEBUG: Vblank took 68us
[359.120372] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.229889
last_received_ts = 361.229095
last_seq = 1313
current_ts = 361.246582
current_received_ts = 361.245789
current_seq = 1314
count = 203
seq_step = 1
[359.120446] (kms_flip:7409) DEBUG: Vblank took 69us
[359.137030] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.246582
last_received_ts = 361.245789
last_seq = 1314
current_ts = 361.263245
current_received_ts = 361.262451
current_seq = 1315
count = 204
seq_step = 1
[359.137097] (kms_flip:7409) DEBUG: Vblank took 62us
[359.153692] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.263245
last_received_ts = 361.262451
last_seq = 1315
current_ts = 361.279938
current_received_ts = 361.279144
current_seq = 1316
count = 205
seq_step = 1
[359.153759] (kms_flip:7409) DEBUG: Vblank took 62us
[359.170357] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.279938
last_received_ts = 361.279144
last_seq = 1316
current_ts = 361.296631
current_received_ts = 361.295807
current_seq = 1317
count = 206
seq_step = 1
[359.170424] (kms_flip:7409) DEBUG: Vblank took 63us
[359.187028] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.296631
last_received_ts = 361.295807
last_seq = 1317
current_ts = 361.313293
current_received_ts = 361.312500
current_seq = 1318
count = 207
seq_step = 1
[359.187102] (kms_flip:7409) DEBUG: Vblank took 68us
[359.203691] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.313293
last_received_ts = 361.312500
last_seq = 1318
current_ts = 361.329987
current_received_ts = 361.329163
current_seq = 1319
count = 208
seq_step = 1
[359.203765] (kms_flip:7409) DEBUG: Vblank took 68us
[359.220356] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.329987
last_received_ts = 361.329163
last_seq = 1319
current_ts = 361.346680
current_received_ts = 361.345856
current_seq = 1320
count = 209
seq_step = 1
[359.220430] (kms_flip:7409) DEBUG: Vblank took 68us
[359.237020] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.346680
last_received_ts = 361.345856
last_seq = 1320
current_ts = 361.363342
current_received_ts = 361.362549
current_seq = 1321
count = 210
seq_step = 1
[359.237093] (kms_flip:7409) DEBUG: Vblank took 67us
[359.253668] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.363342
last_received_ts = 361.362549
last_seq = 1321
current_ts = 361.380005
current_received_ts = 361.379211
current_seq = 1322
count = 211
seq_step = 1
[359.253737] (kms_flip:7409) DEBUG: Vblank took 63us
[359.270340] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.380005
last_received_ts = 361.379211
last_seq = 1322
current_ts = 361.396698
current_received_ts = 361.395905
current_seq = 1323
count = 212
seq_step = 1
[359.270407] (kms_flip:7409) DEBUG: Vblank took 63us
[359.287004] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.396698
last_received_ts = 361.395905
last_seq = 1323
current_ts = 361.413391
current_received_ts = 361.412567
current_seq = 1324
count = 213
seq_step = 1
[359.287072] (kms_flip:7409) DEBUG: Vblank took 62us
[359.303681] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.413391
last_received_ts = 361.412567
last_seq = 1324
current_ts = 361.430054
current_received_ts = 361.429260
current_seq = 1325
count = 214
seq_step = 1
[359.303754] (kms_flip:7409) DEBUG: Vblank took 65us
[359.320495] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.430054
last_received_ts = 361.429260
last_seq = 1325
current_ts = 361.446747
current_received_ts = 361.445984
current_seq = 1326
count = 215
seq_step = 1
[359.320611] (kms_flip:7409) DEBUG: Vblank took 95us
[359.337032] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.446747
last_received_ts = 361.445984
last_seq = 1326
current_ts = 361.463409
current_received_ts = 361.462646
current_seq = 1327
count = 216
seq_step = 1
[359.337115] (kms_flip:7409) DEBUG: Vblank took 73us
[359.353668] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.463409
last_received_ts = 361.462646
last_seq = 1327
current_ts = 361.480103
current_received_ts = 361.479309
current_seq = 1328
count = 217
seq_step = 1
[359.353744] (kms_flip:7409) DEBUG: Vblank took 70us
[359.370344] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.480103
last_received_ts = 361.479309
last_seq = 1328
current_ts = 361.496765
current_received_ts = 361.496002
current_seq = 1329
count = 218
seq_step = 1
[359.370443] (kms_flip:7409) DEBUG: Vblank took 69us
[359.386987] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.496765
last_received_ts = 361.496002
last_seq = 1329
current_ts = 361.513458
current_received_ts = 361.512634
current_seq = 1330
count = 219
seq_step = 1
[359.387055] (kms_flip:7409) DEBUG: Vblank took 63us
[359.403647] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.513458
last_received_ts = 361.512634
last_seq = 1330
current_ts = 361.530121
current_received_ts = 361.529327
current_seq = 1331
count = 220
seq_step = 1
[359.403715] (kms_flip:7409) DEBUG: Vblank took 63us
[359.420343] (kms_flip:7409) DEBUG: name = flip
last_ts = 361.530121
last_received_ts = 361.529327
last_seq = 1331
current_ts = 361.546814
current_received_ts = 361.546021
current_seq = 1332
count = 221
seq_step = 1
[359.421552] (kms_flip:7409) DEBUG: Vblank took 1183us
[359.421573] (kms_flip:7409) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[359.421701] (kms_flip:7409) CRITICAL: Failed assertion: end - start < 500
[359.436809] (kms_flip:7409) igt_core-INFO: Stack trace:
[359.450848] (kms_flip:7409) igt_core-INFO:   #0 ../lib/igt_core.c:2106 __igt_fail_assert()
[359.452031] (kms_flip:7409) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[359.452103] (kms_flip:7409) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[359.452134] (kms_flip:7409) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
[359.452160] (kms_flip:7409) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[359.455516] (kms_flip:7409) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[359.456152] (kms_flip:7409) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[359.456365] (kms_flip:7409) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (5.088s)

Dmesg

<6> [371.266145] Console: switching to colour dummy device 80x25

<6> [371.266478] [IGT] kms_flip: executing

<7> [371.274144] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

<7> [371.274153] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1]

<7> [371.274314] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [371.274427] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

<7> [371.274696] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2]

<7> [371.274700] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2]

<7> [371.274829] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [371.274923] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

<7> [371.275167] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3]

<7> [371.275170] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3]

<7> [371.275302] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [371.275395] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

<7> [371.275682] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1]

<7> [371.275687] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:393:eDP-1]

<7> [371.276146] xe 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [xe]] DSC DPCD: 00 11 00 76 0b 01 01 80 00 01 06 66 08 00 00 00

<7> [371.276543] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000

<7> [371.276664] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000

<7> [371.276781] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000

<7> [371.276903] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Supported Monitor Refresh rate range is 40 Hz - 120 Hz

<5> [371.276907] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [371.276909] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [371.276910] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00

<7> [371.276912] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc.

<5> [371.276913] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [371.276915] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor

<5> [371.276917] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [371.276918] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0

<5> [371.276920] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [371.276932] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes

<7> [371.277036] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps

<7> [371.277131] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no

<5> [371.277441] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [371.277444] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [371.277446] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [371.277487] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes:

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

<7> [371.277495] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 120 695310 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa

<7> [371.277507] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

<7> [371.277510] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1]

<7> [371.277647] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

<7> [371.277657] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2]

<7> [371.277660] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2]

<7> [371.277781] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

<7> [371.277789] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3]

<7> [371.277791] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3]

<7> [371.277907] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

<6> [371.278484] [IGT] kms_flip: starting subtest flip-vs-expired-vblank

<6> [371.279912] [IGT] kms_flip: starting dynamic subtest A-eDP1

<7> [371.281050] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431]

<7> [371.281522] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432]

<7> [371.358148] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [371.364855] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0

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

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

<7> [371.365268] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0

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

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

<7> [371.365511] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 1, 13, 13, 13, 13, 13, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [371.365586] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 24, 313, 313, 313, 313, 313, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [371.365658] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 28, 346, 346, 346, 346, 346, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

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

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

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

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

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

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

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

<7> [371.366571] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz

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

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

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

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

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

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

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

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

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

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

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

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

<7> [371.368035] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2

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

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

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

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

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

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

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

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

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

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

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

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

<7> [371.641350] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A]

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

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

<7> [371.642878] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [371.650021] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000)

<7> [371.650494] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A]

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

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

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

<7> [371.652502] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B]

<7> [371.652894] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C]

<7> [371.653196] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

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

<7> [371.653448] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)

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

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

<7> [371.654557] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0

<7> [371.654890] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:151:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [371.662517] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

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

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

<7> [371.662760] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0

<7> [371.662846] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197

<7> [371.662923] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198

<7> [371.663014] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1

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

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

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

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

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

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

<7> [371.663694] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz

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

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

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

<7> [371.664141] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0

<7> [371.664222] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0

<7> [371.664306] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: yes [modeset]

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

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

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

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

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

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

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

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

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

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

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

<7> [371.665522] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0

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

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

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

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

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

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

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

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

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

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

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

<7> [371.666603] xe 0000:00:02.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> [371.666683] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

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

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

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

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

<7> [371.667214] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0

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

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

<7> [371.667516] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0

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

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

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

<7> [371.667864] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no

<7> [371.667983] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

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

<7> [371.668192] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state:

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [371.671636] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A

<7> [371.671784] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xa8000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [371.674844] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A]

<7> [371.674976] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0

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

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

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

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

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

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

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

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

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

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

<7> [372.333157] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

<7> [372.333242] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

<7> [372.333257] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

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

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

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

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

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

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

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

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

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

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

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

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

<7> [372.401589] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A

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

<7> [372.402510] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A

<7> [372.402906] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518

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

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

<7> [372.437765] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A]

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

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

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

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

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

<6> [376.368526] [IGT] kms_flip: finished subtest A-eDP1, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank@a-edp1