igt@kms_flip@flip-vs-expired-vblank@b-edp1 on shard-lnl@IGT

Detail	Value
Duration	8.13 seconds
Hostname	shard-lnl-4
Igt-Version	IGT-Version: 2.4-gaf4230819 (x86_64) (Linux: 7.1.0-rc4-lgci-xe-xe-5086-7161a1ce9e045da82-debug+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c: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:2184 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (8.126s)
Err	Starting dynamic subtest: B-eDP1 [254.140930] (kms_flip:4960) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [254.141055] (kms_flip:4960) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-eDP1 failed. ** DEBUG [252.122762] (kms_flip:4960) DEBUG: name = flip last_ts = 252.516373 last_received_ts = 252.515640 last_seq = 522 current_ts = 252.533051 current_received_ts = 252.532196 current_seq = 523 count = 285 seq_step = 1 [252.122812] (kms_flip:4960) DEBUG: Vblank took 42us [252.139609] (kms_flip:4960) DEBUG: name = flip last_ts = 252.533051 last_received_ts = 252.532196 last_seq = 523 current_ts = 252.549713 current_received_ts = 252.549042 current_seq = 524 count = 286 seq_step = 1 [252.139684] (kms_flip:4960) DEBUG: Vblank took 62us [252.156141] (kms_flip:4960) DEBUG: name = flip last_ts = 252.549713 last_received_ts = 252.549042 last_seq = 524 current_ts = 252.566391 current_received_ts = 252.565582 current_seq = 525 count = 287 seq_step = 1 [252.156218] (kms_flip:4960) DEBUG: Vblank took 64us [252.172842] (kms_flip:4960) DEBUG: name = flip last_ts = 252.566391 last_received_ts = 252.565582 last_seq = 525 current_ts = 252.583054 current_received_ts = 252.582291 current_seq = 526 count = 288 seq_step = 1 [252.172942] (kms_flip:4960) DEBUG: Vblank took 83us [252.189565] (kms_flip:4960) DEBUG: name = flip last_ts = 252.583054 last_received_ts = 252.582291 last_seq = 526 current_ts = 252.599731 current_received_ts = 252.599030 current_seq = 527 count = 289 seq_step = 1 [252.189651] (kms_flip:4960) DEBUG: Vblank took 76us [252.206298] (kms_flip:4960) DEBUG: name = flip last_ts = 252.599731 last_received_ts = 252.599030 last_seq = 527 current_ts = 252.616409 current_received_ts = 252.615768 current_seq = 528 count = 290 seq_step = 1 [252.206374] (kms_flip:4960) DEBUG: Vblank took 69us [252.223073] (kms_flip:4960) DEBUG: name = flip last_ts = 252.616409 last_received_ts = 252.615768 last_seq = 528 current_ts = 252.633072 current_received_ts = 252.632553 current_seq = 529 count = 291 seq_step = 1 [252.223154] (kms_flip:4960) DEBUG: Vblank took 74us [252.239650] (kms_flip:4960) DEBUG: name = flip last_ts = 252.633072 last_received_ts = 252.632553 last_seq = 529 current_ts = 252.649750 current_received_ts = 252.649139 current_seq = 530 count = 292 seq_step = 1 [252.239725] (kms_flip:4960) DEBUG: Vblank took 69us [252.256378] (kms_flip:4960) DEBUG: name = flip last_ts = 252.649750 last_received_ts = 252.649139 last_seq = 530 current_ts = 252.666428 current_received_ts = 252.665878 current_seq = 531 count = 293 seq_step = 1 [252.256452] (kms_flip:4960) DEBUG: Vblank took 68us [252.273042] (kms_flip:4960) DEBUG: name = flip last_ts = 252.666428 last_received_ts = 252.665878 last_seq = 531 current_ts = 252.683090 current_received_ts = 252.682526 current_seq = 532 count = 294 seq_step = 1 [252.273199] (kms_flip:4960) DEBUG: Vblank took 125us [252.289598] (kms_flip:4960) DEBUG: name = flip last_ts = 252.683090 last_received_ts = 252.682526 last_seq = 532 current_ts = 252.699768 current_received_ts = 252.699112 current_seq = 533 count = 295 seq_step = 1 [252.289683] (kms_flip:4960) DEBUG: Vblank took 77us [252.306241] (kms_flip:4960) DEBUG: name = flip last_ts = 252.699768 last_received_ts = 252.699112 last_seq = 533 current_ts = 252.716446 current_received_ts = 252.715775 current_seq = 534 count = 296 seq_step = 1 [252.306304] (kms_flip:4960) DEBUG: Vblank took 60us [252.322908] (kms_flip:4960) DEBUG: name = flip last_ts = 252.716446 last_received_ts = 252.715775 last_seq = 534 current_ts = 252.733109 current_received_ts = 252.732452 current_seq = 535 count = 297 seq_step = 1 [252.322965] (kms_flip:4960) DEBUG: Vblank took 54us [252.339662] (kms_flip:4960) DEBUG: name = flip last_ts = 252.733109 last_received_ts = 252.732452 last_seq = 535 current_ts = 252.749786 current_received_ts = 252.749207 current_seq = 536 count = 298 seq_step = 1 [252.339756] (kms_flip:4960) DEBUG: Vblank took 81us [252.356358] (kms_flip:4960) DEBUG: name = flip last_ts = 252.749786 last_received_ts = 252.749207 last_seq = 536 current_ts = 252.766464 current_received_ts = 252.765900 current_seq = 537 count = 299 seq_step = 1 [252.356494] (kms_flip:4960) DEBUG: Vblank took 124us [252.372902] (kms_flip:4960) DEBUG: name = flip last_ts = 252.766464 last_received_ts = 252.765900 last_seq = 537 current_ts = 252.783127 current_received_ts = 252.782471 current_seq = 538 count = 300 seq_step = 1 [252.373046] (kms_flip:4960) DEBUG: Vblank took 139us [252.389657] (kms_flip:4960) DEBUG: name = flip last_ts = 252.783127 last_received_ts = 252.782471 last_seq = 538 current_ts = 252.799805 current_received_ts = 252.799225 current_seq = 539 count = 301 seq_step = 1 [252.389744] (kms_flip:4960) DEBUG: Vblank took 76us [252.406352] (kms_flip:4960) DEBUG: name = flip last_ts = 252.799805 last_received_ts = 252.799225 last_seq = 539 current_ts = 252.816483 current_received_ts = 252.815933 current_seq = 540 count = 302 seq_step = 1 [252.406492] (kms_flip:4960) DEBUG: Vblank took 128us [252.422871] (kms_flip:4960) DEBUG: name = flip last_ts = 252.816483 last_received_ts = 252.815933 last_seq = 540 current_ts = 252.833145 current_received_ts = 252.832458 current_seq = 541 count = 303 seq_step = 1 [252.422941] (kms_flip:4960) DEBUG: Vblank took 64us [252.439501] (kms_flip:4960) DEBUG: name = flip last_ts = 252.833145 last_received_ts = 252.832458 last_seq = 541 current_ts = 252.849823 current_received_ts = 252.849106 current_seq = 542 count = 304 seq_step = 1 [252.439571] (kms_flip:4960) DEBUG: Vblank took 66us [252.456199] (kms_flip:4960) DEBUG: name = flip last_ts = 252.849823 last_received_ts = 252.849106 last_seq = 542 current_ts = 252.866486 current_received_ts = 252.865814 current_seq = 543 count = 305 seq_step = 1 [252.456255] (kms_flip:4960) DEBUG: Vblank took 53us [252.473041] (kms_flip:4960) DEBUG: name = flip last_ts = 252.866486 last_received_ts = 252.865814 last_seq = 543 current_ts = 252.883163 current_received_ts = 252.882645 current_seq = 544 count = 306 seq_step = 1 [252.473138] (kms_flip:4960) DEBUG: Vblank took 83us [252.489612] (kms_flip:4960) DEBUG: name = flip last_ts = 252.883163 last_received_ts = 252.882645 last_seq = 544 current_ts = 252.899841 current_received_ts = 252.899231 current_seq = 545 count = 307 seq_step = 1 [252.489754] (kms_flip:4960) DEBUG: Vblank took 127us [252.506227] (kms_flip:4960) DEBUG: name = flip last_ts = 252.899841 last_received_ts = 252.899231 last_seq = 545 current_ts = 252.916504 current_received_ts = 252.915863 current_seq = 546 count = 308 seq_step = 1 [252.506299] (kms_flip:4960) DEBUG: Vblank took 66us [252.522774] (kms_flip:4960) DEBUG: name = flip last_ts = 252.916504 last_received_ts = 252.915863 last_seq = 546 current_ts = 252.933182 current_received_ts = 252.932419 current_seq = 547 count = 309 seq_step = 1 [252.522836] (kms_flip:4960) DEBUG: Vblank took 58us [252.539604] (kms_flip:4960) DEBUG: name = flip last_ts = 252.933182 last_received_ts = 252.932419 last_seq = 547 current_ts = 252.949860 current_received_ts = 252.949249 current_seq = 548 count = 310 seq_step = 1 [252.539732] (kms_flip:4960) DEBUG: Vblank took 114us [252.556214] (kms_flip:4960) DEBUG: name = flip last_ts = 252.949860 last_received_ts = 252.949249 last_seq = 548 current_ts = 252.966537 current_received_ts = 252.965866 current_seq = 549 count = 311 seq_step = 1 [252.556284] (kms_flip:4960) DEBUG: Vblank took 64us [252.572867] (kms_flip:4960) DEBUG: name = flip last_ts = 252.966537 last_received_ts = 252.965866 last_seq = 549 current_ts = 252.983200 current_received_ts = 252.982529 current_seq = 550 count = 312 seq_step = 1 [252.572931] (kms_flip:4960) DEBUG: Vblank took 60us [252.589538] (kms_flip:4960) DEBUG: name = flip last_ts = 252.983200 last_received_ts = 252.982529 last_seq = 550 current_ts = 252.999878 current_received_ts = 252.999222 current_seq = 551 count = 313 seq_step = 1 [252.589595] (kms_flip:4960) DEBUG: Vblank took 53us [252.606197] (kms_flip:4960) DEBUG: name = flip last_ts = 252.999878 last_received_ts = 252.999222 last_seq = 551 current_ts = 253.016541 current_received_ts = 253.015884 current_seq = 552 count = 314 seq_step = 1 [252.606257] (kms_flip:4960) DEBUG: Vblank took 57us [252.622838] (kms_flip:4960) DEBUG: name = flip last_ts = 253.016541 last_received_ts = 253.015884 last_seq = 552 current_ts = 253.033218 current_received_ts = 253.032532 current_seq = 553 count = 315 seq_step = 1 [252.622885] (kms_flip:4960) DEBUG: Vblank took 44us [252.639493] (kms_flip:4960) DEBUG: name = flip last_ts = 253.033218 last_received_ts = 253.032532 last_seq = 553 current_ts = 253.049896 current_received_ts = 253.049194 current_seq = 554 count = 316 seq_step = 1 [252.639635] (kms_flip:4960) DEBUG: Vblank took 139us [252.656393] (kms_flip:4960) DEBUG: name = flip last_ts = 253.049896 last_received_ts = 253.049194 last_seq = 554 current_ts = 253.066559 current_received_ts = 253.066086 current_seq = 555 count = 317 seq_step = 1 [252.656511] (kms_flip:4960) DEBUG: Vblank took 103us [252.672900] (kms_flip:4960) DEBUG: name = flip last_ts = 253.066559 last_received_ts = 253.066086 last_seq = 555 current_ts = 253.083237 current_received_ts = 253.082611 current_seq = 556 count = 318 seq_step = 1 [252.673035] (kms_flip:4960) DEBUG: Vblank took 121us [252.689510] (kms_flip:4960) DEBUG: name = flip last_ts = 253.083237 last_received_ts = 253.082611 last_seq = 556 current_ts = 253.099915 current_received_ts = 253.099243 current_seq = 557 count = 319 seq_step = 1 [252.689696] (kms_flip:4960) DEBUG: Vblank took 181us [252.706346] (kms_flip:4960) DEBUG: name = flip last_ts = 253.099915 last_received_ts = 253.099243 last_seq = 557 current_ts = 253.116592 current_received_ts = 253.116074 current_seq = 558 count = 320 seq_step = 1 [252.706458] (kms_flip:4960) DEBUG: Vblank took 98us [252.722909] (kms_flip:4960) DEBUG: name = flip last_ts = 253.116592 last_received_ts = 253.116074 last_seq = 558 current_ts = 253.133255 current_received_ts = 253.132645 current_seq = 559 count = 321 seq_step = 1 [252.723050] (kms_flip:4960) DEBUG: Vblank took 125us [252.739538] (kms_flip:4960) DEBUG: name = flip last_ts = 253.133255 last_received_ts = 253.132645 last_seq = 559 current_ts = 253.149918 current_received_ts = 253.149277 current_seq = 560 count = 322 seq_step = 1 [252.739680] (kms_flip:4960) DEBUG: Vblank took 128us [252.756341] (kms_flip:4960) DEBUG: name = flip last_ts = 253.149918 last_received_ts = 253.149277 last_seq = 560 current_ts = 253.166595 current_received_ts = 253.166092 current_seq = 561 count = 323 seq_step = 1 [252.756456] (kms_flip:4960) DEBUG: Vblank took 101us [252.772958] (kms_flip:4960) DEBUG: name = flip last_ts = 253.166595 last_received_ts = 253.166092 last_seq = 561 current_ts = 253.183273 current_received_ts = 253.182709 current_seq = 562 count = 324 seq_step = 1 [252.773069] (kms_flip:4960) DEBUG: Vblank took 97us [252.789495] (kms_flip:4960) DEBUG: name = flip last_ts = 253.183273 last_received_ts = 253.182709 last_seq = 562 current_ts = 253.199936 current_received_ts = 253.199265 current_seq = 563 count = 325 seq_step = 1 [252.789654] (kms_flip:4960) DEBUG: Vblank took 153us [252.806141] (kms_flip:4960) DEBUG: name = flip last_ts = 253.199936 last_received_ts = 253.199265 last_seq = 563 current_ts = 253.216614 current_received_ts = 253.215927 current_seq = 564 count = 326 seq_step = 1 [252.806197] (kms_flip:4960) DEBUG: Vblank took 52us [252.822811] (kms_flip:4960) DEBUG: name = flip last_ts = 253.216614 last_received_ts = 253.215927 last_seq = 564 current_ts = 253.233292 current_received_ts = 253.232605 current_seq = 565 count = 327 seq_step = 1 [252.822873] (kms_flip:4960) DEBUG: Vblank took 58us [252.839476] (kms_flip:4960) DEBUG: name = flip last_ts = 253.233292 last_received_ts = 253.232605 last_seq = 565 current_ts = 253.249954 current_received_ts = 253.249283 current_seq = 566 count = 328 seq_step = 1 [252.839537] (kms_flip:4960) DEBUG: Vblank took 56us [252.856291] (kms_flip:4960) DEBUG: name = flip last_ts = 253.249954 last_received_ts = 253.249283 last_seq = 566 current_ts = 253.266632 current_received_ts = 253.266098 current_seq = 567 count = 329 seq_step = 1 [252.856409] (kms_flip:4960) DEBUG: Vblank took 105us [252.872869] (kms_flip:4960) DEBUG: name = flip last_ts = 253.266632 last_received_ts = 253.266098 last_seq = 567 current_ts = 253.283310 current_received_ts = 253.282669 current_seq = 568 count = 330 seq_step = 1 [252.873031] (kms_flip:4960) DEBUG: Vblank took 148us [252.889377] (kms_flip:4960) DEBUG: name = flip last_ts = 253.283310 last_received_ts = 253.282669 last_seq = 568 current_ts = 253.299973 current_received_ts = 253.299210 current_seq = 569 count = 331 seq_step = 1 [252.889512] (kms_flip:4960) DEBUG: Vblank took 130us [252.906311] (kms_flip:4960) DEBUG: name = flip last_ts = 253.299973 last_received_ts = 253.299210 last_seq = 569 current_ts = 253.316650 current_received_ts = 253.316132 current_seq = 570 count = 332 seq_step = 1 [252.906432] (kms_flip:4960) DEBUG: Vblank took 106us [252.922849] (kms_flip:4960) DEBUG: name = flip last_ts = 253.316650 last_received_ts = 253.316132 last_seq = 570 current_ts = 253.333313 current_received_ts = 253.332672 current_seq = 571 count = 333 seq_step = 1 [252.923007] (kms_flip:4960) DEBUG: Vblank took 142us [252.939527] (kms_flip:4960) DEBUG: name = flip last_ts = 253.333313 last_received_ts = 253.332672 last_seq = 571 current_ts = 253.349991 current_received_ts = 253.349365 current_seq = 572 count = 334 seq_step = 1 [252.939635] (kms_flip:4960) DEBUG: Vblank took 94us [252.956313] (kms_flip:4960) DEBUG: name = flip last_ts = 253.349991 last_received_ts = 253.349365 last_seq = 572 current_ts = 253.366653 current_received_ts = 253.366150 current_seq = 573 count = 335 seq_step = 1 [252.956423] (kms_flip:4960) DEBUG: Vblank took 96us [252.972957] (kms_flip:4960) DEBUG: name = flip last_ts = 253.366653 last_received_ts = 253.366150 last_seq = 573 current_ts = 253.383331 current_received_ts = 253.382812 current_seq = 574 count = 336 seq_step = 1 [252.973059] (kms_flip:4960) DEBUG: Vblank took 88us [252.989503] (kms_flip:4960) DEBUG: name = flip last_ts = 253.383331 last_received_ts = 253.382812 last_seq = 574 current_ts = 253.400009 current_received_ts = 253.399368 current_seq = 575 count = 337 seq_step = 1 [252.989619] (kms_flip:4960) DEBUG: Vblank took 106us [253.006273] (kms_flip:4960) DEBUG: name = flip last_ts = 253.400009 last_received_ts = 253.399368 last_seq = 575 current_ts = 253.416672 current_received_ts = 253.416138 current_seq = 576 count = 338 seq_step = 1 [253.006383] (kms_flip:4960) DEBUG: Vblank took 95us [253.022937] (kms_flip:4960) DEBUG: name = flip last_ts = 253.416672 last_received_ts = 253.416138 last_seq = 576 current_ts = 253.433350 current_received_ts = 253.432816 current_seq = 577 count = 339 seq_step = 1 [253.023043] (kms_flip:4960) DEBUG: Vblank took 90us [253.039515] (kms_flip:4960) DEBUG: name = flip last_ts = 253.433350 last_received_ts = 253.432816 last_seq = 577 current_ts = 253.450027 current_received_ts = 253.449402 current_seq = 578 count = 340 seq_step = 1 [253.039661] (kms_flip:4960) DEBUG: Vblank took 132us [253.056130] (kms_flip:4960) DEBUG: name = flip last_ts = 253.450027 last_received_ts = 253.449402 last_seq = 578 current_ts = 253.466690 current_received_ts = 253.466034 current_seq = 579 count = 341 seq_step = 1 [253.056201] (kms_flip:4960) DEBUG: Vblank took 65us [253.072936] (kms_flip:4960) DEBUG: name = flip last_ts = 253.466690 last_received_ts = 253.466034 last_seq = 579 current_ts = 253.483368 current_received_ts = 253.482834 current_seq = 580 count = 342 seq_step = 1 [253.073044] (kms_flip:4960) DEBUG: Vblank took 95us [253.089476] (kms_flip:4960) DEBUG: name = flip last_ts = 253.483368 last_received_ts = 253.482834 last_seq = 580 current_ts = 253.500046 current_received_ts = 253.499390 current_seq = 581 count = 343 seq_step = 1 [253.089603] (kms_flip:4960) DEBUG: Vblank took 114us [253.106246] (kms_flip:4960) DEBUG: name = flip last_ts = 253.500046 last_received_ts = 253.499390 last_seq = 581 current_ts = 253.516708 current_received_ts = 253.516159 current_seq = 582 count = 344 seq_step = 1 [253.106355] (kms_flip:4960) DEBUG: Vblank took 95us [253.122923] (kms_flip:4960) DEBUG: name = flip last_ts = 253.516708 last_received_ts = 253.516159 last_seq = 582 current_ts = 253.533371 current_received_ts = 253.532852 current_seq = 583 count = 345 seq_step = 1 [253.123025] (kms_flip:4960) DEBUG: Vblank took 89us [253.139394] (kms_flip:4960) DEBUG: name = flip last_ts = 253.533371 last_received_ts = 253.532852 last_seq = 583 current_ts = 253.550049 current_received_ts = 253.549316 current_seq = 584 count = 346 seq_step = 1 [253.139531] (kms_flip:4960) DEBUG: Vblank took 122us [253.156229] (kms_flip:4960) DEBUG: name = flip last_ts = 253.550049 last_received_ts = 253.549316 last_seq = 584 current_ts = 253.566727 current_received_ts = 253.566162 current_seq = 585 count = 347 seq_step = 1 [253.156321] (kms_flip:4960) DEBUG: Vblank took 79us [253.172929] (kms_flip:4960) DEBUG: name = flip last_ts = 253.566727 last_received_ts = 253.566162 last_seq = 585 current_ts = 253.583389 current_received_ts = 253.582870 current_seq = 586 count = 348 seq_step = 1 [253.173080] (kms_flip:4960) DEBUG: Vblank took 136us [253.189478] (kms_flip:4960) DEBUG: name = flip last_ts = 253.583389 last_received_ts = 253.582870 last_seq = 586 current_ts = 253.600067 current_received_ts = 253.599426 current_seq = 587 count = 349 seq_step = 1 [253.189627] (kms_flip:4960) DEBUG: Vblank took 135us [253.206093] (kms_flip:4960) DEBUG: name = flip last_ts = 253.600067 last_received_ts = 253.599426 last_seq = 587 current_ts = 253.616730 current_received_ts = 253.616058 current_seq = 588 count = 350 seq_step = 1 [253.206163] (kms_flip:4960) DEBUG: Vblank took 64us [253.222902] (kms_flip:4960) DEBUG: name = flip last_ts = 253.616730 last_received_ts = 253.616058 last_seq = 588 current_ts = 253.633408 current_received_ts = 253.632874 current_seq = 589 count = 351 seq_step = 1 [253.223007] (kms_flip:4960) DEBUG: Vblank took 92us [253.239483] (kms_flip:4960) DEBUG: name = flip last_ts = 253.633408 last_received_ts = 253.632874 last_seq = 589 current_ts = 253.650085 current_received_ts = 253.649460 current_seq = 590 count = 352 seq_step = 1 [253.239631] (kms_flip:4960) DEBUG: Vblank took 132us [253.256103] (kms_flip:4960) DEBUG: name = flip last_ts = 253.650085 last_received_ts = 253.649460 last_seq = 590 current_ts = 253.666763 current_received_ts = 253.666092 current_seq = 591 count = 353 seq_step = 1 [253.256246] (kms_flip:4960) DEBUG: Vblank took 137us [253.272891] (kms_flip:4960) DEBUG: name = flip last_ts = 253.666763 last_received_ts = 253.666092 last_seq = 591 current_ts = 253.683426 current_received_ts = 253.682877 current_seq = 592 count = 354 seq_step = 1 [253.273041] (kms_flip:4960) DEBUG: Vblank took 137us [253.289473] (kms_flip:4960) DEBUG: name = flip last_ts = 253.683426 last_received_ts = 253.682877 last_seq = 592 current_ts = 253.700089 current_received_ts = 253.699463 current_seq = 593 count = 355 seq_step = 1 [253.289624] (kms_flip:4960) DEBUG: Vblank took 136us [253.306067] (kms_flip:4960) DEBUG: name = flip last_ts = 253.700089 last_received_ts = 253.699463 last_seq = 593 current_ts = 253.716766 current_received_ts = 253.716080 current_seq = 594 count = 356 seq_step = 1 [253.306228] (kms_flip:4960) DEBUG: Vblank took 156us [253.322875] (kms_flip:4960) DEBUG: name = flip last_ts = 253.716766 last_received_ts = 253.716080 last_seq = 594 current_ts = 253.733444 current_received_ts = 253.732895 current_seq = 595 count = 357 seq_step = 1 [253.322944] (kms_flip:4960) DEBUG: Vblank took 56us [253.339454] (kms_flip:4960) DEBUG: name = flip last_ts = 253.733444 last_received_ts = 253.732895 last_seq = 595 current_ts = 253.750107 current_received_ts = 253.749481 current_seq = 596 count = 358 seq_step = 1 [253.339590] (kms_flip:4960) DEBUG: Vblank took 123us [253.356071] (kms_flip:4960) DEBUG: name = flip last_ts = 253.750107 last_received_ts = 253.749481 last_seq = 596 current_ts = 253.766785 current_received_ts = 253.766113 current_seq = 597 count = 359 seq_step = 1 [253.356227] (kms_flip:4960) DEBUG: Vblank took 151us [253.372879] (kms_flip:4960) DEBUG: name = flip last_ts = 253.766785 last_received_ts = 253.766113 last_seq = 597 current_ts = 253.783447 current_received_ts = 253.782913 current_seq = 598 count = 360 seq_step = 1 [253.373055] (kms_flip:4960) DEBUG: Vblank took 163us [253.389439] (kms_flip:4960) DEBUG: name = flip last_ts = 253.783447 last_received_ts = 253.782913 last_seq = 598 current_ts = 253.800125 current_received_ts = 253.799484 current_seq = 599 count = 361 seq_step = 1 [253.389587] (kms_flip:4960) DEBUG: Vblank took 134us [253.406062] (kms_flip:4960) DEBUG: name = flip last_ts = 253.800125 last_received_ts = 253.799484 last_seq = 599 current_ts = 253.816803 current_received_ts = 253.816132 current_seq = 600 count = 362 seq_step = 1 [253.406232] (kms_flip:4960) DEBUG: Vblank took 164us [253.422866] (kms_flip:4960) DEBUG: name = flip last_ts = 253.816803 last_received_ts = 253.816132 last_seq = 600 current_ts = 253.833466 current_received_ts = 253.832932 current_seq = 601 count = 363 seq_step = 1 [253.423006] (kms_flip:4960) DEBUG: Vblank took 127us [253.439441] (kms_flip:4960) DEBUG: name = flip last_ts = 253.833466 last_received_ts = 253.832932 last_seq = 601 current_ts = 253.850143 current_received_ts = 253.849503 current_seq = 602 count = 364 seq_step = 1 [253.439575] (kms_flip:4960) DEBUG: Vblank took 120us [253.456057] (kms_flip:4960) DEBUG: name = flip last_ts = 253.850143 last_received_ts = 253.849503 last_seq = 602 current_ts = 253.866821 current_received_ts = 253.866150 current_seq = 603 count = 365 seq_step = 1 [253.456200] (kms_flip:4960) DEBUG: Vblank took 137us [253.472846] (kms_flip:4960) DEBUG: name = flip last_ts = 253.866821 last_received_ts = 253.866150 last_seq = 603 current_ts = 253.883484 current_received_ts = 253.882935 current_seq = 604 count = 366 seq_step = 1 [253.472999] (kms_flip:4960) DEBUG: Vblank took 139us [253.489439] (kms_flip:4960) DEBUG: name = flip last_ts = 253.883484 last_received_ts = 253.882935 last_seq = 604 current_ts = 253.900162 current_received_ts = 253.899536 current_seq = 605 count = 367 seq_step = 1 [253.489583] (kms_flip:4960) DEBUG: Vblank took 131us [253.506046] (kms_flip:4960) DEBUG: name = flip last_ts = 253.900162 last_received_ts = 253.899536 last_seq = 605 current_ts = 253.916824 current_received_ts = 253.916153 current_seq = 606 count = 368 seq_step = 1 [253.506123] (kms_flip:4960) DEBUG: Vblank took 70us [253.522705] (kms_flip:4960) DEBUG: name = flip last_ts = 253.916824 last_received_ts = 253.916153 last_seq = 606 current_ts = 253.933502 current_received_ts = 253.932816 current_seq = 607 count = 369 seq_step = 1 [253.522773] (kms_flip:4960) DEBUG: Vblank took 64us [253.539415] (kms_flip:4960) DEBUG: name = flip last_ts = 253.933502 last_received_ts = 253.932816 last_seq = 607 current_ts = 253.950165 current_received_ts = 253.949524 current_seq = 608 count = 370 seq_step = 1 [253.539556] (kms_flip:4960) DEBUG: Vblank took 128us [253.556027] (kms_flip:4960) DEBUG: name = flip last_ts = 253.950165 last_received_ts = 253.949524 last_seq = 608 current_ts = 253.966843 current_received_ts = 253.966156 current_seq = 609 count = 371 seq_step = 1 [253.556098] (kms_flip:4960) DEBUG: Vblank took 65us [253.572697] (kms_flip:4960) DEBUG: name = flip last_ts = 253.966843 last_received_ts = 253.966156 last_seq = 609 current_ts = 253.983521 current_received_ts = 253.982834 current_seq = 610 count = 372 seq_step = 1 [253.572754] (kms_flip:4960) DEBUG: Vblank took 54us [253.589401] (kms_flip:4960) DEBUG: name = flip last_ts = 253.983521 last_received_ts = 253.982834 last_seq = 610 current_ts = 254.000183 current_received_ts = 253.999542 current_seq = 611 count = 373 seq_step = 1 [253.589523] (kms_flip:4960) DEBUG: Vblank took 110us [253.606030] (kms_flip:4960) DEBUG: name = flip last_ts = 254.000183 last_received_ts = 253.999542 last_seq = 611 current_ts = 254.016861 current_received_ts = 254.016190 current_seq = 612 count = 374 seq_step = 1 [253.606109] (kms_flip:4960) DEBUG: Vblank took 72us [253.622824] (kms_flip:4960) DEBUG: name = flip last_ts = 254.016861 last_received_ts = 254.016190 last_seq = 612 current_ts = 254.033524 current_received_ts = 254.032974 current_seq = 613 count = 375 seq_step = 1 [253.622999] (kms_flip:4960) DEBUG: Vblank took 110us [253.639412] (kms_flip:4960) DEBUG: name = flip last_ts = 254.033524 last_received_ts = 254.032974 last_seq = 613 current_ts = 254.050201 current_received_ts = 254.049576 current_seq = 614 count = 376 seq_step = 1 [253.639553] (kms_flip:4960) DEBUG: Vblank took 127us [253.656027] (kms_flip:4960) DEBUG: name = flip last_ts = 254.050201 last_received_ts = 254.049576 last_seq = 614 current_ts = 254.066879 current_received_ts = 254.066208 current_seq = 615 count = 377 seq_step = 1 [253.656098] (kms_flip:4960) DEBUG: Vblank took 66us [253.672874] (kms_flip:4960) DEBUG: name = flip last_ts = 254.066879 last_received_ts = 254.066208 last_seq = 615 current_ts = 254.083542 current_received_ts = 254.083054 current_seq = 616 count = 378 seq_step = 1 [253.672983] (kms_flip:4960) DEBUG: Vblank took 95us [253.689408] (kms_flip:4960) DEBUG: name = flip last_ts = 254.083542 last_received_ts = 254.083054 last_seq = 616 current_ts = 254.100220 current_received_ts = 254.099594 current_seq = 617 count = 379 seq_step = 1 [253.689536] (kms_flip:4960) DEBUG: Vblank took 114us [253.706043] (kms_flip:4960) DEBUG: name = flip last_ts = 254.100220 last_received_ts = 254.099594 last_seq = 617 current_ts = 254.116898 current_received_ts = 254.116241 current_seq = 618 count = 380 seq_step = 1 [253.706200] (kms_flip:4960) DEBUG: Vblank took 151us [253.722777] (kms_flip:4960) DEBUG: name = flip last_ts = 254.116898 last_received_ts = 254.116241 last_seq = 618 current_ts = 254.133560 current_received_ts = 254.132980 current_seq = 619 count = 381 seq_step = 1 [253.722907] (kms_flip:4960) DEBUG: Vblank took 81us [253.739393] (kms_flip:4960) DEBUG: name = flip last_ts = 254.133560 last_received_ts = 254.132980 last_seq = 619 current_ts = 254.150238 current_received_ts = 254.149597 current_seq = 620 count = 382 seq_step = 1 [253.739521] (kms_flip:4960) DEBUG: Vblank took 115us [253.756050] (kms_flip:4960) DEBUG: name = flip last_ts = 254.150238 last_received_ts = 254.149597 last_seq = 620 current_ts = 254.166901 current_received_ts = 254.166275 current_seq = 621 count = 383 seq_step = 1 [253.756191] (kms_flip:4960) DEBUG: Vblank took 135us [253.772715] (kms_flip:4960) DEBUG: name = flip last_ts = 254.166901 last_received_ts = 254.166275 last_seq = 621 current_ts = 254.183578 current_received_ts = 254.182938 current_seq = 622 count = 384 seq_step = 1 [253.772857] (kms_flip:4960) DEBUG: Vblank took 129us [253.789390] (kms_flip:4960) DEBUG: name = flip last_ts = 254.183578 last_received_ts = 254.182938 last_seq = 622 current_ts = 254.200241 current_received_ts = 254.199615 current_seq = 623 count = 385 seq_step = 1 [253.789516] (kms_flip:4960) DEBUG: Vblank took 113us [253.806026] (kms_flip:4960) DEBUG: name = flip last_ts = 254.200241 last_received_ts = 254.199615 last_seq = 623 current_ts = 254.216919 current_received_ts = 254.216263 current_seq = 624 count = 386 seq_step = 1 [253.806189] (kms_flip:4960) DEBUG: Vblank took 154us [253.822808] (kms_flip:4960) DEBUG: name = flip last_ts = 254.216919 last_received_ts = 254.216263 last_seq = 624 current_ts = 254.233597 current_received_ts = 254.233047 current_seq = 625 count = 387 seq_step = 1 [253.822902] (kms_flip:4960) DEBUG: Vblank took 81us [253.839284] (kms_flip:4960) DEBUG: name = flip last_ts = 254.233597 last_received_ts = 254.233047 last_seq = 625 current_ts = 254.250259 current_received_ts = 254.249527 current_seq = 626 count = 388 seq_step = 1 [253.839424] (kms_flip:4960) DEBUG: Vblank took 125us [253.856060] (kms_flip:4960) DEBUG: name = flip last_ts = 254.250259 last_received_ts = 254.249527 last_seq = 626 current_ts = 254.266922 current_received_ts = 254.266312 current_seq = 627 count = 389 seq_step = 1 [253.856163] (kms_flip:4960) DEBUG: Vblank took 88us [253.872815] (kms_flip:4960) DEBUG: name = flip last_ts = 254.266922 last_received_ts = 254.266312 last_seq = 627 current_ts = 254.283600 current_received_ts = 254.283081 current_seq = 628 count = 390 seq_step = 1 [253.872913] (kms_flip:4960) DEBUG: Vblank took 83us [253.889285] (kms_flip:4960) DEBUG: name = flip last_ts = 254.283600 last_received_ts = 254.283081 last_seq = 628 current_ts = 254.300278 current_received_ts = 254.299561 current_seq = 629 count = 391 seq_step = 1 [253.889412] (kms_flip:4960) DEBUG: Vblank took 114us [253.906005] (kms_flip:4960) DEBUG: name = flip last_ts = 254.300278 last_received_ts = 254.299561 last_seq = 629 current_ts = 254.316940 current_received_ts = 254.316299 current_seq = 630 count = 392 seq_step = 1 [253.906159] (kms_flip:4960) DEBUG: Vblank took 147us [253.922814] (kms_flip:4960) DEBUG: name = flip last_ts = 254.316940 last_received_ts = 254.316299 last_seq = 630 current_ts = 254.333618 current_received_ts = 254.333099 current_seq = 631 count = 393 seq_step = 1 [253.922936] (kms_flip:4960) DEBUG: Vblank took 107us [253.939363] (kms_flip:4960) DEBUG: name = flip last_ts = 254.333618 last_received_ts = 254.333099 last_seq = 631 current_ts = 254.350296 current_received_ts = 254.349655 current_seq = 632 count = 394 seq_step = 1 [253.939494] (kms_flip:4960) DEBUG: Vblank took 118us [253.956099] (kms_flip:4960) DEBUG: name = flip last_ts = 254.350296 last_received_ts = 254.349655 last_seq = 632 current_ts = 254.366959 current_received_ts = 254.366394 current_seq = 633 count = 395 seq_step = 1 [253.956201] (kms_flip:4960) DEBUG: Vblank took 89us [253.972714] (kms_flip:4960) DEBUG: name = flip last_ts = 254.366959 last_received_ts = 254.366394 last_seq = 633 current_ts = 254.383621 current_received_ts = 254.383026 current_seq = 634 count = 396 seq_step = 1 [253.972833] (kms_flip:4960) DEBUG: Vblank took 108us [253.989321] (kms_flip:4960) DEBUG: name = flip last_ts = 254.383621 last_received_ts = 254.383026 last_seq = 634 current_ts = 254.400299 current_received_ts = 254.399643 current_seq = 635 count = 397 seq_step = 1 [253.989395] (kms_flip:4960) DEBUG: Vblank took 69us [254.005966] (kms_flip:4960) DEBUG: name = flip last_ts = 254.400299 last_received_ts = 254.399643 last_seq = 635 current_ts = 254.416962 current_received_ts = 254.416306 current_seq = 636 count = 398 seq_step = 1 [254.006028] (kms_flip:4960) DEBUG: Vblank took 57us [254.022789] (kms_flip:4960) DEBUG: name = flip last_ts = 254.416962 last_received_ts = 254.416306 last_seq = 636 current_ts = 254.433640 current_received_ts = 254.433105 current_seq = 637 count = 399 seq_step = 1 [254.022902] (kms_flip:4960) DEBUG: Vblank took 98us [254.039309] (kms_flip:4960) DEBUG: name = flip last_ts = 254.433640 last_received_ts = 254.433105 last_seq = 637 current_ts = 254.450302 current_received_ts = 254.449646 current_seq = 638 count = 400 seq_step = 1 [254.039427] (kms_flip:4960) DEBUG: Vblank took 108us [254.056102] (kms_flip:4960) DEBUG: name = flip last_ts = 254.450302 last_received_ts = 254.449646 last_seq = 638 current_ts = 254.466980 current_received_ts = 254.466446 current_seq = 639 count = 401 seq_step = 1 [254.056199] (kms_flip:4960) DEBUG: Vblank took 83us [254.072717] (kms_flip:4960) DEBUG: name = flip last_ts = 254.466980 last_received_ts = 254.466446 last_seq = 639 current_ts = 254.483658 current_received_ts = 254.483063 current_seq = 640 count = 402 seq_step = 1 [254.072846] (kms_flip:4960) DEBUG: Vblank took 114us [254.089455] (kms_flip:4960) DEBUG: name = flip last_ts = 254.483658 last_received_ts = 254.483063 last_seq = 640 current_ts = 254.500320 current_received_ts = 254.499802 current_seq = 641 count = 403 seq_step = 1 [254.089550] (kms_flip:4960) DEBUG: Vblank took 81us [254.106033] (kms_flip:4960) DEBUG: name = flip last_ts = 254.500320 last_received_ts = 254.499802 last_seq = 641 current_ts = 254.516998 current_received_ts = 254.516388 current_seq = 642 count = 404 seq_step = 1 [254.106202] (kms_flip:4960) DEBUG: Vblank took 152us [254.122893] (kms_flip:4960) DEBUG: name = flip last_ts = 254.516998 last_received_ts = 254.516388 last_seq = 642 current_ts = 254.533661 current_received_ts = 254.533218 current_seq = 643 count = 405 seq_step = 1 [254.123073] (kms_flip:4960) DEBUG: Vblank took 142us [254.139336] (kms_flip:4960) DEBUG: name = flip last_ts = 254.533661 last_received_ts = 254.533218 last_seq = 643 current_ts = 254.550339 current_received_ts = 254.549698 current_seq = 644 count = 406 seq_step = 1 [254.140917] (kms_flip:4960) DEBUG: Vblank took 1556us [254.140930] (kms_flip:4960) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [254.141055] (kms_flip:4960) CRITICAL: Failed assertion: end - start < 500 [254.146717] (kms_flip:4960) igt_core-INFO: Stack trace: [254.151235] (kms_flip:4960) igt_core-INFO: #0 ../lib/igt_core.c:2074 __igt_fail_assert() [254.153861] (kms_flip:4960) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [254.153963] (kms_flip:4960) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [254.154026] (kms_flip:4960) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() [254.154087] (kms_flip:4960) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [254.159386] (kms_flip:4960) igt_core-INFO: #5 [__libc_init_first+0x8a] [254.174384] (kms_flip:4960) igt_core-INFO: #6 [__libc_start_main+0x8b] [254.175287] (kms_flip:4960) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (8.126s)
Dmesg	<6> [352.088466] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [352.091928] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:442] <7> [352.093499] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:443] <7> [352.176372] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [352.176759] 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> [352.177148] 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> [352.177407] 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> [352.177647] 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> [352.177875] 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> [352.178096] 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> [352.178339] 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> [352.178550] 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> [352.178749] 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> [352.178945] 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> [352.179148] 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> [352.179339] 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> [352.179525] 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> [352.179699] 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> [352.179871] 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> [352.180039] 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> [352.180214] 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> [352.180373] 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> [352.180527] 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> [352.180674] 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> [352.180820] 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> [352.180960] 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> [352.181111] 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> [352.181249] 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> [352.181381] 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> [352.181512] 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> [352.181641] 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> [352.181768] 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> [352.181893] 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> [352.182013] 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> [352.182175] 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> [352.182303] 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> [352.182425] 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> [352.182546] 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> [352.182664] 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> [352.182779] 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> [352.182890] 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> [352.183000] 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> [352.183120] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [352.183229] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [352.183394] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [352.183491] 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> [352.183616] 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> [352.183704] 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> [352.183805] 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> [352.183882] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [352.183957] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [352.184031] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [352.184133] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [352.184246] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400 <7> [352.184353] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400 <7> [352.184458] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [352.184560] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [352.184658] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [352.184764] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [352.184888] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [352.184997] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [352.185106] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [352.185221] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [352.185353] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [352.185464] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [352.185562] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [352.185646] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [352.185730] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [352.185813] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [352.185896] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [352.186032] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [352.186152] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [352.186324] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [352.186530] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [352.186637] 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: 0x0000006f <7> [352.187241] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [352.187363] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [352.390133] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [352.391130] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [352.405368] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [352.405749] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [352.405943] 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> [352.406479] 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> [352.406414] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [352.458538] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [352.459269] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [352.466337] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [352.466925] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [352.466960] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [352.467647] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [352.468594] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [352.469268] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [352.469982] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [352.470491] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [352.470986] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [352.471387] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [352.471765] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [352.472169] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [352.472520] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [352.472977] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [352.473391] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [352.473744] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [352.474170] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [352.474511] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [352.474863] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [352.475238] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [352.475709] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [352.476128] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [352.476479] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [352.477087] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [352.477578] 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> [352.478169] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [352.478595] 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> [352.479058] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [352.479389] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [352.480337] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [352.480677] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [352.480964] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [352.481029] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [352.481179] 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> [352.481514] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] 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> [352.481810] 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> [352.482134] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [352.482461] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [352.482734] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [352.483008] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [352.483290] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [352.483510] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [352.483728] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [352.484001] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [352.484206] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [352.484402] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [352.484615] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [352.484797] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [352.484996] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [352.485167] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [352.485326] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [352.485483] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [352.485633] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [352.485781] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [352.485945] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [352.486080] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [352.486212] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [352.486359] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [352.486496] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [352.486624] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [352.486749] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [352.486883] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [352.487024] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [352.487163] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [352.487282] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [352.487394] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [352.487506] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [352.487617] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [352.487724] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [352.487835] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [352.487945] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [352.488043] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [352.488140] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [352.488233] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [352.488323] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [352.488413] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [352.488505] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [352.488638] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [352.488722] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [352.488837] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [352.488929] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:264:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [352.489007] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [352.489083] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [352.489156] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [352.489217] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [352.489290] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [352.489397] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [352.489502] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [352.489589] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [352.489673] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [352.489775] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [352.489940] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [352.490062] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [352.490163] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [352.490253] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [352.490357] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [352.490463] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [352.490550] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [352.490645] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [352.490737] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [352.490829] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [352.490936] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [352.491037] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [352.491136] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [352.491226] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [352.491310] 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> [352.491389] 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> [352.491470] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [352.491550] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [352.491630] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [352.491707] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [352.491779] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [352.491866] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [352.491970] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [352.492084] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [352.492181] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [352.492260] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [352.492341] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [352.492435] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [352.492528] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [352.492616] 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> [352.492689] 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> [352.492762] 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> [352.492838] 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> [352.492935] 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> [352.493032] 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> [352.493125] 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> [352.493195] 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> [352.493270] 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> [352.493347] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [352.493423] 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> [352.493500] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [352.493576] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [352.493652] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [352.493724] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [352.493805] 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> [352.493914] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [352.494012] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [352.494111] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [352.494192] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [352.494287] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [352.494380] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [352.494472] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [352.494551] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [352.494628] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [352.494699] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [352.494777] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [352.494881] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [352.494978] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [352.495071] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [352.495157] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [352.495141] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [352.495242] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [352.495256] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [352.495318] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [352.495354] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [352.495396] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [352.495472] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [352.495460] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [352.495549] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [352.495629] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [352.495713] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:442] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [352.495793] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [352.495885] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [352.495964] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [352.496054] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [352.496146] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [352.496242] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [352.496330] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [352.496633] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [352.496793] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [352.496975] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [352.497099] 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> [352.497203] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [352.497297] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [352.497395] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [352.497479] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [352.497558] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [352.497635] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [352.497708] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [352.497780] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [352.497874] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [352.497961] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [352.498045] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [352.498127] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [352.498203] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [352.498277] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [352.498351] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [352.498440] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [352.498621] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [352.498703] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [352.498823] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [352.499840] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [352.499952] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [352.501967] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [352.502082] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (465 ms remaining) <7> [352.973710] 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> [352.994504] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [352.995042] 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> [352.995579] 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> [353.031460] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [353.031880] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [353.032271] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [353.032701] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [353.209265] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [353.209677] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [353.210033] 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> [353.212255] 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> [353.213838] 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> [353.214760] 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> [353.216045] 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> [353.217623] 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> [353.218952] 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> [353.219543] 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> [353.221187] 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> [353.221699] 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> [353.222653] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [353.223221] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [353.223673] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [353.224185] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 13892 <7> [353.256983] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [353.258798] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [353.259252] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <7> [355.771712] 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> [355.772272] 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> [360.073380] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [360.074800] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [360.087545] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [360.215798] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

