igt@kms_flip@flip-vs-expired-vblank-interruptible@a-edp1 on shard-lnl@xe-5056-8b3420d629f66344dcf91b54c6c9bed8602001e3 Test details

Detail	Value
Duration	8.08 seconds
Hostname	shard-lnl-4
Igt-Version	IGT-Version: 2.4-ge68d82b44 (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5056-8b3420d629f66344d-debug+ x86_64)
Out	Using IGT_SRANDOM=1778753201 for randomisation Opened device: /dev/dri/card0 Using monotonic timestamps Starting subtest: flip-vs-expired-vblank-interruptible 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:2074 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-eDP1: FAIL (8.084s)
Err	Starting subtest: flip-vs-expired-vblank-interruptible Starting dynamic subtest: A-eDP1 [379.803667] (kms_flip:8588) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [379.803781] (kms_flip:8588) CRITICAL: Failed assertion: end - start < 500 [379.803858] (kms_flip:8588) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest A-eDP1 failed. ** DEBUG [377.785216] (kms_flip:8588) DEBUG: Vblank took 52us [377.801800] (kms_flip:8588) DEBUG: name = flip last_ts = 378.705292 last_received_ts = 378.704620 last_seq = 2055 current_ts = 378.721954 current_received_ts = 378.721252 current_seq = 2056 count = 289 seq_step = 1 [377.801843] (kms_flip:8588) DEBUG: Vblank took 41us [377.818485] (kms_flip:8588) DEBUG: name = flip last_ts = 378.721954 last_received_ts = 378.721252 last_seq = 2056 current_ts = 378.738617 current_received_ts = 378.737946 current_seq = 2057 count = 290 seq_step = 1 [377.818578] (kms_flip:8588) DEBUG: Vblank took 89us [377.835153] (kms_flip:8588) DEBUG: name = flip last_ts = 378.738617 last_received_ts = 378.737946 last_seq = 2057 current_ts = 378.755280 current_received_ts = 378.754608 current_seq = 2058 count = 291 seq_step = 1 [377.835216] (kms_flip:8588) DEBUG: Vblank took 59us [377.851812] (kms_flip:8588) DEBUG: name = flip last_ts = 378.755280 last_received_ts = 378.754608 last_seq = 2058 current_ts = 378.771942 current_received_ts = 378.771271 current_seq = 2059 count = 292 seq_step = 1 [377.851869] (kms_flip:8588) DEBUG: Vblank took 55us [377.868481] (kms_flip:8588) DEBUG: name = flip last_ts = 378.771942 last_received_ts = 378.771271 last_seq = 2059 current_ts = 378.788605 current_received_ts = 378.787933 current_seq = 2060 count = 293 seq_step = 1 [377.868555] (kms_flip:8588) DEBUG: Vblank took 70us [377.885149] (kms_flip:8588) DEBUG: name = flip last_ts = 378.788605 last_received_ts = 378.787933 last_seq = 2060 current_ts = 378.805267 current_received_ts = 378.804596 current_seq = 2061 count = 294 seq_step = 1 [377.885204] (kms_flip:8588) DEBUG: Vblank took 52us [377.901802] (kms_flip:8588) DEBUG: name = flip last_ts = 378.805267 last_received_ts = 378.804596 last_seq = 2061 current_ts = 378.821930 current_received_ts = 378.821259 current_seq = 2062 count = 295 seq_step = 1 [377.901870] (kms_flip:8588) DEBUG: Vblank took 64us [377.918463] (kms_flip:8588) DEBUG: name = flip last_ts = 378.821930 last_received_ts = 378.821259 last_seq = 2062 current_ts = 378.838623 current_received_ts = 378.837921 current_seq = 2063 count = 296 seq_step = 1 [377.918526] (kms_flip:8588) DEBUG: Vblank took 60us [377.935126] (kms_flip:8588) DEBUG: name = flip last_ts = 378.838623 last_received_ts = 378.837921 last_seq = 2063 current_ts = 378.855286 current_received_ts = 378.854584 current_seq = 2064 count = 297 seq_step = 1 [377.935183] (kms_flip:8588) DEBUG: Vblank took 53us [377.951801] (kms_flip:8588) DEBUG: name = flip last_ts = 378.855286 last_received_ts = 378.854584 last_seq = 2064 current_ts = 378.871948 current_received_ts = 378.871246 current_seq = 2065 count = 298 seq_step = 1 [377.951866] (kms_flip:8588) DEBUG: Vblank took 61us [377.968455] (kms_flip:8588) DEBUG: name = flip last_ts = 378.871948 last_received_ts = 378.871246 last_seq = 2065 current_ts = 378.888611 current_received_ts = 378.887909 current_seq = 2066 count = 299 seq_step = 1 [377.968508] (kms_flip:8588) DEBUG: Vblank took 51us [377.985127] (kms_flip:8588) DEBUG: name = flip last_ts = 378.888611 last_received_ts = 378.887909 last_seq = 2066 current_ts = 378.905273 current_received_ts = 378.904572 current_seq = 2067 count = 300 seq_step = 1 [377.985187] (kms_flip:8588) DEBUG: Vblank took 57us [378.001767] (kms_flip:8588) DEBUG: name = flip last_ts = 378.905273 last_received_ts = 378.904572 last_seq = 2067 current_ts = 378.921936 current_received_ts = 378.921234 current_seq = 2068 count = 301 seq_step = 1 [378.001824] (kms_flip:8588) DEBUG: Vblank took 54us [378.018443] (kms_flip:8588) DEBUG: name = flip last_ts = 378.921936 last_received_ts = 378.921234 last_seq = 2068 current_ts = 378.938599 current_received_ts = 378.937897 current_seq = 2069 count = 302 seq_step = 1 [378.018506] (kms_flip:8588) DEBUG: Vblank took 58us [378.035107] (kms_flip:8588) DEBUG: name = flip last_ts = 378.938599 last_received_ts = 378.937897 last_seq = 2069 current_ts = 378.955261 current_received_ts = 378.954559 current_seq = 2070 count = 303 seq_step = 1 [378.035163] (kms_flip:8588) DEBUG: Vblank took 52us [378.051792] (kms_flip:8588) DEBUG: name = flip last_ts = 378.955261 last_received_ts = 378.954559 last_seq = 2070 current_ts = 378.971924 current_received_ts = 378.971252 current_seq = 2071 count = 304 seq_step = 1 [378.051849] (kms_flip:8588) DEBUG: Vblank took 55us [378.068430] (kms_flip:8588) DEBUG: name = flip last_ts = 378.971924 last_received_ts = 378.971252 last_seq = 2071 current_ts = 378.988586 current_received_ts = 378.987885 current_seq = 2072 count = 305 seq_step = 1 [378.068487] (kms_flip:8588) DEBUG: Vblank took 54us [378.085106] (kms_flip:8588) DEBUG: name = flip last_ts = 378.988586 last_received_ts = 378.987885 last_seq = 2072 current_ts = 379.005249 current_received_ts = 379.004578 current_seq = 2073 count = 306 seq_step = 1 [378.085169] (kms_flip:8588) DEBUG: Vblank took 59us [378.101753] (kms_flip:8588) DEBUG: name = flip last_ts = 379.005249 last_received_ts = 379.004578 last_seq = 2073 current_ts = 379.021912 current_received_ts = 379.021210 current_seq = 2074 count = 307 seq_step = 1 [378.101811] (kms_flip:8588) DEBUG: Vblank took 55us [378.118447] (kms_flip:8588) DEBUG: name = flip last_ts = 379.021912 last_received_ts = 379.021210 last_seq = 2074 current_ts = 379.038574 current_received_ts = 379.037903 current_seq = 2075 count = 308 seq_step = 1 [378.118502] (kms_flip:8588) DEBUG: Vblank took 52us [378.135100] (kms_flip:8588) DEBUG: name = flip last_ts = 379.038574 last_received_ts = 379.037903 last_seq = 2075 current_ts = 379.055237 current_received_ts = 379.054565 current_seq = 2076 count = 309 seq_step = 1 [378.135153] (kms_flip:8588) DEBUG: Vblank took 50us [378.151742] (kms_flip:8588) DEBUG: name = flip last_ts = 379.055237 last_received_ts = 379.054565 last_seq = 2076 current_ts = 379.071899 current_received_ts = 379.071198 current_seq = 2077 count = 310 seq_step = 1 [378.151799] (kms_flip:8588) DEBUG: Vblank took 54us [378.168421] (kms_flip:8588) DEBUG: name = flip last_ts = 379.071899 last_received_ts = 379.071198 last_seq = 2077 current_ts = 379.088562 current_received_ts = 379.087891 current_seq = 2078 count = 311 seq_step = 1 [378.168477] (kms_flip:8588) DEBUG: Vblank took 53us [378.185076] (kms_flip:8588) DEBUG: name = flip last_ts = 379.088562 last_received_ts = 379.087891 last_seq = 2078 current_ts = 379.105225 current_received_ts = 379.104523 current_seq = 2079 count = 312 seq_step = 1 [378.185133] (kms_flip:8588) DEBUG: Vblank took 53us [378.201734] (kms_flip:8588) DEBUG: name = flip last_ts = 379.105225 last_received_ts = 379.104523 last_seq = 2079 current_ts = 379.121887 current_received_ts = 379.121185 current_seq = 2080 count = 313 seq_step = 1 [378.201813] (kms_flip:8588) DEBUG: Vblank took 75us [378.218440] (kms_flip:8588) DEBUG: name = flip last_ts = 379.121887 last_received_ts = 379.121185 last_seq = 2080 current_ts = 379.138550 current_received_ts = 379.137909 current_seq = 2081 count = 314 seq_step = 1 [378.218494] (kms_flip:8588) DEBUG: Vblank took 51us [378.235087] (kms_flip:8588) DEBUG: name = flip last_ts = 379.138550 last_received_ts = 379.137909 last_seq = 2081 current_ts = 379.155212 current_received_ts = 379.154541 current_seq = 2082 count = 315 seq_step = 1 [378.235145] (kms_flip:8588) DEBUG: Vblank took 55us [378.251731] (kms_flip:8588) DEBUG: name = flip last_ts = 379.155212 last_received_ts = 379.154541 last_seq = 2082 current_ts = 379.171875 current_received_ts = 379.171204 current_seq = 2083 count = 316 seq_step = 1 [378.251788] (kms_flip:8588) DEBUG: Vblank took 54us [378.268409] (kms_flip:8588) DEBUG: name = flip last_ts = 379.171875 last_received_ts = 379.171204 last_seq = 2083 current_ts = 379.188568 current_received_ts = 379.187866 current_seq = 2084 count = 317 seq_step = 1 [378.268471] (kms_flip:8588) DEBUG: Vblank took 58us [378.285081] (kms_flip:8588) DEBUG: name = flip last_ts = 379.188568 last_received_ts = 379.187866 last_seq = 2084 current_ts = 379.205231 current_received_ts = 379.204529 current_seq = 2085 count = 318 seq_step = 1 [378.285144] (kms_flip:8588) DEBUG: Vblank took 58us [378.301723] (kms_flip:8588) DEBUG: name = flip last_ts = 379.205231 last_received_ts = 379.204529 last_seq = 2085 current_ts = 379.221893 current_received_ts = 379.221191 current_seq = 2086 count = 319 seq_step = 1 [378.301780] (kms_flip:8588) DEBUG: Vblank took 54us [378.318403] (kms_flip:8588) DEBUG: name = flip last_ts = 379.221893 last_received_ts = 379.221191 last_seq = 2086 current_ts = 379.238556 current_received_ts = 379.237854 current_seq = 2087 count = 320 seq_step = 1 [378.318461] (kms_flip:8588) DEBUG: Vblank took 54us [378.335081] (kms_flip:8588) DEBUG: name = flip last_ts = 379.238556 last_received_ts = 379.237854 last_seq = 2087 current_ts = 379.255219 current_received_ts = 379.254547 current_seq = 2088 count = 321 seq_step = 1 [378.335141] (kms_flip:8588) DEBUG: Vblank took 56us [378.351717] (kms_flip:8588) DEBUG: name = flip last_ts = 379.255219 last_received_ts = 379.254547 last_seq = 2088 current_ts = 379.271881 current_received_ts = 379.271179 current_seq = 2089 count = 322 seq_step = 1 [378.351774] (kms_flip:8588) DEBUG: Vblank took 54us [378.368353] (kms_flip:8588) DEBUG: name = flip last_ts = 379.271881 last_received_ts = 379.271179 last_seq = 2089 current_ts = 379.288544 current_received_ts = 379.287811 current_seq = 2090 count = 323 seq_step = 1 [378.368420] (kms_flip:8588) DEBUG: Vblank took 64us [378.385047] (kms_flip:8588) DEBUG: name = flip last_ts = 379.288544 last_received_ts = 379.287811 last_seq = 2090 current_ts = 379.305206 current_received_ts = 379.304504 current_seq = 2091 count = 324 seq_step = 1 [378.385097] (kms_flip:8588) DEBUG: Vblank took 47us [378.401697] (kms_flip:8588) DEBUG: name = flip last_ts = 379.305206 last_received_ts = 379.304504 last_seq = 2091 current_ts = 379.321869 current_received_ts = 379.321167 current_seq = 2092 count = 325 seq_step = 1 [378.401747] (kms_flip:8588) DEBUG: Vblank took 47us [378.418390] (kms_flip:8588) DEBUG: name = flip last_ts = 379.321869 last_received_ts = 379.321167 last_seq = 2092 current_ts = 379.338531 current_received_ts = 379.337860 current_seq = 2093 count = 326 seq_step = 1 [378.418447] (kms_flip:8588) DEBUG: Vblank took 53us [378.435038] (kms_flip:8588) DEBUG: name = flip last_ts = 379.338531 last_received_ts = 379.337860 last_seq = 2093 current_ts = 379.355194 current_received_ts = 379.354492 current_seq = 2094 count = 327 seq_step = 1 [378.435084] (kms_flip:8588) DEBUG: Vblank took 43us [378.451706] (kms_flip:8588) DEBUG: name = flip last_ts = 379.355194 last_received_ts = 379.354492 last_seq = 2094 current_ts = 379.371857 current_received_ts = 379.371155 current_seq = 2095 count = 328 seq_step = 1 [378.451763] (kms_flip:8588) DEBUG: Vblank took 54us [378.468373] (kms_flip:8588) DEBUG: name = flip last_ts = 379.371857 last_received_ts = 379.371155 last_seq = 2095 current_ts = 379.388519 current_received_ts = 379.387848 current_seq = 2096 count = 329 seq_step = 1 [378.468433] (kms_flip:8588) DEBUG: Vblank took 56us [378.485053] (kms_flip:8588) DEBUG: name = flip last_ts = 379.388519 last_received_ts = 379.387848 last_seq = 2096 current_ts = 379.405182 current_received_ts = 379.404510 current_seq = 2097 count = 330 seq_step = 1 [378.485112] (kms_flip:8588) DEBUG: Vblank took 55us [378.501705] (kms_flip:8588) DEBUG: name = flip last_ts = 379.405182 last_received_ts = 379.404510 last_seq = 2097 current_ts = 379.421844 current_received_ts = 379.421173 current_seq = 2098 count = 331 seq_step = 1 [378.501762] (kms_flip:8588) DEBUG: Vblank took 54us [378.518377] (kms_flip:8588) DEBUG: name = flip last_ts = 379.421844 last_received_ts = 379.421173 last_seq = 2098 current_ts = 379.438507 current_received_ts = 379.437836 current_seq = 2099 count = 332 seq_step = 1 [378.518434] (kms_flip:8588) DEBUG: Vblank took 53us [378.535028] (kms_flip:8588) DEBUG: name = flip last_ts = 379.438507 last_received_ts = 379.437836 last_seq = 2099 current_ts = 379.455170 current_received_ts = 379.454498 current_seq = 2100 count = 333 seq_step = 1 [378.535085] (kms_flip:8588) DEBUG: Vblank took 53us [378.551664] (kms_flip:8588) DEBUG: name = flip last_ts = 379.455170 last_received_ts = 379.454498 last_seq = 2100 current_ts = 379.471832 current_received_ts = 379.471130 current_seq = 2101 count = 334 seq_step = 1 [378.551721] (kms_flip:8588) DEBUG: Vblank took 54us [378.568378] (kms_flip:8588) DEBUG: name = flip last_ts = 379.471832 last_received_ts = 379.471130 last_seq = 2101 current_ts = 379.488495 current_received_ts = 379.487854 current_seq = 2102 count = 335 seq_step = 1 [378.568446] (kms_flip:8588) DEBUG: Vblank took 64us [378.585046] (kms_flip:8588) DEBUG: name = flip last_ts = 379.488495 last_received_ts = 379.487854 last_seq = 2102 current_ts = 379.505188 current_received_ts = 379.504517 current_seq = 2103 count = 336 seq_step = 1 [378.585102] (kms_flip:8588) DEBUG: Vblank took 52us [378.601682] (kms_flip:8588) DEBUG: name = flip last_ts = 379.505188 last_received_ts = 379.504517 last_seq = 2103 current_ts = 379.521851 current_received_ts = 379.521149 current_seq = 2104 count = 337 seq_step = 1 [378.601743] (kms_flip:8588) DEBUG: Vblank took 58us [378.618349] (kms_flip:8588) DEBUG: name = flip last_ts = 379.521851 last_received_ts = 379.521149 last_seq = 2104 current_ts = 379.538483 current_received_ts = 379.537811 current_seq = 2105 count = 338 seq_step = 1 [378.618405] (kms_flip:8588) DEBUG: Vblank took 52us [378.635025] (kms_flip:8588) DEBUG: name = flip last_ts = 379.538483 last_received_ts = 379.537811 last_seq = 2105 current_ts = 379.555176 current_received_ts = 379.554474 current_seq = 2106 count = 339 seq_step = 1 [378.635080] (kms_flip:8588) DEBUG: Vblank took 52us [378.651663] (kms_flip:8588) DEBUG: name = flip last_ts = 379.555176 last_received_ts = 379.554474 last_seq = 2106 current_ts = 379.571838 current_received_ts = 379.571136 current_seq = 2107 count = 340 seq_step = 1 [378.651721] (kms_flip:8588) DEBUG: Vblank took 55us [378.668342] (kms_flip:8588) DEBUG: name = flip last_ts = 379.571838 last_received_ts = 379.571136 last_seq = 2107 current_ts = 379.588501 current_received_ts = 379.587799 current_seq = 2108 count = 341 seq_step = 1 [378.668399] (kms_flip:8588) DEBUG: Vblank took 53us [378.685015] (kms_flip:8588) DEBUG: name = flip last_ts = 379.588501 last_received_ts = 379.587799 last_seq = 2108 current_ts = 379.605164 current_received_ts = 379.604492 current_seq = 2109 count = 342 seq_step = 1 [378.685068] (kms_flip:8588) DEBUG: Vblank took 51us [378.701660] (kms_flip:8588) DEBUG: name = flip last_ts = 379.605164 last_received_ts = 379.604492 last_seq = 2109 current_ts = 379.621826 current_received_ts = 379.621124 current_seq = 2110 count = 343 seq_step = 1 [378.701717] (kms_flip:8588) DEBUG: Vblank took 54us [378.718343] (kms_flip:8588) DEBUG: name = flip last_ts = 379.621826 last_received_ts = 379.621124 last_seq = 2110 current_ts = 379.638489 current_received_ts = 379.637817 current_seq = 2111 count = 344 seq_step = 1 [378.718401] (kms_flip:8588) DEBUG: Vblank took 54us [378.735028] (kms_flip:8588) DEBUG: name = flip last_ts = 379.638489 last_received_ts = 379.637817 last_seq = 2111 current_ts = 379.655151 current_received_ts = 379.654480 current_seq = 2112 count = 345 seq_step = 1 [378.735086] (kms_flip:8588) DEBUG: Vblank took 54us [378.751646] (kms_flip:8588) DEBUG: name = flip last_ts = 379.655151 last_received_ts = 379.654480 last_seq = 2112 current_ts = 379.671814 current_received_ts = 379.671112 current_seq = 2113 count = 346 seq_step = 1 [378.751702] (kms_flip:8588) DEBUG: Vblank took 53us [378.768341] (kms_flip:8588) DEBUG: name = flip last_ts = 379.671814 last_received_ts = 379.671112 last_seq = 2113 current_ts = 379.688477 current_received_ts = 379.687805 current_seq = 2114 count = 347 seq_step = 1 [378.768403] (kms_flip:8588) DEBUG: Vblank took 58us [378.785021] (kms_flip:8588) DEBUG: name = flip last_ts = 379.688477 last_received_ts = 379.687805 last_seq = 2114 current_ts = 379.705139 current_received_ts = 379.704498 current_seq = 2115 count = 348 seq_step = 1 [378.785079] (kms_flip:8588) DEBUG: Vblank took 55us [378.801657] (kms_flip:8588) DEBUG: name = flip last_ts = 379.705139 last_received_ts = 379.704498 last_seq = 2115 current_ts = 379.721802 current_received_ts = 379.721130 current_seq = 2116 count = 349 seq_step = 1 [378.801719] (kms_flip:8588) DEBUG: Vblank took 59us [378.818327] (kms_flip:8588) DEBUG: name = flip last_ts = 379.721802 last_received_ts = 379.721130 last_seq = 2116 current_ts = 379.738464 current_received_ts = 379.737793 current_seq = 2117 count = 350 seq_step = 1 [378.818386] (kms_flip:8588) DEBUG: Vblank took 54us [378.834979] (kms_flip:8588) DEBUG: name = flip last_ts = 379.738464 last_received_ts = 379.737793 last_seq = 2117 current_ts = 379.755127 current_received_ts = 379.754456 current_seq = 2118 count = 351 seq_step = 1 [378.835038] (kms_flip:8588) DEBUG: Vblank took 55us [378.851601] (kms_flip:8588) DEBUG: name = flip last_ts = 379.755127 last_received_ts = 379.754456 last_seq = 2118 current_ts = 379.771790 current_received_ts = 379.771057 current_seq = 2119 count = 352 seq_step = 1 [378.851657] (kms_flip:8588) DEBUG: Vblank took 53us [378.868312] (kms_flip:8588) DEBUG: name = flip last_ts = 379.771790 last_received_ts = 379.771057 last_seq = 2119 current_ts = 379.788452 current_received_ts = 379.787781 current_seq = 2120 count = 353 seq_step = 1 [378.868368] (kms_flip:8588) DEBUG: Vblank took 53us [378.884968] (kms_flip:8588) DEBUG: name = flip last_ts = 379.788452 last_received_ts = 379.787781 last_seq = 2120 current_ts = 379.805115 current_received_ts = 379.804443 current_seq = 2121 count = 354 seq_step = 1 [378.885024] (kms_flip:8588) DEBUG: Vblank took 53us [378.901561] (kms_flip:8588) DEBUG: name = flip last_ts = 379.805115 last_received_ts = 379.804443 last_seq = 2121 current_ts = 379.821777 current_received_ts = 379.821014 current_seq = 2122 count = 355 seq_step = 1 [378.901619] (kms_flip:8588) DEBUG: Vblank took 56us [378.918315] (kms_flip:8588) DEBUG: name = flip last_ts = 379.821777 last_received_ts = 379.821014 last_seq = 2122 current_ts = 379.838440 current_received_ts = 379.837769 current_seq = 2123 count = 356 seq_step = 1 [378.918371] (kms_flip:8588) DEBUG: Vblank took 54us [378.934970] (kms_flip:8588) DEBUG: name = flip last_ts = 379.838440 last_received_ts = 379.837769 last_seq = 2123 current_ts = 379.855133 current_received_ts = 379.854431 current_seq = 2124 count = 357 seq_step = 1 [378.935028] (kms_flip:8588) DEBUG: Vblank took 55us [378.951626] (kms_flip:8588) DEBUG: name = flip last_ts = 379.855133 last_received_ts = 379.854431 last_seq = 2124 current_ts = 379.871796 current_received_ts = 379.871094 current_seq = 2125 count = 358 seq_step = 1 [378.951683] (kms_flip:8588) DEBUG: Vblank took 53us [378.968310] (kms_flip:8588) DEBUG: name = flip last_ts = 379.871796 last_received_ts = 379.871094 last_seq = 2125 current_ts = 379.888458 current_received_ts = 379.887787 current_seq = 2126 count = 359 seq_step = 1 [378.968370] (kms_flip:8588) DEBUG: Vblank took 57us [378.984855] (kms_flip:8588) DEBUG: name = flip last_ts = 379.888458 last_received_ts = 379.887787 last_seq = 2126 current_ts = 379.905121 current_received_ts = 379.904327 current_seq = 2127 count = 360 seq_step = 1 [378.984918] (kms_flip:8588) DEBUG: Vblank took 60us [379.001522] (kms_flip:8588) DEBUG: name = flip last_ts = 379.905121 last_received_ts = 379.904327 last_seq = 2127 current_ts = 379.921783 current_received_ts = 379.920990 current_seq = 2128 count = 361 seq_step = 1 [379.001595] (kms_flip:8588) DEBUG: Vblank took 70us [379.018281] (kms_flip:8588) DEBUG: name = flip last_ts = 379.921783 last_received_ts = 379.920990 last_seq = 2128 current_ts = 379.938446 current_received_ts = 379.937744 current_seq = 2129 count = 362 seq_step = 1 [379.018331] (kms_flip:8588) DEBUG: Vblank took 46us [379.034858] (kms_flip:8588) DEBUG: name = flip last_ts = 379.938446 last_received_ts = 379.937744 last_seq = 2129 current_ts = 379.955109 current_received_ts = 379.954315 current_seq = 2130 count = 363 seq_step = 1 [379.034901] (kms_flip:8588) DEBUG: Vblank took 39us [379.051626] (kms_flip:8588) DEBUG: name = flip last_ts = 379.955109 last_received_ts = 379.954315 last_seq = 2130 current_ts = 379.971771 current_received_ts = 379.971100 current_seq = 2131 count = 364 seq_step = 1 [379.051692] (kms_flip:8588) DEBUG: Vblank took 61us [379.068286] (kms_flip:8588) DEBUG: name = flip last_ts = 379.971771 last_received_ts = 379.971100 last_seq = 2131 current_ts = 379.988434 current_received_ts = 379.987762 current_seq = 2132 count = 365 seq_step = 1 [379.068339] (kms_flip:8588) DEBUG: Vblank took 49us [379.084975] (kms_flip:8588) DEBUG: name = flip last_ts = 379.988434 last_received_ts = 379.987762 last_seq = 2132 current_ts = 380.005096 current_received_ts = 380.004425 current_seq = 2133 count = 366 seq_step = 1 [379.085038] (kms_flip:8588) DEBUG: Vblank took 59us [379.101624] (kms_flip:8588) DEBUG: name = flip last_ts = 380.005096 last_received_ts = 380.004425 last_seq = 2133 current_ts = 380.021759 current_received_ts = 380.021088 current_seq = 2134 count = 367 seq_step = 1 [379.101687] (kms_flip:8588) DEBUG: Vblank took 59us [379.118271] (kms_flip:8588) DEBUG: name = flip last_ts = 380.021759 last_received_ts = 380.021088 last_seq = 2134 current_ts = 380.038422 current_received_ts = 380.037750 current_seq = 2135 count = 368 seq_step = 1 [379.118327] (kms_flip:8588) DEBUG: Vblank took 53us [379.134952] (kms_flip:8588) DEBUG: name = flip last_ts = 380.038422 last_received_ts = 380.037750 last_seq = 2135 current_ts = 380.055084 current_received_ts = 380.054413 current_seq = 2136 count = 369 seq_step = 1 [379.135014] (kms_flip:8588) DEBUG: Vblank took 58us [379.151606] (kms_flip:8588) DEBUG: name = flip last_ts = 380.055084 last_received_ts = 380.054413 last_seq = 2136 current_ts = 380.071747 current_received_ts = 380.071075 current_seq = 2137 count = 370 seq_step = 1 [379.151654] (kms_flip:8588) DEBUG: Vblank took 44us [379.168252] (kms_flip:8588) DEBUG: name = flip last_ts = 380.071747 last_received_ts = 380.071075 last_seq = 2137 current_ts = 380.088409 current_received_ts = 380.087708 current_seq = 2138 count = 371 seq_step = 1 [379.168294] (kms_flip:8588) DEBUG: Vblank took 39us [379.184927] (kms_flip:8588) DEBUG: name = flip last_ts = 380.088409 last_received_ts = 380.087708 last_seq = 2138 current_ts = 380.105072 current_received_ts = 380.104401 current_seq = 2139 count = 372 seq_step = 1 [379.184987] (kms_flip:8588) DEBUG: Vblank took 56us [379.201594] (kms_flip:8588) DEBUG: name = flip last_ts = 380.105072 last_received_ts = 380.104401 last_seq = 2139 current_ts = 380.121735 current_received_ts = 380.121063 current_seq = 2140 count = 373 seq_step = 1 [379.201653] (kms_flip:8588) DEBUG: Vblank took 56us [379.218256] (kms_flip:8588) DEBUG: name = flip last_ts = 380.121735 last_received_ts = 380.121063 last_seq = 2140 current_ts = 380.138397 current_received_ts = 380.137726 current_seq = 2141 count = 374 seq_step = 1 [379.218309] (kms_flip:8588) DEBUG: Vblank took 50us [379.234919] (kms_flip:8588) DEBUG: name = flip last_ts = 380.138397 last_received_ts = 380.137726 last_seq = 2141 current_ts = 380.155060 current_received_ts = 380.154388 current_seq = 2142 count = 375 seq_step = 1 [379.234975] (kms_flip:8588) DEBUG: Vblank took 52us [379.251591] (kms_flip:8588) DEBUG: name = flip last_ts = 380.155060 last_received_ts = 380.154388 last_seq = 2142 current_ts = 380.171753 current_received_ts = 380.171051 current_seq = 2143 count = 376 seq_step = 1 [379.251646] (kms_flip:8588) DEBUG: Vblank took 52us [379.268253] (kms_flip:8588) DEBUG: name = flip last_ts = 380.171753 last_received_ts = 380.171051 last_seq = 2143 current_ts = 380.188416 current_received_ts = 380.187714 current_seq = 2144 count = 377 seq_step = 1 [379.268309] (kms_flip:8588) DEBUG: Vblank took 53us [379.284901] (kms_flip:8588) DEBUG: name = flip last_ts = 380.188416 last_received_ts = 380.187714 last_seq = 2144 current_ts = 380.205078 current_received_ts = 380.204376 current_seq = 2145 count = 378 seq_step = 1 [379.284958] (kms_flip:8588) DEBUG: Vblank took 53us [379.301592] (kms_flip:8588) DEBUG: name = flip last_ts = 380.205078 last_received_ts = 380.204376 last_seq = 2145 current_ts = 380.221741 current_received_ts = 380.221069 current_seq = 2146 count = 379 seq_step = 1 [379.301642] (kms_flip:8588) DEBUG: Vblank took 47us [379.318244] (kms_flip:8588) DEBUG: name = flip last_ts = 380.221741 last_received_ts = 380.221069 last_seq = 2146 current_ts = 380.238403 current_received_ts = 380.237701 current_seq = 2147 count = 380 seq_step = 1 [379.318297] (kms_flip:8588) DEBUG: Vblank took 50us [379.334896] (kms_flip:8588) DEBUG: name = flip last_ts = 380.238403 last_received_ts = 380.237701 last_seq = 2147 current_ts = 380.255066 current_received_ts = 380.254364 current_seq = 2148 count = 381 seq_step = 1 [379.334952] (kms_flip:8588) DEBUG: Vblank took 52us [379.351594] (kms_flip:8588) DEBUG: name = flip last_ts = 380.255066 last_received_ts = 380.254364 last_seq = 2148 current_ts = 380.271729 current_received_ts = 380.271057 current_seq = 2149 count = 382 seq_step = 1 [379.351652] (kms_flip:8588) DEBUG: Vblank took 54us [379.368236] (kms_flip:8588) DEBUG: name = flip last_ts = 380.271729 last_received_ts = 380.271057 last_seq = 2149 current_ts = 380.288391 current_received_ts = 380.287689 current_seq = 2150 count = 383 seq_step = 1 [379.368292] (kms_flip:8588) DEBUG: Vblank took 52us [379.384911] (kms_flip:8588) DEBUG: name = flip last_ts = 380.288391 last_received_ts = 380.287689 last_seq = 2150 current_ts = 380.305054 current_received_ts = 380.304382 current_seq = 2151 count = 384 seq_step = 1 [379.384970] (kms_flip:8588) DEBUG: Vblank took 55us [379.401601] (kms_flip:8588) DEBUG: name = flip last_ts = 380.305054 last_received_ts = 380.304382 last_seq = 2151 current_ts = 380.321716 current_received_ts = 380.321075 current_seq = 2152 count = 385 seq_step = 1 [379.401659] (kms_flip:8588) DEBUG: Vblank took 56us [379.418213] (kms_flip:8588) DEBUG: name = flip last_ts = 380.321716 last_received_ts = 380.321075 last_seq = 2152 current_ts = 380.338379 current_received_ts = 380.337677 current_seq = 2153 count = 386 seq_step = 1 [379.418272] (kms_flip:8588) DEBUG: Vblank took 56us [379.434887] (kms_flip:8588) DEBUG: name = flip last_ts = 380.338379 last_received_ts = 380.337677 last_seq = 2153 current_ts = 380.355042 current_received_ts = 380.354340 current_seq = 2154 count = 387 seq_step = 1 [379.434942] (kms_flip:8588) DEBUG: Vblank took 52us [379.451546] (kms_flip:8588) DEBUG: name = flip last_ts = 380.355042 last_received_ts = 380.354340 last_seq = 2154 current_ts = 380.371704 current_received_ts = 380.371002 current_seq = 2155 count = 388 seq_step = 1 [379.451604] (kms_flip:8588) DEBUG: Vblank took 55us [379.468215] (kms_flip:8588) DEBUG: name = flip last_ts = 380.371704 last_received_ts = 380.371002 last_seq = 2155 current_ts = 380.388367 current_received_ts = 380.387695 current_seq = 2156 count = 389 seq_step = 1 [379.468274] (kms_flip:8588) DEBUG: Vblank took 55us [379.484897] (kms_flip:8588) DEBUG: name = flip last_ts = 380.388367 last_received_ts = 380.387695 last_seq = 2156 current_ts = 380.405029 current_received_ts = 380.404358 current_seq = 2157 count = 390 seq_step = 1 [379.484952] (kms_flip:8588) DEBUG: Vblank took 52us [379.501453] (kms_flip:8588) DEBUG: name = flip last_ts = 380.405029 last_received_ts = 380.404358 last_seq = 2157 current_ts = 380.421692 current_received_ts = 380.420929 current_seq = 2158 count = 391 seq_step = 1 [379.501510] (kms_flip:8588) DEBUG: Vblank took 54us [379.518215] (kms_flip:8588) DEBUG: name = flip last_ts = 380.421692 last_received_ts = 380.420929 last_seq = 2158 current_ts = 380.438354 current_received_ts = 380.437683 current_seq = 2159 count = 392 seq_step = 1 [379.518273] (kms_flip:8588) DEBUG: Vblank took 54us [379.534863] (kms_flip:8588) DEBUG: name = flip last_ts = 380.438354 last_received_ts = 380.437683 last_seq = 2159 current_ts = 380.455017 current_received_ts = 380.454346 current_seq = 2160 count = 393 seq_step = 1 [379.534925] (kms_flip:8588) DEBUG: Vblank took 58us [379.551500] (kms_flip:8588) DEBUG: name = flip last_ts = 380.455017 last_received_ts = 380.454346 last_seq = 2160 current_ts = 380.471680 current_received_ts = 380.470978 current_seq = 2161 count = 394 seq_step = 1 [379.551574] (kms_flip:8588) DEBUG: Vblank took 71us [379.568207] (kms_flip:8588) DEBUG: name = flip last_ts = 380.471680 last_received_ts = 380.470978 last_seq = 2161 current_ts = 380.488342 current_received_ts = 380.487671 current_seq = 2162 count = 395 seq_step = 1 [379.568267] (kms_flip:8588) DEBUG: Vblank took 57us [379.584876] (kms_flip:8588) DEBUG: name = flip last_ts = 380.488342 last_received_ts = 380.487671 last_seq = 2162 current_ts = 380.505005 current_received_ts = 380.504333 current_seq = 2163 count = 396 seq_step = 1 [379.584931] (kms_flip:8588) DEBUG: Vblank took 52us [379.601556] (kms_flip:8588) DEBUG: name = flip last_ts = 380.505005 last_received_ts = 380.504333 last_seq = 2163 current_ts = 380.521667 current_received_ts = 380.521027 current_seq = 2164 count = 397 seq_step = 1 [379.601596] (kms_flip:8588) DEBUG: Vblank took 38us [379.618181] (kms_flip:8588) DEBUG: name = flip last_ts = 380.521667 last_received_ts = 380.521027 last_seq = 2164 current_ts = 380.538330 current_received_ts = 380.537659 current_seq = 2165 count = 398 seq_step = 1 [379.618230] (kms_flip:8588) DEBUG: Vblank took 46us [379.634865] (kms_flip:8588) DEBUG: name = flip last_ts = 380.538330 last_received_ts = 380.537659 last_seq = 2165 current_ts = 380.555023 current_received_ts = 380.554321 current_seq = 2166 count = 399 seq_step = 1 [379.634929] (kms_flip:8588) DEBUG: Vblank took 60us [379.651487] (kms_flip:8588) DEBUG: name = flip last_ts = 380.555023 last_received_ts = 380.554321 last_seq = 2166 current_ts = 380.571686 current_received_ts = 380.570953 current_seq = 2167 count = 400 seq_step = 1 [379.651559] (kms_flip:8588) DEBUG: Vblank took 69us [379.668195] (kms_flip:8588) DEBUG: name = flip last_ts = 380.571686 last_received_ts = 380.570953 last_seq = 2167 current_ts = 380.588348 current_received_ts = 380.587677 current_seq = 2168 count = 401 seq_step = 1 [379.668284] (kms_flip:8588) DEBUG: Vblank took 84us [379.684857] (kms_flip:8588) DEBUG: name = flip last_ts = 380.588348 last_received_ts = 380.587677 last_seq = 2168 current_ts = 380.605011 current_received_ts = 380.604309 current_seq = 2169 count = 402 seq_step = 1 [379.684917] (kms_flip:8588) DEBUG: Vblank took 54us [379.701509] (kms_flip:8588) DEBUG: name = flip last_ts = 380.605011 last_received_ts = 380.604309 last_seq = 2169 current_ts = 380.621674 current_received_ts = 380.620972 current_seq = 2170 count = 403 seq_step = 1 [379.701594] (kms_flip:8588) DEBUG: Vblank took 82us [379.718175] (kms_flip:8588) DEBUG: name = flip last_ts = 380.621674 last_received_ts = 380.620972 last_seq = 2170 current_ts = 380.638336 current_received_ts = 380.637634 current_seq = 2171 count = 404 seq_step = 1 [379.718234] (kms_flip:8588) DEBUG: Vblank took 55us [379.734842] (kms_flip:8588) DEBUG: name = flip last_ts = 380.638336 last_received_ts = 380.637634 last_seq = 2171 current_ts = 380.654999 current_received_ts = 380.654297 current_seq = 2172 count = 405 seq_step = 1 [379.734902] (kms_flip:8588) DEBUG: Vblank took 57us [379.751508] (kms_flip:8588) DEBUG: name = flip last_ts = 380.654999 last_received_ts = 380.654297 last_seq = 2172 current_ts = 380.671661 current_received_ts = 380.670990 current_seq = 2173 count = 406 seq_step = 1 [379.751577] (kms_flip:8588) DEBUG: Vblank took 67us [379.768163] (kms_flip:8588) DEBUG: name = flip last_ts = 380.671661 last_received_ts = 380.670990 last_seq = 2173 current_ts = 380.688324 current_received_ts = 380.687622 current_seq = 2174 count = 407 seq_step = 1 [379.768218] (kms_flip:8588) DEBUG: Vblank took 52us [379.784813] (kms_flip:8588) DEBUG: name = flip last_ts = 380.688324 last_received_ts = 380.687622 last_seq = 2174 current_ts = 380.704987 current_received_ts = 380.704285 current_seq = 2175 count = 408 seq_step = 1 [379.784870] (kms_flip:8588) DEBUG: Vblank took 54us [379.801498] (kms_flip:8588) DEBUG: name = flip last_ts = 380.704987 last_received_ts = 380.704285 last_seq = 2175 current_ts = 380.721649 current_received_ts = 380.720978 current_seq = 2176 count = 409 seq_step = 1 [379.803653] (kms_flip:8588) DEBUG: Vblank took 2141us [379.803667] (kms_flip:8588) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [379.803781] (kms_flip:8588) CRITICAL: Failed assertion: end - start < 500 [379.803858] (kms_flip:8588) CRITICAL: Last errno: 4, Interrupted system call [379.826524] (kms_flip:8588) igt_core-INFO: Stack trace: [379.842131] (kms_flip:8588) igt_core-INFO: #0 ../lib/igt_core.c:2074 __igt_fail_assert() [379.843338] (kms_flip:8588) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [379.843404] (kms_flip:8588) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [379.843436] (kms_flip:8588) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() [379.843479] (kms_flip:8588) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [379.848113] (kms_flip:8588) igt_core-INFO: #5 [__libc_init_first+0x8a] [379.848845] (kms_flip:8588) igt_core-INFO: #6 [__libc_start_main+0x8b] [379.849014] (kms_flip:8588) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-eDP1: FAIL (8.084s)
Dmesg	<6> [402.840884] Console: switching to colour dummy device 80x25 <6> [402.841195] [IGT] kms_flip: executing <7> [402.849020] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [402.849030] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [402.849184] 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> [402.849280] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [402.849494] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [402.849497] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [402.849642] 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> [402.849755] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [402.849982] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [402.849985] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [402.850100] 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> [402.850184] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <7> [402.850405] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] <7> [402.850408] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:393:eDP-1] <7> [402.850875] 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> [402.851198] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000 <7> [402.851312] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [402.851425] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [402.851545] 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> [402.851729] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [402.851732] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [402.851733] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00 <7> [402.851737] 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> [402.851740] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [402.851742] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor <5> [402.851746] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [402.851747] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0 <5> [402.851750] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [402.851767] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes <7> [402.851900] 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> [402.852086] 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> [402.852423] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [402.852426] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [402.852428] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [402.852478] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes: <7> [402.852482] 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> [402.852485] 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> [402.852498] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [402.852501] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [402.852658] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [402.852669] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [402.852672] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [402.852793] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [402.852801] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [402.852803] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [402.852915] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <6> [402.856463] [IGT] kms_flip: starting subtest flip-vs-expired-vblank-interruptible <6> [402.857782] [IGT] kms_flip: starting dynamic subtest A-eDP1 <7> [402.858653] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431] <7> [402.859096] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [402.916670] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [402.916764] 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> [402.916922] 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> [402.917032] 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> [402.917127] 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> [402.917223] 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> [402.917318] 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> [402.917412] 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> [402.917505] 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> [402.917614] 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> [402.917727] 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> [402.917849] 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> [402.917947] 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> [402.918036] 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> [402.918124] 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> [402.918211] 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> [402.918297] 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> [402.918379] 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> [402.918463] 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> [402.918551] 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> [402.918637] 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> [402.918727] 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> [402.918815] 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> [402.918902] 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> [402.918982] 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> [402.919060] 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> [402.919139] 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> [402.919216] 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> [402.919294] 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> [402.919370] 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> [402.919447] 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> [402.919524] 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> [402.919613] 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> [402.919696] 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> [402.919779] 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> [402.919861] 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> [402.919936] 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> [402.920011] 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> [402.920085] 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> [402.920161] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [402.920237] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [402.920347] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [402.920416] 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> [402.920503] 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> [402.920585] 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> [402.920655] 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> [402.920718] 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> [402.920780] 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> [402.920842] 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> [402.920925] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [402.921014] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400 <7> [402.921101] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400 <7> [402.921188] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [402.921275] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [402.921360] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [402.921446] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [402.921568] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [402.921674] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [402.921782] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [402.921883] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [402.921990] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [402.922085] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [402.922182] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [402.922277] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [402.922361] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [402.922445] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [402.922525] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [402.922733] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [402.922847] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [402.923005] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [402.940132] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [402.940530] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [403.145702] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [403.146200] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [403.157890] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [403.158208] 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> [403.158524] 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> [403.210726] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [403.211222] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [403.219735] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [403.220223] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [403.220287] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [403.221879] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [403.222472] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [403.223115] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [403.223485] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [403.223893] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [403.224321] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [403.224717] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [403.225048] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [403.225424] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [403.225774] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [403.226084] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [403.226393] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [403.226732] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [403.227040] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [403.227345] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [403.227681] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [403.228077] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [403.228375] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [403.228759] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [403.229375] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [403.229870] 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> [403.230403] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [403.230838] 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> [403.231312] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [403.231739] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [403.232673] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [403.233057] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [403.233400] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [403.233473] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [403.233675] 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> [403.234045] 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> [403.234359] 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> [403.234701] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [403.235041] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:151:pipe A] <7> [403.235342] 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> [403.235696] 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> [403.235962] 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> [403.236240] 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> [403.236522] 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> [403.236800] 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> [403.237066] 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> [403.237285] 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> [403.237483] 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> [403.237695] 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> [403.237880] 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> [403.238062] 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> [403.238267] 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> [403.238454] 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> [403.238634] 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> [403.238813] 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> [403.238973] 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> [403.239126] 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> [403.239272] 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> [403.239434] 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> [403.239606] 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> [403.239760] 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> [403.239891] 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> [403.240022] 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> [403.240150] 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> [403.240272] 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> [403.240392] 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> [403.240512] 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> [403.240671] 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> [403.240810] 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> [403.240924] 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> [403.241039] 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> [403.241153] 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> [403.241260] 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> [403.241368] 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> [403.241471] 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> [403.241581] 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> [403.241683] 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> [403.241784] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [403.241919] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [403.242004] 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> [403.242117] 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> [403.242198] 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> [403.242264] 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> [403.242327] 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> [403.242391] 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> [403.242455] 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> [403.242531] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1 <7> [403.242672] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [403.242784] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [403.242894] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [403.243001] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [403.243087] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [403.243175] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 0 kHz -> 173855 kHz <7> [403.243274] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [403.243367] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [403.243460] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [403.243557] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [403.243679] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0 <7> [403.243796] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0 <7> [403.243903] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: yes [modeset] <7> [403.243998] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [403.244084] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: A, pipe bpp: 30, dithering: 0 <7> [403.244170] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [403.244252] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [403.244334] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [403.244416] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [403.244497] 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> [403.244650] 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> [403.244759] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [403.244857] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [403.244940] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [403.245020] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [403.245100] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [403.245181] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [403.245260] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [403.245339] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [403.245416] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [403.245492] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [403.245581] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [403.245683] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [403.245780] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [403.245878] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [403.245963] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [403.246039] 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> [403.246115] 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> [403.246190] 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> [403.246265] 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> [403.246340] 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> [403.246417] 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> [403.246501] 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> [403.246597] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [403.246699] 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> [403.246785] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [403.246869] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [403.246950] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [403.247026] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [403.247101] 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> [403.247148] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [403.247178] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [403.247247] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [403.247254] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [403.247331] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [403.247334] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [403.247416] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [403.247499] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [403.247502] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [403.247601] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [403.247699] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [403.247798] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [403.247895] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [403.247972] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [403.248046] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [403.248119] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [403.248191] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [403.248264] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [403.248337] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [403.248411] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [403.248485] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [403.248564] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [403.248658] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [403.248754] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [403.248848] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [403.248927] 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> [403.249002] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [403.249075] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [403.249149] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [403.249221] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [403.249296] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [403.249373] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [403.249448] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [403.249769] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A <7> [403.249937] 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> [403.250036] 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> [403.250127] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [403.250213] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [403.250297] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [403.250367] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [403.250437] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [403.250505] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [403.250594] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [403.250683] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [403.250771] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [403.250858] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [403.250929] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [403.250994] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [403.251060] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [403.251126] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [403.251190] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [403.251275] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [403.251432] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [403.251496] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [403.251614] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [403.252663] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A] <7> [403.252801] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [403.254791] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [403.254897] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (466 ms remaining) <7> [403.729712] 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> [403.750427] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [403.750981] 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> [403.751412] 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> [403.787280] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [403.787727] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [403.788188] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [403.788711] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [403.859225] 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> [403.859366] 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> [403.859469] 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> [403.964006] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [403.964457] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [403.964945] 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> [403.967077] 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> [403.968619] 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> [403.969462] 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> [403.970660] 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> [403.972045] 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> [403.973211] 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> [403.973608] 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> [403.975084] 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> [403.975461] 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> [403.976325] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A <7> [403.976914] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [403.977292] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A <7> [403.977816] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [404.010502] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [404.012435] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [404.012975] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [406.545527] 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> [406.546161] 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> [410.876481] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [410.877314] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [410.878141] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [410.945648] [IGT] kms_flip: finished subtest A-eDP1, FAIL

Detail

Value

Duration

8.08 seconds

Hostname

shard-lnl-4

Igt-Version

IGT-Version: 2.4-ge68d82b44 (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5056-8b3420d629f66344d-debug+ x86_64)

Out

Using IGT_SRANDOM=1778753201 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank-interruptible
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:2074 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (8.084s)

Err

Starting subtest: flip-vs-expired-vblank-interruptible
Starting dynamic subtest: A-eDP1
[379.803667] (kms_flip:8588) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[379.803781] (kms_flip:8588) CRITICAL: Failed assertion: end - start < 500
[379.803858] (kms_flip:8588) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
[377.785216] (kms_flip:8588) DEBUG: Vblank took 52us
[377.801800] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.705292
last_received_ts = 378.704620
last_seq = 2055
current_ts = 378.721954
current_received_ts = 378.721252
current_seq = 2056
count = 289
seq_step = 1
[377.801843] (kms_flip:8588) DEBUG: Vblank took 41us
[377.818485] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.721954
last_received_ts = 378.721252
last_seq = 2056
current_ts = 378.738617
current_received_ts = 378.737946
current_seq = 2057
count = 290
seq_step = 1
[377.818578] (kms_flip:8588) DEBUG: Vblank took 89us
[377.835153] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.738617
last_received_ts = 378.737946
last_seq = 2057
current_ts = 378.755280
current_received_ts = 378.754608
current_seq = 2058
count = 291
seq_step = 1
[377.835216] (kms_flip:8588) DEBUG: Vblank took 59us
[377.851812] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.755280
last_received_ts = 378.754608
last_seq = 2058
current_ts = 378.771942
current_received_ts = 378.771271
current_seq = 2059
count = 292
seq_step = 1
[377.851869] (kms_flip:8588) DEBUG: Vblank took 55us
[377.868481] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.771942
last_received_ts = 378.771271
last_seq = 2059
current_ts = 378.788605
current_received_ts = 378.787933
current_seq = 2060
count = 293
seq_step = 1
[377.868555] (kms_flip:8588) DEBUG: Vblank took 70us
[377.885149] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.788605
last_received_ts = 378.787933
last_seq = 2060
current_ts = 378.805267
current_received_ts = 378.804596
current_seq = 2061
count = 294
seq_step = 1
[377.885204] (kms_flip:8588) DEBUG: Vblank took 52us
[377.901802] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.805267
last_received_ts = 378.804596
last_seq = 2061
current_ts = 378.821930
current_received_ts = 378.821259
current_seq = 2062
count = 295
seq_step = 1
[377.901870] (kms_flip:8588) DEBUG: Vblank took 64us
[377.918463] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.821930
last_received_ts = 378.821259
last_seq = 2062
current_ts = 378.838623
current_received_ts = 378.837921
current_seq = 2063
count = 296
seq_step = 1
[377.918526] (kms_flip:8588) DEBUG: Vblank took 60us
[377.935126] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.838623
last_received_ts = 378.837921
last_seq = 2063
current_ts = 378.855286
current_received_ts = 378.854584
current_seq = 2064
count = 297
seq_step = 1
[377.935183] (kms_flip:8588) DEBUG: Vblank took 53us
[377.951801] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.855286
last_received_ts = 378.854584
last_seq = 2064
current_ts = 378.871948
current_received_ts = 378.871246
current_seq = 2065
count = 298
seq_step = 1
[377.951866] (kms_flip:8588) DEBUG: Vblank took 61us
[377.968455] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.871948
last_received_ts = 378.871246
last_seq = 2065
current_ts = 378.888611
current_received_ts = 378.887909
current_seq = 2066
count = 299
seq_step = 1
[377.968508] (kms_flip:8588) DEBUG: Vblank took 51us
[377.985127] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.888611
last_received_ts = 378.887909
last_seq = 2066
current_ts = 378.905273
current_received_ts = 378.904572
current_seq = 2067
count = 300
seq_step = 1
[377.985187] (kms_flip:8588) DEBUG: Vblank took 57us
[378.001767] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.905273
last_received_ts = 378.904572
last_seq = 2067
current_ts = 378.921936
current_received_ts = 378.921234
current_seq = 2068
count = 301
seq_step = 1
[378.001824] (kms_flip:8588) DEBUG: Vblank took 54us
[378.018443] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.921936
last_received_ts = 378.921234
last_seq = 2068
current_ts = 378.938599
current_received_ts = 378.937897
current_seq = 2069
count = 302
seq_step = 1
[378.018506] (kms_flip:8588) DEBUG: Vblank took 58us
[378.035107] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.938599
last_received_ts = 378.937897
last_seq = 2069
current_ts = 378.955261
current_received_ts = 378.954559
current_seq = 2070
count = 303
seq_step = 1
[378.035163] (kms_flip:8588) DEBUG: Vblank took 52us
[378.051792] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.955261
last_received_ts = 378.954559
last_seq = 2070
current_ts = 378.971924
current_received_ts = 378.971252
current_seq = 2071
count = 304
seq_step = 1
[378.051849] (kms_flip:8588) DEBUG: Vblank took 55us
[378.068430] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.971924
last_received_ts = 378.971252
last_seq = 2071
current_ts = 378.988586
current_received_ts = 378.987885
current_seq = 2072
count = 305
seq_step = 1
[378.068487] (kms_flip:8588) DEBUG: Vblank took 54us
[378.085106] (kms_flip:8588) DEBUG: name = flip
last_ts = 378.988586
last_received_ts = 378.987885
last_seq = 2072
current_ts = 379.005249
current_received_ts = 379.004578
current_seq = 2073
count = 306
seq_step = 1
[378.085169] (kms_flip:8588) DEBUG: Vblank took 59us
[378.101753] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.005249
last_received_ts = 379.004578
last_seq = 2073
current_ts = 379.021912
current_received_ts = 379.021210
current_seq = 2074
count = 307
seq_step = 1
[378.101811] (kms_flip:8588) DEBUG: Vblank took 55us
[378.118447] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.021912
last_received_ts = 379.021210
last_seq = 2074
current_ts = 379.038574
current_received_ts = 379.037903
current_seq = 2075
count = 308
seq_step = 1
[378.118502] (kms_flip:8588) DEBUG: Vblank took 52us
[378.135100] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.038574
last_received_ts = 379.037903
last_seq = 2075
current_ts = 379.055237
current_received_ts = 379.054565
current_seq = 2076
count = 309
seq_step = 1
[378.135153] (kms_flip:8588) DEBUG: Vblank took 50us
[378.151742] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.055237
last_received_ts = 379.054565
last_seq = 2076
current_ts = 379.071899
current_received_ts = 379.071198
current_seq = 2077
count = 310
seq_step = 1
[378.151799] (kms_flip:8588) DEBUG: Vblank took 54us
[378.168421] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.071899
last_received_ts = 379.071198
last_seq = 2077
current_ts = 379.088562
current_received_ts = 379.087891
current_seq = 2078
count = 311
seq_step = 1
[378.168477] (kms_flip:8588) DEBUG: Vblank took 53us
[378.185076] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.088562
last_received_ts = 379.087891
last_seq = 2078
current_ts = 379.105225
current_received_ts = 379.104523
current_seq = 2079
count = 312
seq_step = 1
[378.185133] (kms_flip:8588) DEBUG: Vblank took 53us
[378.201734] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.105225
last_received_ts = 379.104523
last_seq = 2079
current_ts = 379.121887
current_received_ts = 379.121185
current_seq = 2080
count = 313
seq_step = 1
[378.201813] (kms_flip:8588) DEBUG: Vblank took 75us
[378.218440] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.121887
last_received_ts = 379.121185
last_seq = 2080
current_ts = 379.138550
current_received_ts = 379.137909
current_seq = 2081
count = 314
seq_step = 1
[378.218494] (kms_flip:8588) DEBUG: Vblank took 51us
[378.235087] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.138550
last_received_ts = 379.137909
last_seq = 2081
current_ts = 379.155212
current_received_ts = 379.154541
current_seq = 2082
count = 315
seq_step = 1
[378.235145] (kms_flip:8588) DEBUG: Vblank took 55us
[378.251731] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.155212
last_received_ts = 379.154541
last_seq = 2082
current_ts = 379.171875
current_received_ts = 379.171204
current_seq = 2083
count = 316
seq_step = 1
[378.251788] (kms_flip:8588) DEBUG: Vblank took 54us
[378.268409] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.171875
last_received_ts = 379.171204
last_seq = 2083
current_ts = 379.188568
current_received_ts = 379.187866
current_seq = 2084
count = 317
seq_step = 1
[378.268471] (kms_flip:8588) DEBUG: Vblank took 58us
[378.285081] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.188568
last_received_ts = 379.187866
last_seq = 2084
current_ts = 379.205231
current_received_ts = 379.204529
current_seq = 2085
count = 318
seq_step = 1
[378.285144] (kms_flip:8588) DEBUG: Vblank took 58us
[378.301723] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.205231
last_received_ts = 379.204529
last_seq = 2085
current_ts = 379.221893
current_received_ts = 379.221191
current_seq = 2086
count = 319
seq_step = 1
[378.301780] (kms_flip:8588) DEBUG: Vblank took 54us
[378.318403] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.221893
last_received_ts = 379.221191
last_seq = 2086
current_ts = 379.238556
current_received_ts = 379.237854
current_seq = 2087
count = 320
seq_step = 1
[378.318461] (kms_flip:8588) DEBUG: Vblank took 54us
[378.335081] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.238556
last_received_ts = 379.237854
last_seq = 2087
current_ts = 379.255219
current_received_ts = 379.254547
current_seq = 2088
count = 321
seq_step = 1
[378.335141] (kms_flip:8588) DEBUG: Vblank took 56us
[378.351717] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.255219
last_received_ts = 379.254547
last_seq = 2088
current_ts = 379.271881
current_received_ts = 379.271179
current_seq = 2089
count = 322
seq_step = 1
[378.351774] (kms_flip:8588) DEBUG: Vblank took 54us
[378.368353] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.271881
last_received_ts = 379.271179
last_seq = 2089
current_ts = 379.288544
current_received_ts = 379.287811
current_seq = 2090
count = 323
seq_step = 1
[378.368420] (kms_flip:8588) DEBUG: Vblank took 64us
[378.385047] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.288544
last_received_ts = 379.287811
last_seq = 2090
current_ts = 379.305206
current_received_ts = 379.304504
current_seq = 2091
count = 324
seq_step = 1
[378.385097] (kms_flip:8588) DEBUG: Vblank took 47us
[378.401697] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.305206
last_received_ts = 379.304504
last_seq = 2091
current_ts = 379.321869
current_received_ts = 379.321167
current_seq = 2092
count = 325
seq_step = 1
[378.401747] (kms_flip:8588) DEBUG: Vblank took 47us
[378.418390] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.321869
last_received_ts = 379.321167
last_seq = 2092
current_ts = 379.338531
current_received_ts = 379.337860
current_seq = 2093
count = 326
seq_step = 1
[378.418447] (kms_flip:8588) DEBUG: Vblank took 53us
[378.435038] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.338531
last_received_ts = 379.337860
last_seq = 2093
current_ts = 379.355194
current_received_ts = 379.354492
current_seq = 2094
count = 327
seq_step = 1
[378.435084] (kms_flip:8588) DEBUG: Vblank took 43us
[378.451706] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.355194
last_received_ts = 379.354492
last_seq = 2094
current_ts = 379.371857
current_received_ts = 379.371155
current_seq = 2095
count = 328
seq_step = 1
[378.451763] (kms_flip:8588) DEBUG: Vblank took 54us
[378.468373] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.371857
last_received_ts = 379.371155
last_seq = 2095
current_ts = 379.388519
current_received_ts = 379.387848
current_seq = 2096
count = 329
seq_step = 1
[378.468433] (kms_flip:8588) DEBUG: Vblank took 56us
[378.485053] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.388519
last_received_ts = 379.387848
last_seq = 2096
current_ts = 379.405182
current_received_ts = 379.404510
current_seq = 2097
count = 330
seq_step = 1
[378.485112] (kms_flip:8588) DEBUG: Vblank took 55us
[378.501705] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.405182
last_received_ts = 379.404510
last_seq = 2097
current_ts = 379.421844
current_received_ts = 379.421173
current_seq = 2098
count = 331
seq_step = 1
[378.501762] (kms_flip:8588) DEBUG: Vblank took 54us
[378.518377] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.421844
last_received_ts = 379.421173
last_seq = 2098
current_ts = 379.438507
current_received_ts = 379.437836
current_seq = 2099
count = 332
seq_step = 1
[378.518434] (kms_flip:8588) DEBUG: Vblank took 53us
[378.535028] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.438507
last_received_ts = 379.437836
last_seq = 2099
current_ts = 379.455170
current_received_ts = 379.454498
current_seq = 2100
count = 333
seq_step = 1
[378.535085] (kms_flip:8588) DEBUG: Vblank took 53us
[378.551664] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.455170
last_received_ts = 379.454498
last_seq = 2100
current_ts = 379.471832
current_received_ts = 379.471130
current_seq = 2101
count = 334
seq_step = 1
[378.551721] (kms_flip:8588) DEBUG: Vblank took 54us
[378.568378] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.471832
last_received_ts = 379.471130
last_seq = 2101
current_ts = 379.488495
current_received_ts = 379.487854
current_seq = 2102
count = 335
seq_step = 1
[378.568446] (kms_flip:8588) DEBUG: Vblank took 64us
[378.585046] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.488495
last_received_ts = 379.487854
last_seq = 2102
current_ts = 379.505188
current_received_ts = 379.504517
current_seq = 2103
count = 336
seq_step = 1
[378.585102] (kms_flip:8588) DEBUG: Vblank took 52us
[378.601682] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.505188
last_received_ts = 379.504517
last_seq = 2103
current_ts = 379.521851
current_received_ts = 379.521149
current_seq = 2104
count = 337
seq_step = 1
[378.601743] (kms_flip:8588) DEBUG: Vblank took 58us
[378.618349] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.521851
last_received_ts = 379.521149
last_seq = 2104
current_ts = 379.538483
current_received_ts = 379.537811
current_seq = 2105
count = 338
seq_step = 1
[378.618405] (kms_flip:8588) DEBUG: Vblank took 52us
[378.635025] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.538483
last_received_ts = 379.537811
last_seq = 2105
current_ts = 379.555176
current_received_ts = 379.554474
current_seq = 2106
count = 339
seq_step = 1
[378.635080] (kms_flip:8588) DEBUG: Vblank took 52us
[378.651663] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.555176
last_received_ts = 379.554474
last_seq = 2106
current_ts = 379.571838
current_received_ts = 379.571136
current_seq = 2107
count = 340
seq_step = 1
[378.651721] (kms_flip:8588) DEBUG: Vblank took 55us
[378.668342] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.571838
last_received_ts = 379.571136
last_seq = 2107
current_ts = 379.588501
current_received_ts = 379.587799
current_seq = 2108
count = 341
seq_step = 1
[378.668399] (kms_flip:8588) DEBUG: Vblank took 53us
[378.685015] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.588501
last_received_ts = 379.587799
last_seq = 2108
current_ts = 379.605164
current_received_ts = 379.604492
current_seq = 2109
count = 342
seq_step = 1
[378.685068] (kms_flip:8588) DEBUG: Vblank took 51us
[378.701660] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.605164
last_received_ts = 379.604492
last_seq = 2109
current_ts = 379.621826
current_received_ts = 379.621124
current_seq = 2110
count = 343
seq_step = 1
[378.701717] (kms_flip:8588) DEBUG: Vblank took 54us
[378.718343] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.621826
last_received_ts = 379.621124
last_seq = 2110
current_ts = 379.638489
current_received_ts = 379.637817
current_seq = 2111
count = 344
seq_step = 1
[378.718401] (kms_flip:8588) DEBUG: Vblank took 54us
[378.735028] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.638489
last_received_ts = 379.637817
last_seq = 2111
current_ts = 379.655151
current_received_ts = 379.654480
current_seq = 2112
count = 345
seq_step = 1
[378.735086] (kms_flip:8588) DEBUG: Vblank took 54us
[378.751646] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.655151
last_received_ts = 379.654480
last_seq = 2112
current_ts = 379.671814
current_received_ts = 379.671112
current_seq = 2113
count = 346
seq_step = 1
[378.751702] (kms_flip:8588) DEBUG: Vblank took 53us
[378.768341] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.671814
last_received_ts = 379.671112
last_seq = 2113
current_ts = 379.688477
current_received_ts = 379.687805
current_seq = 2114
count = 347
seq_step = 1
[378.768403] (kms_flip:8588) DEBUG: Vblank took 58us
[378.785021] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.688477
last_received_ts = 379.687805
last_seq = 2114
current_ts = 379.705139
current_received_ts = 379.704498
current_seq = 2115
count = 348
seq_step = 1
[378.785079] (kms_flip:8588) DEBUG: Vblank took 55us
[378.801657] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.705139
last_received_ts = 379.704498
last_seq = 2115
current_ts = 379.721802
current_received_ts = 379.721130
current_seq = 2116
count = 349
seq_step = 1
[378.801719] (kms_flip:8588) DEBUG: Vblank took 59us
[378.818327] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.721802
last_received_ts = 379.721130
last_seq = 2116
current_ts = 379.738464
current_received_ts = 379.737793
current_seq = 2117
count = 350
seq_step = 1
[378.818386] (kms_flip:8588) DEBUG: Vblank took 54us
[378.834979] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.738464
last_received_ts = 379.737793
last_seq = 2117
current_ts = 379.755127
current_received_ts = 379.754456
current_seq = 2118
count = 351
seq_step = 1
[378.835038] (kms_flip:8588) DEBUG: Vblank took 55us
[378.851601] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.755127
last_received_ts = 379.754456
last_seq = 2118
current_ts = 379.771790
current_received_ts = 379.771057
current_seq = 2119
count = 352
seq_step = 1
[378.851657] (kms_flip:8588) DEBUG: Vblank took 53us
[378.868312] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.771790
last_received_ts = 379.771057
last_seq = 2119
current_ts = 379.788452
current_received_ts = 379.787781
current_seq = 2120
count = 353
seq_step = 1
[378.868368] (kms_flip:8588) DEBUG: Vblank took 53us
[378.884968] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.788452
last_received_ts = 379.787781
last_seq = 2120
current_ts = 379.805115
current_received_ts = 379.804443
current_seq = 2121
count = 354
seq_step = 1
[378.885024] (kms_flip:8588) DEBUG: Vblank took 53us
[378.901561] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.805115
last_received_ts = 379.804443
last_seq = 2121
current_ts = 379.821777
current_received_ts = 379.821014
current_seq = 2122
count = 355
seq_step = 1
[378.901619] (kms_flip:8588) DEBUG: Vblank took 56us
[378.918315] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.821777
last_received_ts = 379.821014
last_seq = 2122
current_ts = 379.838440
current_received_ts = 379.837769
current_seq = 2123
count = 356
seq_step = 1
[378.918371] (kms_flip:8588) DEBUG: Vblank took 54us
[378.934970] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.838440
last_received_ts = 379.837769
last_seq = 2123
current_ts = 379.855133
current_received_ts = 379.854431
current_seq = 2124
count = 357
seq_step = 1
[378.935028] (kms_flip:8588) DEBUG: Vblank took 55us
[378.951626] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.855133
last_received_ts = 379.854431
last_seq = 2124
current_ts = 379.871796
current_received_ts = 379.871094
current_seq = 2125
count = 358
seq_step = 1
[378.951683] (kms_flip:8588) DEBUG: Vblank took 53us
[378.968310] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.871796
last_received_ts = 379.871094
last_seq = 2125
current_ts = 379.888458
current_received_ts = 379.887787
current_seq = 2126
count = 359
seq_step = 1
[378.968370] (kms_flip:8588) DEBUG: Vblank took 57us
[378.984855] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.888458
last_received_ts = 379.887787
last_seq = 2126
current_ts = 379.905121
current_received_ts = 379.904327
current_seq = 2127
count = 360
seq_step = 1
[378.984918] (kms_flip:8588) DEBUG: Vblank took 60us
[379.001522] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.905121
last_received_ts = 379.904327
last_seq = 2127
current_ts = 379.921783
current_received_ts = 379.920990
current_seq = 2128
count = 361
seq_step = 1
[379.001595] (kms_flip:8588) DEBUG: Vblank took 70us
[379.018281] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.921783
last_received_ts = 379.920990
last_seq = 2128
current_ts = 379.938446
current_received_ts = 379.937744
current_seq = 2129
count = 362
seq_step = 1
[379.018331] (kms_flip:8588) DEBUG: Vblank took 46us
[379.034858] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.938446
last_received_ts = 379.937744
last_seq = 2129
current_ts = 379.955109
current_received_ts = 379.954315
current_seq = 2130
count = 363
seq_step = 1
[379.034901] (kms_flip:8588) DEBUG: Vblank took 39us
[379.051626] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.955109
last_received_ts = 379.954315
last_seq = 2130
current_ts = 379.971771
current_received_ts = 379.971100
current_seq = 2131
count = 364
seq_step = 1
[379.051692] (kms_flip:8588) DEBUG: Vblank took 61us
[379.068286] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.971771
last_received_ts = 379.971100
last_seq = 2131
current_ts = 379.988434
current_received_ts = 379.987762
current_seq = 2132
count = 365
seq_step = 1
[379.068339] (kms_flip:8588) DEBUG: Vblank took 49us
[379.084975] (kms_flip:8588) DEBUG: name = flip
last_ts = 379.988434
last_received_ts = 379.987762
last_seq = 2132
current_ts = 380.005096
current_received_ts = 380.004425
current_seq = 2133
count = 366
seq_step = 1
[379.085038] (kms_flip:8588) DEBUG: Vblank took 59us
[379.101624] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.005096
last_received_ts = 380.004425
last_seq = 2133
current_ts = 380.021759
current_received_ts = 380.021088
current_seq = 2134
count = 367
seq_step = 1
[379.101687] (kms_flip:8588) DEBUG: Vblank took 59us
[379.118271] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.021759
last_received_ts = 380.021088
last_seq = 2134
current_ts = 380.038422
current_received_ts = 380.037750
current_seq = 2135
count = 368
seq_step = 1
[379.118327] (kms_flip:8588) DEBUG: Vblank took 53us
[379.134952] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.038422
last_received_ts = 380.037750
last_seq = 2135
current_ts = 380.055084
current_received_ts = 380.054413
current_seq = 2136
count = 369
seq_step = 1
[379.135014] (kms_flip:8588) DEBUG: Vblank took 58us
[379.151606] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.055084
last_received_ts = 380.054413
last_seq = 2136
current_ts = 380.071747
current_received_ts = 380.071075
current_seq = 2137
count = 370
seq_step = 1
[379.151654] (kms_flip:8588) DEBUG: Vblank took 44us
[379.168252] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.071747
last_received_ts = 380.071075
last_seq = 2137
current_ts = 380.088409
current_received_ts = 380.087708
current_seq = 2138
count = 371
seq_step = 1
[379.168294] (kms_flip:8588) DEBUG: Vblank took 39us
[379.184927] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.088409
last_received_ts = 380.087708
last_seq = 2138
current_ts = 380.105072
current_received_ts = 380.104401
current_seq = 2139
count = 372
seq_step = 1
[379.184987] (kms_flip:8588) DEBUG: Vblank took 56us
[379.201594] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.105072
last_received_ts = 380.104401
last_seq = 2139
current_ts = 380.121735
current_received_ts = 380.121063
current_seq = 2140
count = 373
seq_step = 1
[379.201653] (kms_flip:8588) DEBUG: Vblank took 56us
[379.218256] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.121735
last_received_ts = 380.121063
last_seq = 2140
current_ts = 380.138397
current_received_ts = 380.137726
current_seq = 2141
count = 374
seq_step = 1
[379.218309] (kms_flip:8588) DEBUG: Vblank took 50us
[379.234919] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.138397
last_received_ts = 380.137726
last_seq = 2141
current_ts = 380.155060
current_received_ts = 380.154388
current_seq = 2142
count = 375
seq_step = 1
[379.234975] (kms_flip:8588) DEBUG: Vblank took 52us
[379.251591] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.155060
last_received_ts = 380.154388
last_seq = 2142
current_ts = 380.171753
current_received_ts = 380.171051
current_seq = 2143
count = 376
seq_step = 1
[379.251646] (kms_flip:8588) DEBUG: Vblank took 52us
[379.268253] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.171753
last_received_ts = 380.171051
last_seq = 2143
current_ts = 380.188416
current_received_ts = 380.187714
current_seq = 2144
count = 377
seq_step = 1
[379.268309] (kms_flip:8588) DEBUG: Vblank took 53us
[379.284901] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.188416
last_received_ts = 380.187714
last_seq = 2144
current_ts = 380.205078
current_received_ts = 380.204376
current_seq = 2145
count = 378
seq_step = 1
[379.284958] (kms_flip:8588) DEBUG: Vblank took 53us
[379.301592] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.205078
last_received_ts = 380.204376
last_seq = 2145
current_ts = 380.221741
current_received_ts = 380.221069
current_seq = 2146
count = 379
seq_step = 1
[379.301642] (kms_flip:8588) DEBUG: Vblank took 47us
[379.318244] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.221741
last_received_ts = 380.221069
last_seq = 2146
current_ts = 380.238403
current_received_ts = 380.237701
current_seq = 2147
count = 380
seq_step = 1
[379.318297] (kms_flip:8588) DEBUG: Vblank took 50us
[379.334896] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.238403
last_received_ts = 380.237701
last_seq = 2147
current_ts = 380.255066
current_received_ts = 380.254364
current_seq = 2148
count = 381
seq_step = 1
[379.334952] (kms_flip:8588) DEBUG: Vblank took 52us
[379.351594] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.255066
last_received_ts = 380.254364
last_seq = 2148
current_ts = 380.271729
current_received_ts = 380.271057
current_seq = 2149
count = 382
seq_step = 1
[379.351652] (kms_flip:8588) DEBUG: Vblank took 54us
[379.368236] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.271729
last_received_ts = 380.271057
last_seq = 2149
current_ts = 380.288391
current_received_ts = 380.287689
current_seq = 2150
count = 383
seq_step = 1
[379.368292] (kms_flip:8588) DEBUG: Vblank took 52us
[379.384911] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.288391
last_received_ts = 380.287689
last_seq = 2150
current_ts = 380.305054
current_received_ts = 380.304382
current_seq = 2151
count = 384
seq_step = 1
[379.384970] (kms_flip:8588) DEBUG: Vblank took 55us
[379.401601] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.305054
last_received_ts = 380.304382
last_seq = 2151
current_ts = 380.321716
current_received_ts = 380.321075
current_seq = 2152
count = 385
seq_step = 1
[379.401659] (kms_flip:8588) DEBUG: Vblank took 56us
[379.418213] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.321716
last_received_ts = 380.321075
last_seq = 2152
current_ts = 380.338379
current_received_ts = 380.337677
current_seq = 2153
count = 386
seq_step = 1
[379.418272] (kms_flip:8588) DEBUG: Vblank took 56us
[379.434887] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.338379
last_received_ts = 380.337677
last_seq = 2153
current_ts = 380.355042
current_received_ts = 380.354340
current_seq = 2154
count = 387
seq_step = 1
[379.434942] (kms_flip:8588) DEBUG: Vblank took 52us
[379.451546] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.355042
last_received_ts = 380.354340
last_seq = 2154
current_ts = 380.371704
current_received_ts = 380.371002
current_seq = 2155
count = 388
seq_step = 1
[379.451604] (kms_flip:8588) DEBUG: Vblank took 55us
[379.468215] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.371704
last_received_ts = 380.371002
last_seq = 2155
current_ts = 380.388367
current_received_ts = 380.387695
current_seq = 2156
count = 389
seq_step = 1
[379.468274] (kms_flip:8588) DEBUG: Vblank took 55us
[379.484897] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.388367
last_received_ts = 380.387695
last_seq = 2156
current_ts = 380.405029
current_received_ts = 380.404358
current_seq = 2157
count = 390
seq_step = 1
[379.484952] (kms_flip:8588) DEBUG: Vblank took 52us
[379.501453] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.405029
last_received_ts = 380.404358
last_seq = 2157
current_ts = 380.421692
current_received_ts = 380.420929
current_seq = 2158
count = 391
seq_step = 1
[379.501510] (kms_flip:8588) DEBUG: Vblank took 54us
[379.518215] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.421692
last_received_ts = 380.420929
last_seq = 2158
current_ts = 380.438354
current_received_ts = 380.437683
current_seq = 2159
count = 392
seq_step = 1
[379.518273] (kms_flip:8588) DEBUG: Vblank took 54us
[379.534863] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.438354
last_received_ts = 380.437683
last_seq = 2159
current_ts = 380.455017
current_received_ts = 380.454346
current_seq = 2160
count = 393
seq_step = 1
[379.534925] (kms_flip:8588) DEBUG: Vblank took 58us
[379.551500] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.455017
last_received_ts = 380.454346
last_seq = 2160
current_ts = 380.471680
current_received_ts = 380.470978
current_seq = 2161
count = 394
seq_step = 1
[379.551574] (kms_flip:8588) DEBUG: Vblank took 71us
[379.568207] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.471680
last_received_ts = 380.470978
last_seq = 2161
current_ts = 380.488342
current_received_ts = 380.487671
current_seq = 2162
count = 395
seq_step = 1
[379.568267] (kms_flip:8588) DEBUG: Vblank took 57us
[379.584876] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.488342
last_received_ts = 380.487671
last_seq = 2162
current_ts = 380.505005
current_received_ts = 380.504333
current_seq = 2163
count = 396
seq_step = 1
[379.584931] (kms_flip:8588) DEBUG: Vblank took 52us
[379.601556] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.505005
last_received_ts = 380.504333
last_seq = 2163
current_ts = 380.521667
current_received_ts = 380.521027
current_seq = 2164
count = 397
seq_step = 1
[379.601596] (kms_flip:8588) DEBUG: Vblank took 38us
[379.618181] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.521667
last_received_ts = 380.521027
last_seq = 2164
current_ts = 380.538330
current_received_ts = 380.537659
current_seq = 2165
count = 398
seq_step = 1
[379.618230] (kms_flip:8588) DEBUG: Vblank took 46us
[379.634865] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.538330
last_received_ts = 380.537659
last_seq = 2165
current_ts = 380.555023
current_received_ts = 380.554321
current_seq = 2166
count = 399
seq_step = 1
[379.634929] (kms_flip:8588) DEBUG: Vblank took 60us
[379.651487] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.555023
last_received_ts = 380.554321
last_seq = 2166
current_ts = 380.571686
current_received_ts = 380.570953
current_seq = 2167
count = 400
seq_step = 1
[379.651559] (kms_flip:8588) DEBUG: Vblank took 69us
[379.668195] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.571686
last_received_ts = 380.570953
last_seq = 2167
current_ts = 380.588348
current_received_ts = 380.587677
current_seq = 2168
count = 401
seq_step = 1
[379.668284] (kms_flip:8588) DEBUG: Vblank took 84us
[379.684857] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.588348
last_received_ts = 380.587677
last_seq = 2168
current_ts = 380.605011
current_received_ts = 380.604309
current_seq = 2169
count = 402
seq_step = 1
[379.684917] (kms_flip:8588) DEBUG: Vblank took 54us
[379.701509] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.605011
last_received_ts = 380.604309
last_seq = 2169
current_ts = 380.621674
current_received_ts = 380.620972
current_seq = 2170
count = 403
seq_step = 1
[379.701594] (kms_flip:8588) DEBUG: Vblank took 82us
[379.718175] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.621674
last_received_ts = 380.620972
last_seq = 2170
current_ts = 380.638336
current_received_ts = 380.637634
current_seq = 2171
count = 404
seq_step = 1
[379.718234] (kms_flip:8588) DEBUG: Vblank took 55us
[379.734842] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.638336
last_received_ts = 380.637634
last_seq = 2171
current_ts = 380.654999
current_received_ts = 380.654297
current_seq = 2172
count = 405
seq_step = 1
[379.734902] (kms_flip:8588) DEBUG: Vblank took 57us
[379.751508] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.654999
last_received_ts = 380.654297
last_seq = 2172
current_ts = 380.671661
current_received_ts = 380.670990
current_seq = 2173
count = 406
seq_step = 1
[379.751577] (kms_flip:8588) DEBUG: Vblank took 67us
[379.768163] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.671661
last_received_ts = 380.670990
last_seq = 2173
current_ts = 380.688324
current_received_ts = 380.687622
current_seq = 2174
count = 407
seq_step = 1
[379.768218] (kms_flip:8588) DEBUG: Vblank took 52us
[379.784813] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.688324
last_received_ts = 380.687622
last_seq = 2174
current_ts = 380.704987
current_received_ts = 380.704285
current_seq = 2175
count = 408
seq_step = 1
[379.784870] (kms_flip:8588) DEBUG: Vblank took 54us
[379.801498] (kms_flip:8588) DEBUG: name = flip
last_ts = 380.704987
last_received_ts = 380.704285
last_seq = 2175
current_ts = 380.721649
current_received_ts = 380.720978
current_seq = 2176
count = 409
seq_step = 1
[379.803653] (kms_flip:8588) DEBUG: Vblank took 2141us
[379.803667] (kms_flip:8588) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[379.803781] (kms_flip:8588) CRITICAL: Failed assertion: end - start < 500
[379.803858] (kms_flip:8588) CRITICAL: Last errno: 4, Interrupted system call
[379.826524] (kms_flip:8588) igt_core-INFO: Stack trace:
[379.842131] (kms_flip:8588) igt_core-INFO:   #0 ../lib/igt_core.c:2074 __igt_fail_assert()
[379.843338] (kms_flip:8588) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[379.843404] (kms_flip:8588) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[379.843436] (kms_flip:8588) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
[379.843479] (kms_flip:8588) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[379.848113] (kms_flip:8588) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[379.848845] (kms_flip:8588) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[379.849014] (kms_flip:8588) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (8.084s)