8.13 seconds

Hostname

shard-lnl-4

Igt-Version

IGT-Version: 2.4-gaf4230819 (x86_64) (Linux: 7.1.0-rc4-lgci-xe-xe-5086-7161a1ce9e045da82-debug+ x86_64)

Out

Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c: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:2184 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (8.126s)

Err

Starting dynamic subtest: B-eDP1
[254.140930] (kms_flip:4960) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[254.141055] (kms_flip:4960) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
[252.122762] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.516373
last_received_ts = 252.515640
last_seq = 522
current_ts = 252.533051
current_received_ts = 252.532196
current_seq = 523
count = 285
seq_step = 1
[252.122812] (kms_flip:4960) DEBUG: Vblank took 42us
[252.139609] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.533051
last_received_ts = 252.532196
last_seq = 523
current_ts = 252.549713
current_received_ts = 252.549042
current_seq = 524
count = 286
seq_step = 1
[252.139684] (kms_flip:4960) DEBUG: Vblank took 62us
[252.156141] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.549713
last_received_ts = 252.549042
last_seq = 524
current_ts = 252.566391
current_received_ts = 252.565582
current_seq = 525
count = 287
seq_step = 1
[252.156218] (kms_flip:4960) DEBUG: Vblank took 64us
[252.172842] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.566391
last_received_ts = 252.565582
last_seq = 525
current_ts = 252.583054
current_received_ts = 252.582291
current_seq = 526
count = 288
seq_step = 1
[252.172942] (kms_flip:4960) DEBUG: Vblank took 83us
[252.189565] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.583054
last_received_ts = 252.582291
last_seq = 526
current_ts = 252.599731
current_received_ts = 252.599030
current_seq = 527
count = 289
seq_step = 1
[252.189651] (kms_flip:4960) DEBUG: Vblank took 76us
[252.206298] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.599731
last_received_ts = 252.599030
last_seq = 527
current_ts = 252.616409
current_received_ts = 252.615768
current_seq = 528
count = 290
seq_step = 1
[252.206374] (kms_flip:4960) DEBUG: Vblank took 69us
[252.223073] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.616409
last_received_ts = 252.615768
last_seq = 528
current_ts = 252.633072
current_received_ts = 252.632553
current_seq = 529
count = 291
seq_step = 1
[252.223154] (kms_flip:4960) DEBUG: Vblank took 74us
[252.239650] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.633072
last_received_ts = 252.632553
last_seq = 529
current_ts = 252.649750
current_received_ts = 252.649139
current_seq = 530
count = 292
seq_step = 1
[252.239725] (kms_flip:4960) DEBUG: Vblank took 69us
[252.256378] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.649750
last_received_ts = 252.649139
last_seq = 530
current_ts = 252.666428
current_received_ts = 252.665878
current_seq = 531
count = 293
seq_step = 1
[252.256452] (kms_flip:4960) DEBUG: Vblank took 68us
[252.273042] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.666428
last_received_ts = 252.665878
last_seq = 531
current_ts = 252.683090
current_received_ts = 252.682526
current_seq = 532
count = 294
seq_step = 1
[252.273199] (kms_flip:4960) DEBUG: Vblank took 125us
[252.289598] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.683090
last_received_ts = 252.682526
last_seq = 532
current_ts = 252.699768
current_received_ts = 252.699112
current_seq = 533
count = 295
seq_step = 1
[252.289683] (kms_flip:4960) DEBUG: Vblank took 77us
[252.306241] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.699768
last_received_ts = 252.699112
last_seq = 533
current_ts = 252.716446
current_received_ts = 252.715775
current_seq = 534
count = 296
seq_step = 1
[252.306304] (kms_flip:4960) DEBUG: Vblank took 60us
[252.322908] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.716446
last_received_ts = 252.715775
last_seq = 534
current_ts = 252.733109
current_received_ts = 252.732452
current_seq = 535
count = 297
seq_step = 1
[252.322965] (kms_flip:4960) DEBUG: Vblank took 54us
[252.339662] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.733109
last_received_ts = 252.732452
last_seq = 535
current_ts = 252.749786
current_received_ts = 252.749207
current_seq = 536
count = 298
seq_step = 1
[252.339756] (kms_flip:4960) DEBUG: Vblank took 81us
[252.356358] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.749786
last_received_ts = 252.749207
last_seq = 536
current_ts = 252.766464
current_received_ts = 252.765900
current_seq = 537
count = 299
seq_step = 1
[252.356494] (kms_flip:4960) DEBUG: Vblank took 124us
[252.372902] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.766464
last_received_ts = 252.765900
last_seq = 537
current_ts = 252.783127
current_received_ts = 252.782471
current_seq = 538
count = 300
seq_step = 1
[252.373046] (kms_flip:4960) DEBUG: Vblank took 139us
[252.389657] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.783127
last_received_ts = 252.782471
last_seq = 538
current_ts = 252.799805
current_received_ts = 252.799225
current_seq = 539
count = 301
seq_step = 1
[252.389744] (kms_flip:4960) DEBUG: Vblank took 76us
[252.406352] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.799805
last_received_ts = 252.799225
last_seq = 539
current_ts = 252.816483
current_received_ts = 252.815933
current_seq = 540
count = 302
seq_step = 1
[252.406492] (kms_flip:4960) DEBUG: Vblank took 128us
[252.422871] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.816483
last_received_ts = 252.815933
last_seq = 540
current_ts = 252.833145
current_received_ts = 252.832458
current_seq = 541
count = 303
seq_step = 1
[252.422941] (kms_flip:4960) DEBUG: Vblank took 64us
[252.439501] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.833145
last_received_ts = 252.832458
last_seq = 541
current_ts = 252.849823
current_received_ts = 252.849106
current_seq = 542
count = 304
seq_step = 1
[252.439571] (kms_flip:4960) DEBUG: Vblank took 66us
[252.456199] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.849823
last_received_ts = 252.849106
last_seq = 542
current_ts = 252.866486
current_received_ts = 252.865814
current_seq = 543
count = 305
seq_step = 1
[252.456255] (kms_flip:4960) DEBUG: Vblank took 53us
[252.473041] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.866486
last_received_ts = 252.865814
last_seq = 543
current_ts = 252.883163
current_received_ts = 252.882645
current_seq = 544
count = 306
seq_step = 1
[252.473138] (kms_flip:4960) DEBUG: Vblank took 83us
[252.489612] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.883163
last_received_ts = 252.882645
last_seq = 544
current_ts = 252.899841
current_received_ts = 252.899231
current_seq = 545
count = 307
seq_step = 1
[252.489754] (kms_flip:4960) DEBUG: Vblank took 127us
[252.506227] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.899841
last_received_ts = 252.899231
last_seq = 545
current_ts = 252.916504
current_received_ts = 252.915863
current_seq = 546
count = 308
seq_step = 1
[252.506299] (kms_flip:4960) DEBUG: Vblank took 66us
[252.522774] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.916504
last_received_ts = 252.915863
last_seq = 546
current_ts = 252.933182
current_received_ts = 252.932419
current_seq = 547
count = 309
seq_step = 1
[252.522836] (kms_flip:4960) DEBUG: Vblank took 58us
[252.539604] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.933182
last_received_ts = 252.932419
last_seq = 547
current_ts = 252.949860
current_received_ts = 252.949249
current_seq = 548
count = 310
seq_step = 1
[252.539732] (kms_flip:4960) DEBUG: Vblank took 114us
[252.556214] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.949860
last_received_ts = 252.949249
last_seq = 548
current_ts = 252.966537
current_received_ts = 252.965866
current_seq = 549
count = 311
seq_step = 1
[252.556284] (kms_flip:4960) DEBUG: Vblank took 64us
[252.572867] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.966537
last_received_ts = 252.965866
last_seq = 549
current_ts = 252.983200
current_received_ts = 252.982529
current_seq = 550
count = 312
seq_step = 1
[252.572931] (kms_flip:4960) DEBUG: Vblank took 60us
[252.589538] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.983200
last_received_ts = 252.982529
last_seq = 550
current_ts = 252.999878
current_received_ts = 252.999222
current_seq = 551
count = 313
seq_step = 1
[252.589595] (kms_flip:4960) DEBUG: Vblank took 53us
[252.606197] (kms_flip:4960) DEBUG: name = flip
last_ts = 252.999878
last_received_ts = 252.999222
last_seq = 551
current_ts = 253.016541
current_received_ts = 253.015884
current_seq = 552
count = 314
seq_step = 1
[252.606257] (kms_flip:4960) DEBUG: Vblank took 57us
[252.622838] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.016541
last_received_ts = 253.015884
last_seq = 552
current_ts = 253.033218
current_received_ts = 253.032532
current_seq = 553
count = 315
seq_step = 1
[252.622885] (kms_flip:4960) DEBUG: Vblank took 44us
[252.639493] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.033218
last_received_ts = 253.032532
last_seq = 553
current_ts = 253.049896
current_received_ts = 253.049194
current_seq = 554
count = 316
seq_step = 1
[252.639635] (kms_flip:4960) DEBUG: Vblank took 139us
[252.656393] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.049896
last_received_ts = 253.049194
last_seq = 554
current_ts = 253.066559
current_received_ts = 253.066086
current_seq = 555
count = 317
seq_step = 1
[252.656511] (kms_flip:4960) DEBUG: Vblank took 103us
[252.672900] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.066559
last_received_ts = 253.066086
last_seq = 555
current_ts = 253.083237
current_received_ts = 253.082611
current_seq = 556
count = 318
seq_step = 1
[252.673035] (kms_flip:4960) DEBUG: Vblank took 121us
[252.689510] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.083237
last_received_ts = 253.082611
last_seq = 556
current_ts = 253.099915
current_received_ts = 253.099243
current_seq = 557
count = 319
seq_step = 1
[252.689696] (kms_flip:4960) DEBUG: Vblank took 181us
[252.706346] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.099915
last_received_ts = 253.099243
last_seq = 557
current_ts = 253.116592
current_received_ts = 253.116074
current_seq = 558
count = 320
seq_step = 1
[252.706458] (kms_flip:4960) DEBUG: Vblank took 98us
[252.722909] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.116592
last_received_ts = 253.116074
last_seq = 558
current_ts = 253.133255
current_received_ts = 253.132645
current_seq = 559
count = 321
seq_step = 1
[252.723050] (kms_flip:4960) DEBUG: Vblank took 125us
[252.739538] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.133255
last_received_ts = 253.132645
last_seq = 559
current_ts = 253.149918
current_received_ts = 253.149277
current_seq = 560
count = 322
seq_step = 1
[252.739680] (kms_flip:4960) DEBUG: Vblank took 128us
[252.756341] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.149918
last_received_ts = 253.149277
last_seq = 560
current_ts = 253.166595
current_received_ts = 253.166092
current_seq = 561
count = 323
seq_step = 1
[252.756456] (kms_flip:4960) DEBUG: Vblank took 101us
[252.772958] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.166595
last_received_ts = 253.166092
last_seq = 561
current_ts = 253.183273
current_received_ts = 253.182709
current_seq = 562
count = 324
seq_step = 1
[252.773069] (kms_flip:4960) DEBUG: Vblank took 97us
[252.789495] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.183273
last_received_ts = 253.182709
last_seq = 562
current_ts = 253.199936
current_received_ts = 253.199265
current_seq = 563
count = 325
seq_step = 1
[252.789654] (kms_flip:4960) DEBUG: Vblank took 153us
[252.806141] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.199936
last_received_ts = 253.199265
last_seq = 563
current_ts = 253.216614
current_received_ts = 253.215927
current_seq = 564
count = 326
seq_step = 1
[252.806197] (kms_flip:4960) DEBUG: Vblank took 52us
[252.822811] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.216614
last_received_ts = 253.215927
last_seq = 564
current_ts = 253.233292
current_received_ts = 253.232605
current_seq = 565
count = 327
seq_step = 1
[252.822873] (kms_flip:4960) DEBUG: Vblank took 58us
[252.839476] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.233292
last_received_ts = 253.232605
last_seq = 565
current_ts = 253.249954
current_received_ts = 253.249283
current_seq = 566
count = 328
seq_step = 1
[252.839537] (kms_flip:4960) DEBUG: Vblank took 56us
[252.856291] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.249954
last_received_ts = 253.249283
last_seq = 566
current_ts = 253.266632
current_received_ts = 253.266098
current_seq = 567
count = 329
seq_step = 1
[252.856409] (kms_flip:4960) DEBUG: Vblank took 105us
[252.872869] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.266632
last_received_ts = 253.266098
last_seq = 567
current_ts = 253.283310
current_received_ts = 253.282669
current_seq = 568
count = 330
seq_step = 1
[252.873031] (kms_flip:4960) DEBUG: Vblank took 148us
[252.889377] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.283310
last_received_ts = 253.282669
last_seq = 568
current_ts = 253.299973
current_received_ts = 253.299210
current_seq = 569
count = 331
seq_step = 1
[252.889512] (kms_flip:4960) DEBUG: Vblank took 130us
[252.906311] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.299973
last_received_ts = 253.299210
last_seq = 569
current_ts = 253.316650
current_received_ts = 253.316132
current_seq = 570
count = 332
seq_step = 1
[252.906432] (kms_flip:4960) DEBUG: Vblank took 106us
[252.922849] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.316650
last_received_ts = 253.316132
last_seq = 570
current_ts = 253.333313
current_received_ts = 253.332672
current_seq = 571
count = 333
seq_step = 1
[252.923007] (kms_flip:4960) DEBUG: Vblank took 142us
[252.939527] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.333313
last_received_ts = 253.332672
last_seq = 571
current_ts = 253.349991
current_received_ts = 253.349365
current_seq = 572
count = 334
seq_step = 1
[252.939635] (kms_flip:4960) DEBUG: Vblank took 94us
[252.956313] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.349991
last_received_ts = 253.349365
last_seq = 572
current_ts = 253.366653
current_received_ts = 253.366150
current_seq = 573
count = 335
seq_step = 1
[252.956423] (kms_flip:4960) DEBUG: Vblank took 96us
[252.972957] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.366653
last_received_ts = 253.366150
last_seq = 573
current_ts = 253.383331
current_received_ts = 253.382812
current_seq = 574
count = 336
seq_step = 1
[252.973059] (kms_flip:4960) DEBUG: Vblank took 88us
[252.989503] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.383331
last_received_ts = 253.382812
last_seq = 574
current_ts = 253.400009
current_received_ts = 253.399368
current_seq = 575
count = 337
seq_step = 1
[252.989619] (kms_flip:4960) DEBUG: Vblank took 106us
[253.006273] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.400009
last_received_ts = 253.399368
last_seq = 575
current_ts = 253.416672
current_received_ts = 253.416138
current_seq = 576
count = 338
seq_step = 1
[253.006383] (kms_flip:4960) DEBUG: Vblank took 95us
[253.022937] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.416672
last_received_ts = 253.416138
last_seq = 576
current_ts = 253.433350
current_received_ts = 253.432816
current_seq = 577
count = 339
seq_step = 1
[253.023043] (kms_flip:4960) DEBUG: Vblank took 90us
[253.039515] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.433350
last_received_ts = 253.432816
last_seq = 577
current_ts = 253.450027
current_received_ts = 253.449402
current_seq = 578
count = 340
seq_step = 1
[253.039661] (kms_flip:4960) DEBUG: Vblank took 132us
[253.056130] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.450027
last_received_ts = 253.449402
last_seq = 578
current_ts = 253.466690
current_received_ts = 253.466034
current_seq = 579
count = 341
seq_step = 1
[253.056201] (kms_flip:4960) DEBUG: Vblank took 65us
[253.072936] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.466690
last_received_ts = 253.466034
last_seq = 579
current_ts = 253.483368
current_received_ts = 253.482834
current_seq = 580
count = 342
seq_step = 1
[253.073044] (kms_flip:4960) DEBUG: Vblank took 95us
[253.089476] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.483368
last_received_ts = 253.482834
last_seq = 580
current_ts = 253.500046
current_received_ts = 253.499390
current_seq = 581
count = 343
seq_step = 1
[253.089603] (kms_flip:4960) DEBUG: Vblank took 114us
[253.106246] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.500046
last_received_ts = 253.499390
last_seq = 581
current_ts = 253.516708
current_received_ts = 253.516159
current_seq = 582
count = 344
seq_step = 1
[253.106355] (kms_flip:4960) DEBUG: Vblank took 95us
[253.122923] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.516708
last_received_ts = 253.516159
last_seq = 582
current_ts = 253.533371
current_received_ts = 253.532852
current_seq = 583
count = 345
seq_step = 1
[253.123025] (kms_flip:4960) DEBUG: Vblank took 89us
[253.139394] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.533371
last_received_ts = 253.532852
last_seq = 583
current_ts = 253.550049
current_received_ts = 253.549316
current_seq = 584
count = 346
seq_step = 1
[253.139531] (kms_flip:4960) DEBUG: Vblank took 122us
[253.156229] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.550049
last_received_ts = 253.549316
last_seq = 584
current_ts = 253.566727
current_received_ts = 253.566162
current_seq = 585
count = 347
seq_step = 1
[253.156321] (kms_flip:4960) DEBUG: Vblank took 79us
[253.172929] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.566727
last_received_ts = 253.566162
last_seq = 585
current_ts = 253.583389
current_received_ts = 253.582870
current_seq = 586
count = 348
seq_step = 1
[253.173080] (kms_flip:4960) DEBUG: Vblank took 136us
[253.189478] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.583389
last_received_ts = 253.582870
last_seq = 586
current_ts = 253.600067
current_received_ts = 253.599426
current_seq = 587
count = 349
seq_step = 1
[253.189627] (kms_flip:4960) DEBUG: Vblank took 135us
[253.206093] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.600067
last_received_ts = 253.599426
last_seq = 587
current_ts = 253.616730
current_received_ts = 253.616058
current_seq = 588
count = 350
seq_step = 1
[253.206163] (kms_flip:4960) DEBUG: Vblank took 64us
[253.222902] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.616730
last_received_ts = 253.616058
last_seq = 588
current_ts = 253.633408
current_received_ts = 253.632874
current_seq = 589
count = 351
seq_step = 1
[253.223007] (kms_flip:4960) DEBUG: Vblank took 92us
[253.239483] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.633408
last_received_ts = 253.632874
last_seq = 589
current_ts = 253.650085
current_received_ts = 253.649460
current_seq = 590
count = 352
seq_step = 1
[253.239631] (kms_flip:4960) DEBUG: Vblank took 132us
[253.256103] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.650085
last_received_ts = 253.649460
last_seq = 590
current_ts = 253.666763
current_received_ts = 253.666092
current_seq = 591
count = 353
seq_step = 1
[253.256246] (kms_flip:4960) DEBUG: Vblank took 137us
[253.272891] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.666763
last_received_ts = 253.666092
last_seq = 591
current_ts = 253.683426
current_received_ts = 253.682877
current_seq = 592
count = 354
seq_step = 1
[253.273041] (kms_flip:4960) DEBUG: Vblank took 137us
[253.289473] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.683426
last_received_ts = 253.682877
last_seq = 592
current_ts = 253.700089
current_received_ts = 253.699463
current_seq = 593
count = 355
seq_step = 1
[253.289624] (kms_flip:4960) DEBUG: Vblank took 136us
[253.306067] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.700089
last_received_ts = 253.699463
last_seq = 593
current_ts = 253.716766
current_received_ts = 253.716080
current_seq = 594
count = 356
seq_step = 1
[253.306228] (kms_flip:4960) DEBUG: Vblank took 156us
[253.322875] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.716766
last_received_ts = 253.716080
last_seq = 594
current_ts = 253.733444
current_received_ts = 253.732895
current_seq = 595
count = 357
seq_step = 1
[253.322944] (kms_flip:4960) DEBUG: Vblank took 56us
[253.339454] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.733444
last_received_ts = 253.732895
last_seq = 595
current_ts = 253.750107
current_received_ts = 253.749481
current_seq = 596
count = 358
seq_step = 1
[253.339590] (kms_flip:4960) DEBUG: Vblank took 123us
[253.356071] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.750107
last_received_ts = 253.749481
last_seq = 596
current_ts = 253.766785
current_received_ts = 253.766113
current_seq = 597
count = 359
seq_step = 1
[253.356227] (kms_flip:4960) DEBUG: Vblank took 151us
[253.372879] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.766785
last_received_ts = 253.766113
last_seq = 597
current_ts = 253.783447
current_received_ts = 253.782913
current_seq = 598
count = 360
seq_step = 1
[253.373055] (kms_flip:4960) DEBUG: Vblank took 163us
[253.389439] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.783447
last_received_ts = 253.782913
last_seq = 598
current_ts = 253.800125
current_received_ts = 253.799484
current_seq = 599
count = 361
seq_step = 1
[253.389587] (kms_flip:4960) DEBUG: Vblank took 134us
[253.406062] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.800125
last_received_ts = 253.799484
last_seq = 599
current_ts = 253.816803
current_received_ts = 253.816132
current_seq = 600
count = 362
seq_step = 1
[253.406232] (kms_flip:4960) DEBUG: Vblank took 164us
[253.422866] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.816803
last_received_ts = 253.816132
last_seq = 600
current_ts = 253.833466
current_received_ts = 253.832932
current_seq = 601
count = 363
seq_step = 1
[253.423006] (kms_flip:4960) DEBUG: Vblank took 127us
[253.439441] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.833466
last_received_ts = 253.832932
last_seq = 601
current_ts = 253.850143
current_received_ts = 253.849503
current_seq = 602
count = 364
seq_step = 1
[253.439575] (kms_flip:4960) DEBUG: Vblank took 120us
[253.456057] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.850143
last_received_ts = 253.849503
last_seq = 602
current_ts = 253.866821
current_received_ts = 253.866150
current_seq = 603
count = 365
seq_step = 1
[253.456200] (kms_flip:4960) DEBUG: Vblank took 137us
[253.472846] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.866821
last_received_ts = 253.866150
last_seq = 603
current_ts = 253.883484
current_received_ts = 253.882935
current_seq = 604
count = 366
seq_step = 1
[253.472999] (kms_flip:4960) DEBUG: Vblank took 139us
[253.489439] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.883484
last_received_ts = 253.882935
last_seq = 604
current_ts = 253.900162
current_received_ts = 253.899536
current_seq = 605
count = 367
seq_step = 1
[253.489583] (kms_flip:4960) DEBUG: Vblank took 131us
[253.506046] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.900162
last_received_ts = 253.899536
last_seq = 605
current_ts = 253.916824
current_received_ts = 253.916153
current_seq = 606
count = 368
seq_step = 1
[253.506123] (kms_flip:4960) DEBUG: Vblank took 70us
[253.522705] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.916824
last_received_ts = 253.916153
last_seq = 606
current_ts = 253.933502
current_received_ts = 253.932816
current_seq = 607
count = 369
seq_step = 1
[253.522773] (kms_flip:4960) DEBUG: Vblank took 64us
[253.539415] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.933502
last_received_ts = 253.932816
last_seq = 607
current_ts = 253.950165
current_received_ts = 253.949524
current_seq = 608
count = 370
seq_step = 1
[253.539556] (kms_flip:4960) DEBUG: Vblank took 128us
[253.556027] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.950165
last_received_ts = 253.949524
last_seq = 608
current_ts = 253.966843
current_received_ts = 253.966156
current_seq = 609
count = 371
seq_step = 1
[253.556098] (kms_flip:4960) DEBUG: Vblank took 65us
[253.572697] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.966843
last_received_ts = 253.966156
last_seq = 609
current_ts = 253.983521
current_received_ts = 253.982834
current_seq = 610
count = 372
seq_step = 1
[253.572754] (kms_flip:4960) DEBUG: Vblank took 54us
[253.589401] (kms_flip:4960) DEBUG: name = flip
last_ts = 253.983521
last_received_ts = 253.982834
last_seq = 610
current_ts = 254.000183
current_received_ts = 253.999542
current_seq = 611
count = 373
seq_step = 1
[253.589523] (kms_flip:4960) DEBUG: Vblank took 110us
[253.606030] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.000183
last_received_ts = 253.999542
last_seq = 611
current_ts = 254.016861
current_received_ts = 254.016190
current_seq = 612
count = 374
seq_step = 1
[253.606109] (kms_flip:4960) DEBUG: Vblank took 72us
[253.622824] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.016861
last_received_ts = 254.016190
last_seq = 612
current_ts = 254.033524
current_received_ts = 254.032974
current_seq = 613
count = 375
seq_step = 1
[253.622999] (kms_flip:4960) DEBUG: Vblank took 110us
[253.639412] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.033524
last_received_ts = 254.032974
last_seq = 613
current_ts = 254.050201
current_received_ts = 254.049576
current_seq = 614
count = 376
seq_step = 1
[253.639553] (kms_flip:4960) DEBUG: Vblank took 127us
[253.656027] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.050201
last_received_ts = 254.049576
last_seq = 614
current_ts = 254.066879
current_received_ts = 254.066208
current_seq = 615
count = 377
seq_step = 1
[253.656098] (kms_flip:4960) DEBUG: Vblank took 66us
[253.672874] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.066879
last_received_ts = 254.066208
last_seq = 615
current_ts = 254.083542
current_received_ts = 254.083054
current_seq = 616
count = 378
seq_step = 1
[253.672983] (kms_flip:4960) DEBUG: Vblank took 95us
[253.689408] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.083542
last_received_ts = 254.083054
last_seq = 616
current_ts = 254.100220
current_received_ts = 254.099594
current_seq = 617
count = 379
seq_step = 1
[253.689536] (kms_flip:4960) DEBUG: Vblank took 114us
[253.706043] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.100220
last_received_ts = 254.099594
last_seq = 617
current_ts = 254.116898
current_received_ts = 254.116241
current_seq = 618
count = 380
seq_step = 1
[253.706200] (kms_flip:4960) DEBUG: Vblank took 151us
[253.722777] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.116898
last_received_ts = 254.116241
last_seq = 618
current_ts = 254.133560
current_received_ts = 254.132980
current_seq = 619
count = 381
seq_step = 1
[253.722907] (kms_flip:4960) DEBUG: Vblank took 81us
[253.739393] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.133560
last_received_ts = 254.132980
last_seq = 619
current_ts = 254.150238
current_received_ts = 254.149597
current_seq = 620
count = 382
seq_step = 1
[253.739521] (kms_flip:4960) DEBUG: Vblank took 115us
[253.756050] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.150238
last_received_ts = 254.149597
last_seq = 620
current_ts = 254.166901
current_received_ts = 254.166275
current_seq = 621
count = 383
seq_step = 1
[253.756191] (kms_flip:4960) DEBUG: Vblank took 135us
[253.772715] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.166901
last_received_ts = 254.166275
last_seq = 621
current_ts = 254.183578
current_received_ts = 254.182938
current_seq = 622
count = 384
seq_step = 1
[253.772857] (kms_flip:4960) DEBUG: Vblank took 129us
[253.789390] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.183578
last_received_ts = 254.182938
last_seq = 622
current_ts = 254.200241
current_received_ts = 254.199615
current_seq = 623
count = 385
seq_step = 1
[253.789516] (kms_flip:4960) DEBUG: Vblank took 113us
[253.806026] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.200241
last_received_ts = 254.199615
last_seq = 623
current_ts = 254.216919
current_received_ts = 254.216263
current_seq = 624
count = 386
seq_step = 1
[253.806189] (kms_flip:4960) DEBUG: Vblank took 154us
[253.822808] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.216919
last_received_ts = 254.216263
last_seq = 624
current_ts = 254.233597
current_received_ts = 254.233047
current_seq = 625
count = 387
seq_step = 1
[253.822902] (kms_flip:4960) DEBUG: Vblank took 81us
[253.839284] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.233597
last_received_ts = 254.233047
last_seq = 625
current_ts = 254.250259
current_received_ts = 254.249527
current_seq = 626
count = 388
seq_step = 1
[253.839424] (kms_flip:4960) DEBUG: Vblank took 125us
[253.856060] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.250259
last_received_ts = 254.249527
last_seq = 626
current_ts = 254.266922
current_received_ts = 254.266312
current_seq = 627
count = 389
seq_step = 1
[253.856163] (kms_flip:4960) DEBUG: Vblank took 88us
[253.872815] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.266922
last_received_ts = 254.266312
last_seq = 627
current_ts = 254.283600
current_received_ts = 254.283081
current_seq = 628
count = 390
seq_step = 1
[253.872913] (kms_flip:4960) DEBUG: Vblank took 83us
[253.889285] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.283600
last_received_ts = 254.283081
last_seq = 628
current_ts = 254.300278
current_received_ts = 254.299561
current_seq = 629
count = 391
seq_step = 1
[253.889412] (kms_flip:4960) DEBUG: Vblank took 114us
[253.906005] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.300278
last_received_ts = 254.299561
last_seq = 629
current_ts = 254.316940
current_received_ts = 254.316299
current_seq = 630
count = 392
seq_step = 1
[253.906159] (kms_flip:4960) DEBUG: Vblank took 147us
[253.922814] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.316940
last_received_ts = 254.316299
last_seq = 630
current_ts = 254.333618
current_received_ts = 254.333099
current_seq = 631
count = 393
seq_step = 1
[253.922936] (kms_flip:4960) DEBUG: Vblank took 107us
[253.939363] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.333618
last_received_ts = 254.333099
last_seq = 631
current_ts = 254.350296
current_received_ts = 254.349655
current_seq = 632
count = 394
seq_step = 1
[253.939494] (kms_flip:4960) DEBUG: Vblank took 118us
[253.956099] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.350296
last_received_ts = 254.349655
last_seq = 632
current_ts = 254.366959
current_received_ts = 254.366394
current_seq = 633
count = 395
seq_step = 1
[253.956201] (kms_flip:4960) DEBUG: Vblank took 89us
[253.972714] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.366959
last_received_ts = 254.366394
last_seq = 633
current_ts = 254.383621
current_received_ts = 254.383026
current_seq = 634
count = 396
seq_step = 1
[253.972833] (kms_flip:4960) DEBUG: Vblank took 108us
[253.989321] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.383621
last_received_ts = 254.383026
last_seq = 634
current_ts = 254.400299
current_received_ts = 254.399643
current_seq = 635
count = 397
seq_step = 1
[253.989395] (kms_flip:4960) DEBUG: Vblank took 69us
[254.005966] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.400299
last_received_ts = 254.399643
last_seq = 635
current_ts = 254.416962
current_received_ts = 254.416306
current_seq = 636
count = 398
seq_step = 1
[254.006028] (kms_flip:4960) DEBUG: Vblank took 57us
[254.022789] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.416962
last_received_ts = 254.416306
last_seq = 636
current_ts = 254.433640
current_received_ts = 254.433105
current_seq = 637
count = 399
seq_step = 1
[254.022902] (kms_flip:4960) DEBUG: Vblank took 98us
[254.039309] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.433640
last_received_ts = 254.433105
last_seq = 637
current_ts = 254.450302
current_received_ts = 254.449646
current_seq = 638
count = 400
seq_step = 1
[254.039427] (kms_flip:4960) DEBUG: Vblank took 108us
[254.056102] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.450302
last_received_ts = 254.449646
last_seq = 638
current_ts = 254.466980
current_received_ts = 254.466446
current_seq = 639
count = 401
seq_step = 1
[254.056199] (kms_flip:4960) DEBUG: Vblank took 83us
[254.072717] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.466980
last_received_ts = 254.466446
last_seq = 639
current_ts = 254.483658
current_received_ts = 254.483063
current_seq = 640
count = 402
seq_step = 1
[254.072846] (kms_flip:4960) DEBUG: Vblank took 114us
[254.089455] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.483658
last_received_ts = 254.483063
last_seq = 640
current_ts = 254.500320
current_received_ts = 254.499802
current_seq = 641
count = 403
seq_step = 1
[254.089550] (kms_flip:4960) DEBUG: Vblank took 81us
[254.106033] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.500320
last_received_ts = 254.499802
last_seq = 641
current_ts = 254.516998
current_received_ts = 254.516388
current_seq = 642
count = 404
seq_step = 1
[254.106202] (kms_flip:4960) DEBUG: Vblank took 152us
[254.122893] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.516998
last_received_ts = 254.516388
last_seq = 642
current_ts = 254.533661
current_received_ts = 254.533218
current_seq = 643
count = 405
seq_step = 1
[254.123073] (kms_flip:4960) DEBUG: Vblank took 142us
[254.139336] (kms_flip:4960) DEBUG: name = flip
last_ts = 254.533661
last_received_ts = 254.533218
last_seq = 643
current_ts = 254.550339
current_received_ts = 254.549698
current_seq = 644
count = 406
seq_step = 1
[254.140917] (kms_flip:4960) DEBUG: Vblank took 1556us
[254.140930] (kms_flip:4960) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[254.141055] (kms_flip:4960) CRITICAL: Failed assertion: end - start < 500
[254.146717] (kms_flip:4960) igt_core-INFO: Stack trace:
[254.151235] (kms_flip:4960) igt_core-INFO:   #0 ../lib/igt_core.c:2074 __igt_fail_assert()
[254.153861] (kms_flip:4960) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[254.153963] (kms_flip:4960) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[254.154026] (kms_flip:4960) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
[254.154087] (kms_flip:4960) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[254.159386] (kms_flip:4960) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[254.174384] (kms_flip:4960) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[254.175287] (kms_flip:4960) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (8.126s)