Dmesg

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

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

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

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

<7> [402.849184] 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> [402.849280] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

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

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

<7> [402.849642] 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> [402.849755] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

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

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

<7> [402.850100] 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> [402.850184] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

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

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

<7> [402.850875] 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> [402.851198] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000

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

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

<7> [402.851545] 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> [402.851729] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

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

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

<7> [402.851737] 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> [402.851740] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

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

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

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

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

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

<7> [402.851900] 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> [402.852086] 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> [402.852423] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

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

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

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

<7> [402.852482] 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> [402.852485] 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> [402.852498] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [402.916764] 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> [402.916922] 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> [402.917032] 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> [402.917127] 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> [402.917223] 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> [402.917318] 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> [402.917412] 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> [402.917505] 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> [402.917614] 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> [402.917727] 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> [402.917849] 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> [402.917947] 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> [402.918036] 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> [402.918124] 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> [402.918211] 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> [402.918297] 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> [402.918379] 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> [402.918463] 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> [402.918551] 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> [402.918637] 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> [402.918727] 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> [402.918815] 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> [402.918902] 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> [402.918982] 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> [402.919060] 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> [402.919139] 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> [402.919216] 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> [402.919294] 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> [402.919370] 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> [402.919447] 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> [402.919524] 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> [402.919613] 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> [402.919696] 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> [402.919779] 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> [402.919861] 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> [402.919936] 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> [402.920011] 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> [402.920085] 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> [402.920161] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

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

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

<7> [402.920416] 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> [402.920503] 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> [402.920585] 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> [402.920655] 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> [402.920718] 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> [402.920780] 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> [402.920842] 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> [402.920925] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [403.158208] 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> [403.158524] 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> [403.210726] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [403.229870] 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> [403.230403] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A]

<7> [403.230838] 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> [403.231312] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

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

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

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

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

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

<7> [403.233675] 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> [403.234045] 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> [403.234359] 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> [403.234701] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0

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

<7> [403.235342] 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> [403.235696] 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> [403.235962] 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> [403.236240] 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> [403.236522] 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> [403.236800] 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> [403.237066] 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> [403.237285] 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> [403.237483] 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> [403.237695] 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> [403.237880] 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> [403.238062] 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> [403.238267] 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> [403.238454] 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> [403.238634] 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> [403.238813] 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> [403.238973] 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> [403.239126] 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> [403.239272] 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> [403.239434] 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> [403.239606] 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> [403.239760] 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> [403.239891] 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> [403.240022] 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> [403.240150] 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> [403.240272] 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> [403.240392] 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> [403.240512] 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> [403.240671] 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> [403.240810] 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> [403.240924] 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> [403.241039] 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> [403.241153] 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> [403.241260] 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> [403.241368] 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> [403.241471] 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> [403.241581] 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> [403.241683] 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> [403.241784] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

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