Dmesg

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

<7> [352.091928] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:442]

<7> [352.093499] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:443]

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

<7> [352.176759] 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> [352.177148] 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> [352.177407] 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> [352.177647] 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> [352.177875] 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> [352.178096] 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> [352.178339] 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> [352.178550] 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> [352.178749] 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> [352.178945] 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> [352.179148] 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> [352.179339] 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> [352.179525] 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> [352.179699] 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> [352.179871] 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> [352.180039] 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> [352.180214] 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> [352.180373] 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> [352.180527] 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> [352.180674] 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> [352.180820] 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> [352.180960] 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> [352.181111] 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> [352.181249] 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> [352.181381] 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> [352.181512] 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> [352.181641] 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> [352.181768] 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> [352.181893] 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> [352.182013] 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> [352.182175] 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> [352.182303] 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> [352.182425] 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> [352.182546] 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> [352.182664] 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> [352.182779] 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> [352.182890] 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> [352.183000] 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> [352.183120] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

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

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

<7> [352.183491] 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> [352.183616] 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> [352.183704] 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> [352.183805] 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> [352.183882] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [352.186637] 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: 0x0000006f

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

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

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

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

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

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

<7> [352.405943] 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> [352.406479] 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> [352.406414] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [352.481179] 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> [352.481514] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] 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> [352.481810] 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> [352.482134] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [352.488837] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

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

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

<7> [352.489083] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0

<7> [352.489156] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197

<7> [352.489217] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198

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

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

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

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

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

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

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

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

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

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

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

<7> [352.490463] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0

<7> [352.490550] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0

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

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

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

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

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

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

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

<7> [352.491310] 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> [352.491389] 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> [352.491470] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

<7> [352.492616] 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> [352.492689] 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> [352.492762] 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> [352.492838] 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> [352.492935] 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> [352.493032] 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> [352.493125] 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> [352.493195] 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> [352.493270] 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> [352.493347] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

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

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

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

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

<7> [352.493805] 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> [352.493914] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [352.496975] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [352.499840] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B]

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

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

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

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

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

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

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

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

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

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

<7> [353.210033] 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> [353.212255] 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> [353.213838] 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> [353.214760] 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> [353.216045] 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> [353.217623] 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> [353.218952] 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> [353.219543] 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> [353.221187] 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> [353.221699] 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> [353.222653] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B

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

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

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

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

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

<7> [353.259252] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B]

<7> [355.771712] 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> [355.772272] 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> [360.073380] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

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

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

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

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