<7> [403.242004] 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> [403.242117] 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> [403.242198] 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> [403.242264] 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> [403.242327] 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> [403.242391] 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> [403.242455] 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> [403.242531] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [403.244497] 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> [403.244650] 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> [403.244759] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [403.246039] 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> [403.246115] 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> [403.246190] 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> [403.246265] 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> [403.246340] 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> [403.246417] 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> [403.246501] 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> [403.246597] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

<7> [403.246699] 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> [403.246785] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0

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

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

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

<7> [403.247101] 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> [403.247148] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [403.248927] 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> [403.249002] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0

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

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

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

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

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

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

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

<7> [403.249937] 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> [403.250036] 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> [403.250127] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [403.729712] 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> [403.750427] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [403.750981] 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> [403.751412] 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> [403.787280] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

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

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

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

<7> [403.859225] 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> [403.859366] 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> [403.859469] 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> [403.964006] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

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

<7> [403.964945] 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> [403.967077] 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> [403.968619] 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> [403.969462] 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> [403.970660] 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> [403.972045] 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> [403.973211] 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> [403.973608] 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> [403.975084] 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> [403.975461] 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> [403.976325] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A

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

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

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

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

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

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

<7> [406.545527] 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> [406.546161] 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> [410.876481] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

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

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

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

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