igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1 on shard-lnl@xe-5101-7d39df83e93eba14a23b1fb6ffff076eb191f27b Test details

Detail	Value
Duration	8.77 seconds
Hostname	shard-lnl-2
Igt-Version	IGT-Version: 2.4-g3cb6109b3 (x86_64) (Linux: 7.1.0-rc4-lgci-xe-xe-5101-7d39df83e93eba14a-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:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main() #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34() #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (8.769s)
Err	Starting dynamic subtest: B-eDP1 [391.390127] (kms_flip:7691) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [391.390256] (kms_flip:7691) CRITICAL: Failed assertion: end - start < 500 [391.390332] (kms_flip:7691) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG [389.372723] (kms_flip:7691) DEBUG: Vblank took 66us [389.389301] (kms_flip:7691) DEBUG: name = flip last_ts = 391.866302 last_received_ts = 391.865723 last_seq = 522 current_ts = 391.882965 current_received_ts = 391.882385 current_seq = 523 count = 326 seq_step = 1 [389.389374] (kms_flip:7691) DEBUG: Vblank took 67us [389.405969] (kms_flip:7691) DEBUG: name = flip last_ts = 391.882965 last_received_ts = 391.882385 last_seq = 523 current_ts = 391.899628 current_received_ts = 391.899048 current_seq = 524 count = 327 seq_step = 1 [389.406017] (kms_flip:7691) DEBUG: Vblank took 43us [389.422582] (kms_flip:7691) DEBUG: name = flip last_ts = 391.899628 last_received_ts = 391.899048 last_seq = 524 current_ts = 391.916321 current_received_ts = 391.915680 current_seq = 525 count = 328 seq_step = 1 [389.422676] (kms_flip:7691) DEBUG: Vblank took 68us [389.439254] (kms_flip:7691) DEBUG: name = flip last_ts = 391.916321 last_received_ts = 391.915680 last_seq = 525 current_ts = 391.932983 current_received_ts = 391.932343 current_seq = 526 count = 329 seq_step = 1 [389.439327] (kms_flip:7691) DEBUG: Vblank took 68us [389.455959] (kms_flip:7691) DEBUG: name = flip last_ts = 391.932983 last_received_ts = 391.932343 last_seq = 526 current_ts = 391.949646 current_received_ts = 391.949066 current_seq = 527 count = 330 seq_step = 1 [389.456032] (kms_flip:7691) DEBUG: Vblank took 68us [389.472540] (kms_flip:7691) DEBUG: name = flip last_ts = 391.949646 last_received_ts = 391.949066 last_seq = 527 current_ts = 391.966339 current_received_ts = 391.965668 current_seq = 528 count = 331 seq_step = 1 [389.472607] (kms_flip:7691) DEBUG: Vblank took 62us [389.489195] (kms_flip:7691) DEBUG: name = flip last_ts = 391.966339 last_received_ts = 391.965668 last_seq = 528 current_ts = 391.983002 current_received_ts = 391.982330 current_seq = 529 count = 332 seq_step = 1 [389.489275] (kms_flip:7691) DEBUG: Vblank took 75us [389.505915] (kms_flip:7691) DEBUG: name = flip last_ts = 391.983002 last_received_ts = 391.982330 last_seq = 529 current_ts = 391.999664 current_received_ts = 391.999054 current_seq = 530 count = 333 seq_step = 1 [389.505963] (kms_flip:7691) DEBUG: Vblank took 43us [389.522514] (kms_flip:7691) DEBUG: name = flip last_ts = 391.999664 last_received_ts = 391.999054 last_seq = 530 current_ts = 392.016357 current_received_ts = 392.015656 current_seq = 531 count = 334 seq_step = 1 [389.522564] (kms_flip:7691) DEBUG: Vblank took 45us [389.539287] (kms_flip:7691) DEBUG: name = flip last_ts = 392.016357 last_received_ts = 392.015656 last_seq = 531 current_ts = 392.033020 current_received_ts = 392.032440 current_seq = 532 count = 335 seq_step = 1 [389.539354] (kms_flip:7691) DEBUG: Vblank took 61us [389.555904] (kms_flip:7691) DEBUG: name = flip last_ts = 392.033020 last_received_ts = 392.032440 last_seq = 532 current_ts = 392.049683 current_received_ts = 392.049042 current_seq = 533 count = 336 seq_step = 1 [389.555977] (kms_flip:7691) DEBUG: Vblank took 69us [389.572681] (kms_flip:7691) DEBUG: name = flip last_ts = 392.049683 last_received_ts = 392.049042 last_seq = 533 current_ts = 392.066345 current_received_ts = 392.065826 current_seq = 534 count = 337 seq_step = 1 [389.572757] (kms_flip:7691) DEBUG: Vblank took 72us [389.589229] (kms_flip:7691) DEBUG: name = flip last_ts = 392.066345 last_received_ts = 392.065826 last_seq = 534 current_ts = 392.083038 current_received_ts = 392.082397 current_seq = 535 count = 338 seq_step = 1 [389.589301] (kms_flip:7691) DEBUG: Vblank took 67us [389.605933] (kms_flip:7691) DEBUG: name = flip last_ts = 392.083038 last_received_ts = 392.082397 last_seq = 535 current_ts = 392.099701 current_received_ts = 392.099091 current_seq = 536 count = 339 seq_step = 1 [389.606011] (kms_flip:7691) DEBUG: Vblank took 73us [389.622508] (kms_flip:7691) DEBUG: name = flip last_ts = 392.099701 last_received_ts = 392.099091 last_seq = 536 current_ts = 392.116364 current_received_ts = 392.115692 current_seq = 537 count = 340 seq_step = 1 [389.622578] (kms_flip:7691) DEBUG: Vblank took 65us [389.639202] (kms_flip:7691) DEBUG: name = flip last_ts = 392.116364 last_received_ts = 392.115692 last_seq = 537 current_ts = 392.133026 current_received_ts = 392.132385 current_seq = 538 count = 341 seq_step = 1 [389.639280] (kms_flip:7691) DEBUG: Vblank took 72us [389.655933] (kms_flip:7691) DEBUG: name = flip last_ts = 392.133026 last_received_ts = 392.132385 last_seq = 538 current_ts = 392.149719 current_received_ts = 392.149139 current_seq = 539 count = 342 seq_step = 1 [389.656012] (kms_flip:7691) DEBUG: Vblank took 73us [389.672564] (kms_flip:7691) DEBUG: name = flip last_ts = 392.149719 last_received_ts = 392.149139 last_seq = 539 current_ts = 392.166382 current_received_ts = 392.165771 current_seq = 540 count = 343 seq_step = 1 [389.672639] (kms_flip:7691) DEBUG: Vblank took 69us [389.689284] (kms_flip:7691) DEBUG: name = flip last_ts = 392.166382 last_received_ts = 392.165771 last_seq = 540 current_ts = 392.183044 current_received_ts = 392.182495 current_seq = 541 count = 344 seq_step = 1 [389.689353] (kms_flip:7691) DEBUG: Vblank took 64us [389.705929] (kms_flip:7691) DEBUG: name = flip last_ts = 392.183044 last_received_ts = 392.182495 last_seq = 541 current_ts = 392.199738 current_received_ts = 392.199158 current_seq = 542 count = 345 seq_step = 1 [389.706011] (kms_flip:7691) DEBUG: Vblank took 76us [389.722523] (kms_flip:7691) DEBUG: name = flip last_ts = 392.199738 last_received_ts = 392.199158 last_seq = 542 current_ts = 392.216400 current_received_ts = 392.215759 current_seq = 543 count = 346 seq_step = 1 [389.722594] (kms_flip:7691) DEBUG: Vblank took 66us [389.739257] (kms_flip:7691) DEBUG: name = flip last_ts = 392.216400 last_received_ts = 392.215759 last_seq = 543 current_ts = 392.233063 current_received_ts = 392.232483 current_seq = 544 count = 347 seq_step = 1 [389.739340] (kms_flip:7691) DEBUG: Vblank took 77us [389.755932] (kms_flip:7691) DEBUG: name = flip last_ts = 392.233063 last_received_ts = 392.232483 last_seq = 544 current_ts = 392.249725 current_received_ts = 392.249176 current_seq = 545 count = 348 seq_step = 1 [389.756008] (kms_flip:7691) DEBUG: Vblank took 70us [389.772423] (kms_flip:7691) DEBUG: name = flip last_ts = 392.249725 last_received_ts = 392.249176 last_seq = 545 current_ts = 392.266418 current_received_ts = 392.265656 current_seq = 546 count = 349 seq_step = 1 [389.772497] (kms_flip:7691) DEBUG: Vblank took 69us [389.789198] (kms_flip:7691) DEBUG: name = flip last_ts = 392.266418 last_received_ts = 392.265656 last_seq = 546 current_ts = 392.283081 current_received_ts = 392.282440 current_seq = 547 count = 350 seq_step = 1 [389.789280] (kms_flip:7691) DEBUG: Vblank took 76us [389.805797] (kms_flip:7691) DEBUG: name = flip last_ts = 392.283081 last_received_ts = 392.282440 last_seq = 547 current_ts = 392.299744 current_received_ts = 392.299042 current_seq = 548 count = 351 seq_step = 1 [389.805875] (kms_flip:7691) DEBUG: Vblank took 72us [389.822574] (kms_flip:7691) DEBUG: name = flip last_ts = 392.299744 last_received_ts = 392.299042 last_seq = 548 current_ts = 392.316437 current_received_ts = 392.315826 current_seq = 549 count = 352 seq_step = 1 [389.822647] (kms_flip:7691) DEBUG: Vblank took 67us [389.839192] (kms_flip:7691) DEBUG: name = flip last_ts = 392.316437 last_received_ts = 392.315826 last_seq = 549 current_ts = 392.333099 current_received_ts = 392.332458 current_seq = 550 count = 353 seq_step = 1 [389.839263] (kms_flip:7691) DEBUG: Vblank took 66us [389.855890] (kms_flip:7691) DEBUG: name = flip last_ts = 392.333099 last_received_ts = 392.332458 last_seq = 550 current_ts = 392.349762 current_received_ts = 392.349182 current_seq = 551 count = 354 seq_step = 1 [389.855938] (kms_flip:7691) DEBUG: Vblank took 43us [389.872519] (kms_flip:7691) DEBUG: name = flip last_ts = 392.349762 last_received_ts = 392.349182 last_seq = 551 current_ts = 392.366425 current_received_ts = 392.365814 current_seq = 552 count = 355 seq_step = 1 [389.872599] (kms_flip:7691) DEBUG: Vblank took 74us [389.889152] (kms_flip:7691) DEBUG: name = flip last_ts = 392.366425 last_received_ts = 392.365814 last_seq = 552 current_ts = 392.383118 current_received_ts = 392.382446 current_seq = 553 count = 356 seq_step = 1 [389.889232] (kms_flip:7691) DEBUG: Vblank took 73us [389.905923] (kms_flip:7691) DEBUG: name = flip last_ts = 392.383118 last_received_ts = 392.382446 last_seq = 553 current_ts = 392.399780 current_received_ts = 392.399231 current_seq = 554 count = 357 seq_step = 1 [389.905970] (kms_flip:7691) DEBUG: Vblank took 42us [389.922528] (kms_flip:7691) DEBUG: name = flip last_ts = 392.399780 last_received_ts = 392.399231 last_seq = 554 current_ts = 392.416443 current_received_ts = 392.415833 current_seq = 555 count = 358 seq_step = 1 [389.922627] (kms_flip:7691) DEBUG: Vblank took 95us [389.939207] (kms_flip:7691) DEBUG: name = flip last_ts = 392.416443 last_received_ts = 392.415833 last_seq = 555 current_ts = 392.433136 current_received_ts = 392.432495 current_seq = 556 count = 359 seq_step = 1 [389.939324] (kms_flip:7691) DEBUG: Vblank took 99us [389.955886] (kms_flip:7691) DEBUG: name = flip last_ts = 392.433136 last_received_ts = 392.432495 last_seq = 556 current_ts = 392.449799 current_received_ts = 392.449219 current_seq = 557 count = 360 seq_step = 1 [389.955974] (kms_flip:7691) DEBUG: Vblank took 79us [389.972434] (kms_flip:7691) DEBUG: name = flip last_ts = 392.449799 last_received_ts = 392.449219 last_seq = 557 current_ts = 392.466461 current_received_ts = 392.465759 current_seq = 558 count = 361 seq_step = 1 [389.972513] (kms_flip:7691) DEBUG: Vblank took 71us [389.989148] (kms_flip:7691) DEBUG: name = flip last_ts = 392.466461 last_received_ts = 392.465759 last_seq = 558 current_ts = 392.483124 current_received_ts = 392.482483 current_seq = 559 count = 362 seq_step = 1 [389.989223] (kms_flip:7691) DEBUG: Vblank took 69us [390.005813] (kms_flip:7691) DEBUG: name = flip last_ts = 392.483124 last_received_ts = 392.482483 last_seq = 559 current_ts = 392.499817 current_received_ts = 392.499146 current_seq = 560 count = 363 seq_step = 1 [390.005888] (kms_flip:7691) DEBUG: Vblank took 68us [390.022583] (kms_flip:7691) DEBUG: name = flip last_ts = 392.499817 last_received_ts = 392.499146 last_seq = 560 current_ts = 392.516479 current_received_ts = 392.515930 current_seq = 561 count = 364 seq_step = 1 [390.022693] (kms_flip:7691) DEBUG: Vblank took 104us [390.039154] (kms_flip:7691) DEBUG: name = flip last_ts = 392.516479 last_received_ts = 392.515930 last_seq = 561 current_ts = 392.533142 current_received_ts = 392.532501 current_seq = 562 count = 365 seq_step = 1 [390.039227] (kms_flip:7691) DEBUG: Vblank took 67us [390.055872] (kms_flip:7691) DEBUG: name = flip last_ts = 392.533142 last_received_ts = 392.532501 last_seq = 562 current_ts = 392.549835 current_received_ts = 392.549225 current_seq = 563 count = 366 seq_step = 1 [390.055952] (kms_flip:7691) DEBUG: Vblank took 73us [390.072462] (kms_flip:7691) DEBUG: name = flip last_ts = 392.549835 last_received_ts = 392.549225 last_seq = 563 current_ts = 392.566498 current_received_ts = 392.565826 current_seq = 564 count = 367 seq_step = 1 [390.072533] (kms_flip:7691) DEBUG: Vblank took 65us [390.089193] (kms_flip:7691) DEBUG: name = flip last_ts = 392.566498 last_received_ts = 392.565826 last_seq = 564 current_ts = 392.583160 current_received_ts = 392.582581 current_seq = 565 count = 368 seq_step = 1 [390.089265] (kms_flip:7691) DEBUG: Vblank took 66us [390.105906] (kms_flip:7691) DEBUG: name = flip last_ts = 392.583160 last_received_ts = 392.582581 last_seq = 565 current_ts = 392.599823 current_received_ts = 392.599304 current_seq = 566 count = 369 seq_step = 1 [390.105986] (kms_flip:7691) DEBUG: Vblank took 72us [390.122525] (kms_flip:7691) DEBUG: name = flip last_ts = 392.599823 last_received_ts = 392.599304 last_seq = 566 current_ts = 392.616516 current_received_ts = 392.615936 current_seq = 567 count = 370 seq_step = 1 [390.122573] (kms_flip:7691) DEBUG: Vblank took 43us [390.139060] (kms_flip:7691) DEBUG: name = flip last_ts = 392.616516 last_received_ts = 392.615936 last_seq = 567 current_ts = 392.633179 current_received_ts = 392.632477 current_seq = 568 count = 371 seq_step = 1 [390.139130] (kms_flip:7691) DEBUG: Vblank took 64us [390.155887] (kms_flip:7691) DEBUG: name = flip last_ts = 392.633179 last_received_ts = 392.632477 last_seq = 568 current_ts = 392.649841 current_received_ts = 392.649292 current_seq = 569 count = 372 seq_step = 1 [390.155934] (kms_flip:7691) DEBUG: Vblank took 42us [390.172429] (kms_flip:7691) DEBUG: name = flip last_ts = 392.649841 last_received_ts = 392.649292 last_seq = 569 current_ts = 392.666504 current_received_ts = 392.665833 current_seq = 570 count = 373 seq_step = 1 [390.172490] (kms_flip:7691) DEBUG: Vblank took 53us [390.189211] (kms_flip:7691) DEBUG: name = flip last_ts = 392.666504 last_received_ts = 392.665833 last_seq = 570 current_ts = 392.683197 current_received_ts = 392.682617 current_seq = 571 count = 374 seq_step = 1 [390.189297] (kms_flip:7691) DEBUG: Vblank took 77us [390.205884] (kms_flip:7691) DEBUG: name = flip last_ts = 392.683197 last_received_ts = 392.682617 last_seq = 571 current_ts = 392.699860 current_received_ts = 392.699310 current_seq = 572 count = 375 seq_step = 1 [390.205966] (kms_flip:7691) DEBUG: Vblank took 75us [390.222425] (kms_flip:7691) DEBUG: name = flip last_ts = 392.699860 last_received_ts = 392.699310 last_seq = 572 current_ts = 392.716522 current_received_ts = 392.715851 current_seq = 573 count = 376 seq_step = 1 [390.222497] (kms_flip:7691) DEBUG: Vblank took 66us [390.239170] (kms_flip:7691) DEBUG: name = flip last_ts = 392.716522 last_received_ts = 392.715851 last_seq = 573 current_ts = 392.733215 current_received_ts = 392.732605 current_seq = 574 count = 377 seq_step = 1 [390.239248] (kms_flip:7691) DEBUG: Vblank took 72us [390.255761] (kms_flip:7691) DEBUG: name = flip last_ts = 392.733215 last_received_ts = 392.732605 last_seq = 574 current_ts = 392.749878 current_received_ts = 392.749207 current_seq = 575 count = 378 seq_step = 1 [390.255831] (kms_flip:7691) DEBUG: Vblank took 65us [390.272516] (kms_flip:7691) DEBUG: name = flip last_ts = 392.749878 last_received_ts = 392.749207 last_seq = 575 current_ts = 392.766541 current_received_ts = 392.765991 current_seq = 576 count = 379 seq_step = 1 [390.272618] (kms_flip:7691) DEBUG: Vblank took 96us [390.289157] (kms_flip:7691) DEBUG: name = flip last_ts = 392.766541 last_received_ts = 392.765991 last_seq = 576 current_ts = 392.783234 current_received_ts = 392.782623 current_seq = 577 count = 380 seq_step = 1 [390.289236] (kms_flip:7691) DEBUG: Vblank took 74us [390.305841] (kms_flip:7691) DEBUG: name = flip last_ts = 392.783234 last_received_ts = 392.782623 last_seq = 577 current_ts = 392.799896 current_received_ts = 392.799316 current_seq = 578 count = 381 seq_step = 1 [390.305888] (kms_flip:7691) DEBUG: Vblank took 42us [390.322350] (kms_flip:7691) DEBUG: name = flip last_ts = 392.799896 last_received_ts = 392.799316 last_seq = 578 current_ts = 392.816559 current_received_ts = 392.815826 current_seq = 579 count = 382 seq_step = 1 [390.322423] (kms_flip:7691) DEBUG: Vblank took 67us [390.339135] (kms_flip:7691) DEBUG: name = flip last_ts = 392.816559 last_received_ts = 392.815826 last_seq = 579 current_ts = 392.833221 current_received_ts = 392.832642 current_seq = 580 count = 383 seq_step = 1 [390.339204] (kms_flip:7691) DEBUG: Vblank took 63us [390.355836] (kms_flip:7691) DEBUG: name = flip last_ts = 392.833221 last_received_ts = 392.832642 last_seq = 580 current_ts = 392.849915 current_received_ts = 392.849335 current_seq = 581 count = 384 seq_step = 1 [390.355903] (kms_flip:7691) DEBUG: Vblank took 62us [390.372416] (kms_flip:7691) DEBUG: name = flip last_ts = 392.849915 last_received_ts = 392.849335 last_seq = 581 current_ts = 392.866577 current_received_ts = 392.865936 current_seq = 582 count = 385 seq_step = 1 [390.372516] (kms_flip:7691) DEBUG: Vblank took 93us [390.389085] (kms_flip:7691) DEBUG: name = flip last_ts = 392.866577 last_received_ts = 392.865936 last_seq = 582 current_ts = 392.883240 current_received_ts = 392.882599 current_seq = 583 count = 386 seq_step = 1 [390.389166] (kms_flip:7691) DEBUG: Vblank took 76us [390.405846] (kms_flip:7691) DEBUG: name = flip last_ts = 392.883240 last_received_ts = 392.882599 last_seq = 583 current_ts = 392.899933 current_received_ts = 392.899353 current_seq = 584 count = 387 seq_step = 1 [390.405897] (kms_flip:7691) DEBUG: Vblank took 44us [390.422324] (kms_flip:7691) DEBUG: name = flip last_ts = 392.899933 last_received_ts = 392.899353 last_seq = 584 current_ts = 392.916595 current_received_ts = 392.915863 current_seq = 585 count = 388 seq_step = 1 [390.422395] (kms_flip:7691) DEBUG: Vblank took 66us [390.439090] (kms_flip:7691) DEBUG: name = flip last_ts = 392.916595 last_received_ts = 392.915863 last_seq = 585 current_ts = 392.933258 current_received_ts = 392.932617 current_seq = 586 count = 389 seq_step = 1 [390.439155] (kms_flip:7691) DEBUG: Vblank took 60us [390.455824] (kms_flip:7691) DEBUG: name = flip last_ts = 392.933258 last_received_ts = 392.932617 last_seq = 586 current_ts = 392.949921 current_received_ts = 392.949371 current_seq = 587 count = 390 seq_step = 1 [390.455890] (kms_flip:7691) DEBUG: Vblank took 62us [390.472411] (kms_flip:7691) DEBUG: name = flip last_ts = 392.949921 last_received_ts = 392.949371 last_seq = 587 current_ts = 392.966614 current_received_ts = 392.965973 current_seq = 588 count = 391 seq_step = 1 [390.472491] (kms_flip:7691) DEBUG: Vblank took 75us [390.489060] (kms_flip:7691) DEBUG: name = flip last_ts = 392.966614 last_received_ts = 392.965973 last_seq = 588 current_ts = 392.983276 current_received_ts = 392.982605 current_seq = 589 count = 392 seq_step = 1 [390.489134] (kms_flip:7691) DEBUG: Vblank took 67us [390.505661] (kms_flip:7691) DEBUG: name = flip last_ts = 392.983276 last_received_ts = 392.982605 last_seq = 589 current_ts = 392.999939 current_received_ts = 392.999237 current_seq = 590 count = 393 seq_step = 1 [390.505738] (kms_flip:7691) DEBUG: Vblank took 72us [390.522506] (kms_flip:7691) DEBUG: name = flip last_ts = 392.999939 last_received_ts = 392.999237 last_seq = 590 current_ts = 393.016632 current_received_ts = 393.016083 current_seq = 591 count = 394 seq_step = 1 [390.522571] (kms_flip:7691) DEBUG: Vblank took 60us [390.539163] (kms_flip:7691) DEBUG: name = flip last_ts = 393.016632 last_received_ts = 393.016083 last_seq = 591 current_ts = 393.033295 current_received_ts = 393.032745 current_seq = 592 count = 395 seq_step = 1 [390.539233] (kms_flip:7691) DEBUG: Vblank took 65us [390.555741] (kms_flip:7691) DEBUG: name = flip last_ts = 393.033295 last_received_ts = 393.032745 last_seq = 592 current_ts = 393.049957 current_received_ts = 393.049316 current_seq = 593 count = 396 seq_step = 1 [390.555821] (kms_flip:7691) DEBUG: Vblank took 75us [390.572430] (kms_flip:7691) DEBUG: name = flip last_ts = 393.049957 last_received_ts = 393.049316 last_seq = 593 current_ts = 393.066620 current_received_ts = 393.066010 current_seq = 594 count = 397 seq_step = 1 [390.572501] (kms_flip:7691) DEBUG: Vblank took 66us [390.588969] (kms_flip:7691) DEBUG: name = flip last_ts = 393.066620 last_received_ts = 393.066010 last_seq = 594 current_ts = 393.083313 current_received_ts = 393.082581 current_seq = 595 count = 398 seq_step = 1 [390.589036] (kms_flip:7691) DEBUG: Vblank took 62us [390.605829] (kms_flip:7691) DEBUG: name = flip last_ts = 393.083313 last_received_ts = 393.082581 last_seq = 595 current_ts = 393.099976 current_received_ts = 393.099426 current_seq = 596 count = 399 seq_step = 1 [390.605902] (kms_flip:7691) DEBUG: Vblank took 66us [390.622324] (kms_flip:7691) DEBUG: name = flip last_ts = 393.099976 last_received_ts = 393.099426 last_seq = 596 current_ts = 393.116638 current_received_ts = 393.115936 current_seq = 597 count = 400 seq_step = 1 [390.622424] (kms_flip:7691) DEBUG: Vblank took 94us [390.639031] (kms_flip:7691) DEBUG: name = flip last_ts = 393.116638 last_received_ts = 393.115936 last_seq = 597 current_ts = 393.133331 current_received_ts = 393.132660 current_seq = 598 count = 401 seq_step = 1 [390.639110] (kms_flip:7691) DEBUG: Vblank took 73us [390.655740] (kms_flip:7691) DEBUG: name = flip last_ts = 393.133331 last_received_ts = 393.132660 last_seq = 598 current_ts = 393.149994 current_received_ts = 393.149384 current_seq = 599 count = 402 seq_step = 1 [390.655818] (kms_flip:7691) DEBUG: Vblank took 73us [390.672441] (kms_flip:7691) DEBUG: name = flip last_ts = 393.149994 last_received_ts = 393.149384 last_seq = 599 current_ts = 393.166656 current_received_ts = 393.166077 current_seq = 600 count = 403 seq_step = 1 [390.672511] (kms_flip:7691) DEBUG: Vblank took 65us [390.689145] (kms_flip:7691) DEBUG: name = flip last_ts = 393.166656 last_received_ts = 393.166077 last_seq = 600 current_ts = 393.183319 current_received_ts = 393.182800 current_seq = 601 count = 404 seq_step = 1 [390.689244] (kms_flip:7691) DEBUG: Vblank took 93us [390.705779] (kms_flip:7691) DEBUG: name = flip last_ts = 393.183319 last_received_ts = 393.182800 last_seq = 601 current_ts = 393.200012 current_received_ts = 393.199432 current_seq = 602 count = 405 seq_step = 1 [390.705857] (kms_flip:7691) DEBUG: Vblank took 73us [390.722308] (kms_flip:7691) DEBUG: name = flip last_ts = 393.200012 last_received_ts = 393.199432 last_seq = 602 current_ts = 393.216675 current_received_ts = 393.215973 current_seq = 603 count = 406 seq_step = 1 [390.722412] (kms_flip:7691) DEBUG: Vblank took 98us [390.739032] (kms_flip:7691) DEBUG: name = flip last_ts = 393.216675 last_received_ts = 393.215973 last_seq = 603 current_ts = 393.233337 current_received_ts = 393.232697 current_seq = 604 count = 407 seq_step = 1 [390.739104] (kms_flip:7691) DEBUG: Vblank took 66us [390.755701] (kms_flip:7691) DEBUG: name = flip last_ts = 393.233337 last_received_ts = 393.232697 last_seq = 604 current_ts = 393.250031 current_received_ts = 393.249359 current_seq = 605 count = 408 seq_step = 1 [390.755773] (kms_flip:7691) DEBUG: Vblank took 66us [390.772420] (kms_flip:7691) DEBUG: name = flip last_ts = 393.250031 last_received_ts = 393.249359 last_seq = 605 current_ts = 393.266693 current_received_ts = 393.266113 current_seq = 606 count = 409 seq_step = 1 [390.772497] (kms_flip:7691) DEBUG: Vblank took 72us [390.789133] (kms_flip:7691) DEBUG: name = flip last_ts = 393.266693 last_received_ts = 393.266113 last_seq = 606 current_ts = 393.283356 current_received_ts = 393.282806 current_seq = 607 count = 410 seq_step = 1 [390.789207] (kms_flip:7691) DEBUG: Vblank took 68us [390.805787] (kms_flip:7691) DEBUG: name = flip last_ts = 393.283356 last_received_ts = 393.282806 last_seq = 607 current_ts = 393.300018 current_received_ts = 393.299469 current_seq = 608 count = 411 seq_step = 1 [390.805867] (kms_flip:7691) DEBUG: Vblank took 74us [390.822373] (kms_flip:7691) DEBUG: name = flip last_ts = 393.300018 last_received_ts = 393.299469 last_seq = 608 current_ts = 393.316711 current_received_ts = 393.316071 current_seq = 609 count = 412 seq_step = 1 [390.822447] (kms_flip:7691) DEBUG: Vblank took 69us [390.839048] (kms_flip:7691) DEBUG: name = flip last_ts = 393.316711 last_received_ts = 393.316071 last_seq = 609 current_ts = 393.333374 current_received_ts = 393.332764 current_seq = 610 count = 413 seq_step = 1 [390.839126] (kms_flip:7691) DEBUG: Vblank took 73us [390.855766] (kms_flip:7691) DEBUG: name = flip last_ts = 393.333374 last_received_ts = 393.332764 last_seq = 610 current_ts = 393.350037 current_received_ts = 393.349487 current_seq = 611 count = 414 seq_step = 1 [390.855845] (kms_flip:7691) DEBUG: Vblank took 73us [390.872364] (kms_flip:7691) DEBUG: name = flip last_ts = 393.350037 last_received_ts = 393.349487 last_seq = 611 current_ts = 393.366699 current_received_ts = 393.366089 current_seq = 612 count = 415 seq_step = 1 [390.872411] (kms_flip:7691) DEBUG: Vblank took 42us [390.888905] (kms_flip:7691) DEBUG: name = flip last_ts = 393.366699 last_received_ts = 393.366089 last_seq = 612 current_ts = 393.383392 current_received_ts = 393.382629 current_seq = 613 count = 416 seq_step = 1 [390.888977] (kms_flip:7691) DEBUG: Vblank took 67us [390.905658] (kms_flip:7691) DEBUG: name = flip last_ts = 393.383392 last_received_ts = 393.382629 last_seq = 613 current_ts = 393.400055 current_received_ts = 393.399384 current_seq = 614 count = 417 seq_step = 1 [390.905735] (kms_flip:7691) DEBUG: Vblank took 71us [390.922396] (kms_flip:7691) DEBUG: name = flip last_ts = 393.400055 last_received_ts = 393.399384 last_seq = 614 current_ts = 393.416718 current_received_ts = 393.416138 current_seq = 615 count = 418 seq_step = 1 [390.922475] (kms_flip:7691) DEBUG: Vblank took 72us [390.939027] (kms_flip:7691) DEBUG: name = flip last_ts = 393.416718 last_received_ts = 393.416138 last_seq = 615 current_ts = 393.433411 current_received_ts = 393.432770 current_seq = 616 count = 419 seq_step = 1 [390.939102] (kms_flip:7691) DEBUG: Vblank took 69us [390.955702] (kms_flip:7691) DEBUG: name = flip last_ts = 393.433411 last_received_ts = 393.432770 last_seq = 616 current_ts = 393.450073 current_received_ts = 393.449463 current_seq = 617 count = 420 seq_step = 1 [390.955774] (kms_flip:7691) DEBUG: Vblank took 65us [390.972352] (kms_flip:7691) DEBUG: name = flip last_ts = 393.450073 last_received_ts = 393.449463 last_seq = 617 current_ts = 393.466736 current_received_ts = 393.466125 current_seq = 618 count = 421 seq_step = 1 [390.972402] (kms_flip:7691) DEBUG: Vblank took 44us [390.989111] (kms_flip:7691) DEBUG: name = flip last_ts = 393.466736 last_received_ts = 393.466125 last_seq = 618 current_ts = 393.483398 current_received_ts = 393.482880 current_seq = 619 count = 422 seq_step = 1 [390.989186] (kms_flip:7691) DEBUG: Vblank took 69us [391.005718] (kms_flip:7691) DEBUG: name = flip last_ts = 393.483398 last_received_ts = 393.482880 last_seq = 619 current_ts = 393.500092 current_received_ts = 393.499512 current_seq = 620 count = 423 seq_step = 1 [391.005792] (kms_flip:7691) DEBUG: Vblank took 66us [391.022243] (kms_flip:7691) DEBUG: name = flip last_ts = 393.500092 last_received_ts = 393.499512 last_seq = 620 current_ts = 393.516754 current_received_ts = 393.516022 current_seq = 621 count = 424 seq_step = 1 [391.022323] (kms_flip:7691) DEBUG: Vblank took 75us [391.038927] (kms_flip:7691) DEBUG: name = flip last_ts = 393.516754 last_received_ts = 393.516022 last_seq = 621 current_ts = 393.533417 current_received_ts = 393.532715 current_seq = 622 count = 425 seq_step = 1 [391.039006] (kms_flip:7691) DEBUG: Vblank took 73us [391.055653] (kms_flip:7691) DEBUG: name = flip last_ts = 393.533417 last_received_ts = 393.532715 last_seq = 622 current_ts = 393.550110 current_received_ts = 393.549469 current_seq = 623 count = 426 seq_step = 1 [391.055726] (kms_flip:7691) DEBUG: Vblank took 67us [391.072389] (kms_flip:7691) DEBUG: name = flip last_ts = 393.550110 last_received_ts = 393.549469 last_seq = 623 current_ts = 393.566772 current_received_ts = 393.566193 current_seq = 624 count = 427 seq_step = 1 [391.072467] (kms_flip:7691) DEBUG: Vblank took 72us [391.089063] (kms_flip:7691) DEBUG: name = flip last_ts = 393.566772 last_received_ts = 393.566193 last_seq = 624 current_ts = 393.583435 current_received_ts = 393.582886 current_seq = 625 count = 428 seq_step = 1 [391.089137] (kms_flip:7691) DEBUG: Vblank took 68us [391.105699] (kms_flip:7691) DEBUG: name = flip last_ts = 393.583435 last_received_ts = 393.582886 last_seq = 625 current_ts = 393.600098 current_received_ts = 393.599518 current_seq = 626 count = 429 seq_step = 1 [391.105778] (kms_flip:7691) DEBUG: Vblank took 73us [391.122326] (kms_flip:7691) DEBUG: name = flip last_ts = 393.600098 last_received_ts = 393.599518 last_seq = 626 current_ts = 393.616791 current_received_ts = 393.616150 current_seq = 627 count = 430 seq_step = 1 [391.122375] (kms_flip:7691) DEBUG: Vblank took 42us [391.139051] (kms_flip:7691) DEBUG: name = flip last_ts = 393.616791 last_received_ts = 393.616150 last_seq = 627 current_ts = 393.633453 current_received_ts = 393.632904 current_seq = 628 count = 431 seq_step = 1 [391.139131] (kms_flip:7691) DEBUG: Vblank took 73us [391.155686] (kms_flip:7691) DEBUG: name = flip last_ts = 393.633453 last_received_ts = 393.632904 last_seq = 628 current_ts = 393.650116 current_received_ts = 393.649536 current_seq = 629 count = 432 seq_step = 1 [391.155765] (kms_flip:7691) DEBUG: Vblank took 73us [391.172345] (kms_flip:7691) DEBUG: name = flip last_ts = 393.650116 last_received_ts = 393.649536 last_seq = 629 current_ts = 393.666809 current_received_ts = 393.666199 current_seq = 630 count = 433 seq_step = 1 [391.172417] (kms_flip:7691) DEBUG: Vblank took 66us [391.189040] (kms_flip:7691) DEBUG: name = flip last_ts = 393.666809 last_received_ts = 393.666199 last_seq = 630 current_ts = 393.683472 current_received_ts = 393.682892 current_seq = 631 count = 434 seq_step = 1 [391.189176] (kms_flip:7691) DEBUG: Vblank took 130us [391.205727] (kms_flip:7691) DEBUG: name = flip last_ts = 393.683472 last_received_ts = 393.682892 last_seq = 631 current_ts = 393.700134 current_received_ts = 393.699585 current_seq = 632 count = 435 seq_step = 1 [391.205806] (kms_flip:7691) DEBUG: Vblank took 74us [391.222343] (kms_flip:7691) DEBUG: name = flip last_ts = 393.700134 last_received_ts = 393.699585 last_seq = 632 current_ts = 393.716797 current_received_ts = 393.716217 current_seq = 633 count = 436 seq_step = 1 [391.222421] (kms_flip:7691) DEBUG: Vblank took 72us [391.239057] (kms_flip:7691) DEBUG: name = flip last_ts = 393.716797 last_received_ts = 393.716217 last_seq = 633 current_ts = 393.733490 current_received_ts = 393.732941 current_seq = 634 count = 437 seq_step = 1 [391.239148] (kms_flip:7691) DEBUG: Vblank took 85us [391.255598] (kms_flip:7691) DEBUG: name = flip last_ts = 393.733490 last_received_ts = 393.732941 last_seq = 634 current_ts = 393.750153 current_received_ts = 393.749481 current_seq = 635 count = 438 seq_step = 1 [391.255670] (kms_flip:7691) DEBUG: Vblank took 65us [391.272337] (kms_flip:7691) DEBUG: name = flip last_ts = 393.750153 last_received_ts = 393.749481 last_seq = 635 current_ts = 393.766815 current_received_ts = 393.766235 current_seq = 636 count = 439 seq_step = 1 [391.272416] (kms_flip:7691) DEBUG: Vblank took 71us [391.289019] (kms_flip:7691) DEBUG: name = flip last_ts = 393.766815 last_received_ts = 393.766235 last_seq = 636 current_ts = 393.783508 current_received_ts = 393.782928 current_seq = 637 count = 440 seq_step = 1 [391.289110] (kms_flip:7691) DEBUG: Vblank took 85us [391.305673] (kms_flip:7691) DEBUG: name = flip last_ts = 393.783508 last_received_ts = 393.782928 last_seq = 637 current_ts = 393.800171 current_received_ts = 393.799591 current_seq = 638 count = 441 seq_step = 1 [391.305751] (kms_flip:7691) DEBUG: Vblank took 73us [391.322288] (kms_flip:7691) DEBUG: name = flip last_ts = 393.800171 last_received_ts = 393.799591 last_seq = 638 current_ts = 393.816833 current_received_ts = 393.816223 current_seq = 639 count = 442 seq_step = 1 [391.322366] (kms_flip:7691) DEBUG: Vblank took 72us [391.339022] (kms_flip:7691) DEBUG: name = flip last_ts = 393.816833 last_received_ts = 393.816223 last_seq = 639 current_ts = 393.833527 current_received_ts = 393.832947 current_seq = 640 count = 443 seq_step = 1 [391.339129] (kms_flip:7691) DEBUG: Vblank took 101us [391.355600] (kms_flip:7691) DEBUG: name = flip last_ts = 393.833527 last_received_ts = 393.832947 last_seq = 640 current_ts = 393.850189 current_received_ts = 393.849548 current_seq = 641 count = 444 seq_step = 1 [391.355677] (kms_flip:7691) DEBUG: Vblank took 72us [391.372358] (kms_flip:7691) DEBUG: name = flip last_ts = 393.850189 last_received_ts = 393.849548 last_seq = 641 current_ts = 393.866852 current_received_ts = 393.866302 current_seq = 642 count = 445 seq_step = 1 [391.372435] (kms_flip:7691) DEBUG: Vblank took 71us [391.388971] (kms_flip:7691) DEBUG: name = flip last_ts = 393.866852 last_received_ts = 393.866302 last_seq = 642 current_ts = 393.883514 current_received_ts = 393.882935 current_seq = 643 count = 446 seq_step = 1 [391.390115] (kms_flip:7691) DEBUG: Vblank took 1128us [391.390127] (kms_flip:7691) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [391.390256] (kms_flip:7691) CRITICAL: Failed assertion: end - start < 500 [391.390332] (kms_flip:7691) CRITICAL: Last errno: 4, Interrupted system call [391.417646] (kms_flip:7691) igt_core-INFO: Stack trace: [391.433270] (kms_flip:7691) igt_core-INFO: #0 ../lib/igt_core.c:2074 __igt_fail_assert() [391.434314] (kms_flip:7691) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [391.434365] (kms_flip:7691) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [391.434406] (kms_flip:7691) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() [391.434428] (kms_flip:7691) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [391.491696] (kms_flip:7691) igt_core-INFO: #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main() [391.491761] (kms_flip:7691) igt_core-INFO: #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34() [391.492045] (kms_flip:7691) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (8.769s)
Dmesg	<6> [459.135148] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [459.138761] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430] <7> [459.141359] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [459.146735] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [459.147076] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [459.147330] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [459.204283] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [459.204373] 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> [459.204508] 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> [459.204624] 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> [459.204755] 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> [459.204867] 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> [459.204985] 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> [459.205091] 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> [459.205192] 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> [459.205290] 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> [459.205388] 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> [459.205483] 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> [459.205578] 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> [459.205676] 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> [459.205788] 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> [459.205901] 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> [459.206001] 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> [459.206091] 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> [459.206181] 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> [459.206269] 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> [459.206361] 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> [459.206442] 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> [459.206520] 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> [459.206597] 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> [459.206692] 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> [459.206792] 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> [459.206891] 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> [459.206982] 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> [459.207063] 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> [459.207144] 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> [459.207225] 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> [459.207305] 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> [459.207385] 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> [459.207465] 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> [459.207545] 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> [459.207622] 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> [459.207716] 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> [459.207811] 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> [459.207905] 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> [459.207989] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [459.208064] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [459.208188] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [459.208252] 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> [459.208341] 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> [459.208412] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [459.208511] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [459.208599] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [459.208704] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [459.208859] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [459.208964] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [459.209051] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [459.209137] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [459.209224] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [459.209308] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [459.209391] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [459.209534] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [459.209630] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [459.209878] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [459.209977] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [459.416726] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [459.417361] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [459.428936] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [459.429356] 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> [459.429381] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [459.429814] 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> [459.429885] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [459.481580] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [459.482038] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [459.485569] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [459.485948] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [459.486152] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [459.487489] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [459.487585] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [459.488128] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [459.488794] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [459.489209] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [459.489633] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [459.489999] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [459.490339] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [459.490711] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [459.491043] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [459.491419] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [459.491842] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [459.492198] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [459.492508] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [459.492875] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [459.493183] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [459.493570] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [459.493996] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [459.494291] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [459.494597] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [459.495086] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [459.495511] 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> [459.496038] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [459.496438] 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> [459.496980] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [459.497331] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [459.498250] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [459.498669] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [459.498965] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [459.499025] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [459.499232] 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> [459.499667] 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> [459.500000] 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> [459.500339] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [459.500691] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [459.501032] 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> [459.501302] 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> [459.501567] 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> [459.501901] 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> [459.502199] 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> [459.502432] 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> [459.502673] 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> [459.502929] 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> [459.503145] 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> [459.503381] 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> [459.503598] 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> [459.503790] 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> [459.503973] 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> [459.504149] 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> [459.504323] 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> [459.504488] 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> [459.504687] 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> [459.504856] 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> [459.505010] 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> [459.505158] 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> [459.505320] 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> [459.505482] 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> [459.505632] 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> [459.505767] 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> [459.505921] 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> [459.506074] 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> [459.506212] 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> [459.506349] 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> [459.506468] 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> [459.506601] 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> [459.506714] 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> [459.506822] 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> [459.506930] 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> [459.507044] 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> [459.507154] 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> [459.507255] 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> [459.507354] 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> [459.507449] 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> [459.507555] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [459.507692] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [459.507784] 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> [459.507907] 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> [459.508005] 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> [459.508086] 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> [459.508156] 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> [459.508222] 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> [459.508291] 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> [459.508381] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [459.508492] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [459.508612] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [459.508718] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [459.508820] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [459.508905] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [459.508990] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [459.509088] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [459.509175] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [459.509264] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [459.509360] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [459.509438] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [459.509526] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [459.509633] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [459.509746] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [459.509861] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [459.509965] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [459.510068] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [459.510156] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [459.510238] 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> [459.510320] 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> [459.510401] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [459.510478] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [459.510628] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [459.510730] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [459.510839] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [459.510930] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [459.511012] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [459.511095] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [459.511175] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [459.511254] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [459.511334] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [459.511413] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [459.511491] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [459.511592] 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> [459.511684] 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> [459.511766] 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> [459.511853] 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> [459.511957] 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> [459.512061] 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> [459.512157] 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> [459.512237] 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> [459.512315] 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> [459.512393] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [459.512470] 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> [459.512562] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [459.512657] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [459.512749] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [459.512841] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [459.512925] 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> [459.513007] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [459.513085] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [459.513162] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [459.513237] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [459.513313] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [459.513388] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [459.513464] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [459.513548] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [459.513643] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [459.513733] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [459.513825] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [459.513907] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [459.513997] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [459.514087] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [459.514179] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [459.514266] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [459.514343] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [459.514419] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [459.514490] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [459.514586] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [459.514680] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [459.514776] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:430] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [459.514867] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [459.514944] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [459.515021] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [459.515097] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [459.515174] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [459.515250] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [459.515325] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [459.515657] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [459.515834] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [459.516010] 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> [459.516141] 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> [459.516252] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [459.516359] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [459.516445] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [459.516524] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [459.516614] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [459.516705] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [459.516801] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [459.516884] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [459.516958] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [459.517030] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [459.517099] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [459.517169] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [459.517238] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [459.517302] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [459.517362] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [459.517443] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [459.517605] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [459.517692] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [459.517819] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [459.518571] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [459.518731] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [459.519223] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [459.519311] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [459.519392] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [459.519486] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [459.521044] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [459.521121] 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> [459.992446] 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> [460.043461] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [460.043927] 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> [460.044388] 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> [460.080110] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [460.080621] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [460.081093] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [460.081876] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [460.256908] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [460.257404] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [460.257793] 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> [460.259941] 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> [460.261479] 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> [460.262298] 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> [460.263467] 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> [460.264860] 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> [460.265983] 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> [460.266432] 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> [460.267978] 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> [460.268410] 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> [460.269298] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [460.269784] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [460.270141] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [460.270569] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [460.303343] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [460.305144] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [460.305708] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <7> [462.831203] 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> [462.831885] 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> [467.786055] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [467.787016] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [467.787756] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [467.905680] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

8.77 seconds

Hostname

shard-lnl-2

Igt-Version

IGT-Version: 2.4-g3cb6109b3 (x86_64) (Linux: 7.1.0-rc4-lgci-xe-xe-5101-7d39df83e93eba14a-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:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (8.769s)

Err

Starting dynamic subtest: B-eDP1
[391.390127] (kms_flip:7691) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[391.390256] (kms_flip:7691) CRITICAL: Failed assertion: end - start < 500
[391.390332] (kms_flip:7691) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
[389.372723] (kms_flip:7691) DEBUG: Vblank took 66us
[389.389301] (kms_flip:7691) DEBUG: name = flip
last_ts = 391.866302
last_received_ts = 391.865723
last_seq = 522
current_ts = 391.882965
current_received_ts = 391.882385
current_seq = 523
count = 326
seq_step = 1
[389.389374] (kms_flip:7691) DEBUG: Vblank took 67us
[389.405969] (kms_flip:7691) DEBUG: name = flip
last_ts = 391.882965
last_received_ts = 391.882385
last_seq = 523
current_ts = 391.899628
current_received_ts = 391.899048
current_seq = 524
count = 327
seq_step = 1
[389.406017] (kms_flip:7691) DEBUG: Vblank took 43us
[389.422582] (kms_flip:7691) DEBUG: name = flip
last_ts = 391.899628
last_received_ts = 391.899048
last_seq = 524
current_ts = 391.916321
current_received_ts = 391.915680
current_seq = 525
count = 328
seq_step = 1
[389.422676] (kms_flip:7691) DEBUG: Vblank took 68us
[389.439254] (kms_flip:7691) DEBUG: name = flip
last_ts = 391.916321
last_received_ts = 391.915680
last_seq = 525
current_ts = 391.932983
current_received_ts = 391.932343
current_seq = 526
count = 329
seq_step = 1
[389.439327] (kms_flip:7691) DEBUG: Vblank took 68us
[389.455959] (kms_flip:7691) DEBUG: name = flip
last_ts = 391.932983
last_received_ts = 391.932343
last_seq = 526
current_ts = 391.949646
current_received_ts = 391.949066
current_seq = 527
count = 330
seq_step = 1
[389.456032] (kms_flip:7691) DEBUG: Vblank took 68us
[389.472540] (kms_flip:7691) DEBUG: name = flip
last_ts = 391.949646
last_received_ts = 391.949066
last_seq = 527
current_ts = 391.966339
current_received_ts = 391.965668
current_seq = 528
count = 331
seq_step = 1
[389.472607] (kms_flip:7691) DEBUG: Vblank took 62us
[389.489195] (kms_flip:7691) DEBUG: name = flip
last_ts = 391.966339
last_received_ts = 391.965668
last_seq = 528
current_ts = 391.983002
current_received_ts = 391.982330
current_seq = 529
count = 332
seq_step = 1
[389.489275] (kms_flip:7691) DEBUG: Vblank took 75us
[389.505915] (kms_flip:7691) DEBUG: name = flip
last_ts = 391.983002
last_received_ts = 391.982330
last_seq = 529
current_ts = 391.999664
current_received_ts = 391.999054
current_seq = 530
count = 333
seq_step = 1
[389.505963] (kms_flip:7691) DEBUG: Vblank took 43us
[389.522514] (kms_flip:7691) DEBUG: name = flip
last_ts = 391.999664
last_received_ts = 391.999054
last_seq = 530
current_ts = 392.016357
current_received_ts = 392.015656
current_seq = 531
count = 334
seq_step = 1
[389.522564] (kms_flip:7691) DEBUG: Vblank took 45us
[389.539287] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.016357
last_received_ts = 392.015656
last_seq = 531
current_ts = 392.033020
current_received_ts = 392.032440
current_seq = 532
count = 335
seq_step = 1
[389.539354] (kms_flip:7691) DEBUG: Vblank took 61us
[389.555904] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.033020
last_received_ts = 392.032440
last_seq = 532
current_ts = 392.049683
current_received_ts = 392.049042
current_seq = 533
count = 336
seq_step = 1
[389.555977] (kms_flip:7691) DEBUG: Vblank took 69us
[389.572681] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.049683
last_received_ts = 392.049042
last_seq = 533
current_ts = 392.066345
current_received_ts = 392.065826
current_seq = 534
count = 337
seq_step = 1
[389.572757] (kms_flip:7691) DEBUG: Vblank took 72us
[389.589229] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.066345
last_received_ts = 392.065826
last_seq = 534
current_ts = 392.083038
current_received_ts = 392.082397
current_seq = 535
count = 338
seq_step = 1
[389.589301] (kms_flip:7691) DEBUG: Vblank took 67us
[389.605933] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.083038
last_received_ts = 392.082397
last_seq = 535
current_ts = 392.099701
current_received_ts = 392.099091
current_seq = 536
count = 339
seq_step = 1
[389.606011] (kms_flip:7691) DEBUG: Vblank took 73us
[389.622508] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.099701
last_received_ts = 392.099091
last_seq = 536
current_ts = 392.116364
current_received_ts = 392.115692
current_seq = 537
count = 340
seq_step = 1
[389.622578] (kms_flip:7691) DEBUG: Vblank took 65us
[389.639202] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.116364
last_received_ts = 392.115692
last_seq = 537
current_ts = 392.133026
current_received_ts = 392.132385
current_seq = 538
count = 341
seq_step = 1
[389.639280] (kms_flip:7691) DEBUG: Vblank took 72us
[389.655933] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.133026
last_received_ts = 392.132385
last_seq = 538
current_ts = 392.149719
current_received_ts = 392.149139
current_seq = 539
count = 342
seq_step = 1
[389.656012] (kms_flip:7691) DEBUG: Vblank took 73us
[389.672564] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.149719
last_received_ts = 392.149139
last_seq = 539
current_ts = 392.166382
current_received_ts = 392.165771
current_seq = 540
count = 343
seq_step = 1
[389.672639] (kms_flip:7691) DEBUG: Vblank took 69us
[389.689284] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.166382
last_received_ts = 392.165771
last_seq = 540
current_ts = 392.183044
current_received_ts = 392.182495
current_seq = 541
count = 344
seq_step = 1
[389.689353] (kms_flip:7691) DEBUG: Vblank took 64us
[389.705929] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.183044
last_received_ts = 392.182495
last_seq = 541
current_ts = 392.199738
current_received_ts = 392.199158
current_seq = 542
count = 345
seq_step = 1
[389.706011] (kms_flip:7691) DEBUG: Vblank took 76us
[389.722523] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.199738
last_received_ts = 392.199158
last_seq = 542
current_ts = 392.216400
current_received_ts = 392.215759
current_seq = 543
count = 346
seq_step = 1
[389.722594] (kms_flip:7691) DEBUG: Vblank took 66us
[389.739257] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.216400
last_received_ts = 392.215759
last_seq = 543
current_ts = 392.233063
current_received_ts = 392.232483
current_seq = 544
count = 347
seq_step = 1
[389.739340] (kms_flip:7691) DEBUG: Vblank took 77us
[389.755932] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.233063
last_received_ts = 392.232483
last_seq = 544
current_ts = 392.249725
current_received_ts = 392.249176
current_seq = 545
count = 348
seq_step = 1
[389.756008] (kms_flip:7691) DEBUG: Vblank took 70us
[389.772423] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.249725
last_received_ts = 392.249176
last_seq = 545
current_ts = 392.266418
current_received_ts = 392.265656
current_seq = 546
count = 349
seq_step = 1
[389.772497] (kms_flip:7691) DEBUG: Vblank took 69us
[389.789198] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.266418
last_received_ts = 392.265656
last_seq = 546
current_ts = 392.283081
current_received_ts = 392.282440
current_seq = 547
count = 350
seq_step = 1
[389.789280] (kms_flip:7691) DEBUG: Vblank took 76us
[389.805797] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.283081
last_received_ts = 392.282440
last_seq = 547
current_ts = 392.299744
current_received_ts = 392.299042
current_seq = 548
count = 351
seq_step = 1
[389.805875] (kms_flip:7691) DEBUG: Vblank took 72us
[389.822574] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.299744
last_received_ts = 392.299042
last_seq = 548
current_ts = 392.316437
current_received_ts = 392.315826
current_seq = 549
count = 352
seq_step = 1
[389.822647] (kms_flip:7691) DEBUG: Vblank took 67us
[389.839192] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.316437
last_received_ts = 392.315826
last_seq = 549
current_ts = 392.333099
current_received_ts = 392.332458
current_seq = 550
count = 353
seq_step = 1
[389.839263] (kms_flip:7691) DEBUG: Vblank took 66us
[389.855890] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.333099
last_received_ts = 392.332458
last_seq = 550
current_ts = 392.349762
current_received_ts = 392.349182
current_seq = 551
count = 354
seq_step = 1
[389.855938] (kms_flip:7691) DEBUG: Vblank took 43us
[389.872519] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.349762
last_received_ts = 392.349182
last_seq = 551
current_ts = 392.366425
current_received_ts = 392.365814
current_seq = 552
count = 355
seq_step = 1
[389.872599] (kms_flip:7691) DEBUG: Vblank took 74us
[389.889152] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.366425
last_received_ts = 392.365814
last_seq = 552
current_ts = 392.383118
current_received_ts = 392.382446
current_seq = 553
count = 356
seq_step = 1
[389.889232] (kms_flip:7691) DEBUG: Vblank took 73us
[389.905923] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.383118
last_received_ts = 392.382446
last_seq = 553
current_ts = 392.399780
current_received_ts = 392.399231
current_seq = 554
count = 357
seq_step = 1
[389.905970] (kms_flip:7691) DEBUG: Vblank took 42us
[389.922528] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.399780
last_received_ts = 392.399231
last_seq = 554
current_ts = 392.416443
current_received_ts = 392.415833
current_seq = 555
count = 358
seq_step = 1
[389.922627] (kms_flip:7691) DEBUG: Vblank took 95us
[389.939207] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.416443
last_received_ts = 392.415833
last_seq = 555
current_ts = 392.433136
current_received_ts = 392.432495
current_seq = 556
count = 359
seq_step = 1
[389.939324] (kms_flip:7691) DEBUG: Vblank took 99us
[389.955886] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.433136
last_received_ts = 392.432495
last_seq = 556
current_ts = 392.449799
current_received_ts = 392.449219
current_seq = 557
count = 360
seq_step = 1
[389.955974] (kms_flip:7691) DEBUG: Vblank took 79us
[389.972434] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.449799
last_received_ts = 392.449219
last_seq = 557
current_ts = 392.466461
current_received_ts = 392.465759
current_seq = 558
count = 361
seq_step = 1
[389.972513] (kms_flip:7691) DEBUG: Vblank took 71us
[389.989148] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.466461
last_received_ts = 392.465759
last_seq = 558
current_ts = 392.483124
current_received_ts = 392.482483
current_seq = 559
count = 362
seq_step = 1
[389.989223] (kms_flip:7691) DEBUG: Vblank took 69us
[390.005813] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.483124
last_received_ts = 392.482483
last_seq = 559
current_ts = 392.499817
current_received_ts = 392.499146
current_seq = 560
count = 363
seq_step = 1
[390.005888] (kms_flip:7691) DEBUG: Vblank took 68us
[390.022583] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.499817
last_received_ts = 392.499146
last_seq = 560
current_ts = 392.516479
current_received_ts = 392.515930
current_seq = 561
count = 364
seq_step = 1
[390.022693] (kms_flip:7691) DEBUG: Vblank took 104us
[390.039154] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.516479
last_received_ts = 392.515930
last_seq = 561
current_ts = 392.533142
current_received_ts = 392.532501
current_seq = 562
count = 365
seq_step = 1
[390.039227] (kms_flip:7691) DEBUG: Vblank took 67us
[390.055872] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.533142
last_received_ts = 392.532501
last_seq = 562
current_ts = 392.549835
current_received_ts = 392.549225
current_seq = 563
count = 366
seq_step = 1
[390.055952] (kms_flip:7691) DEBUG: Vblank took 73us
[390.072462] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.549835
last_received_ts = 392.549225
last_seq = 563
current_ts = 392.566498
current_received_ts = 392.565826
current_seq = 564
count = 367
seq_step = 1
[390.072533] (kms_flip:7691) DEBUG: Vblank took 65us
[390.089193] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.566498
last_received_ts = 392.565826
last_seq = 564
current_ts = 392.583160
current_received_ts = 392.582581
current_seq = 565
count = 368
seq_step = 1
[390.089265] (kms_flip:7691) DEBUG: Vblank took 66us
[390.105906] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.583160
last_received_ts = 392.582581
last_seq = 565
current_ts = 392.599823
current_received_ts = 392.599304
current_seq = 566
count = 369
seq_step = 1
[390.105986] (kms_flip:7691) DEBUG: Vblank took 72us
[390.122525] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.599823
last_received_ts = 392.599304
last_seq = 566
current_ts = 392.616516
current_received_ts = 392.615936
current_seq = 567
count = 370
seq_step = 1
[390.122573] (kms_flip:7691) DEBUG: Vblank took 43us
[390.139060] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.616516
last_received_ts = 392.615936
last_seq = 567
current_ts = 392.633179
current_received_ts = 392.632477
current_seq = 568
count = 371
seq_step = 1
[390.139130] (kms_flip:7691) DEBUG: Vblank took 64us
[390.155887] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.633179
last_received_ts = 392.632477
last_seq = 568
current_ts = 392.649841
current_received_ts = 392.649292
current_seq = 569
count = 372
seq_step = 1
[390.155934] (kms_flip:7691) DEBUG: Vblank took 42us
[390.172429] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.649841
last_received_ts = 392.649292
last_seq = 569
current_ts = 392.666504
current_received_ts = 392.665833
current_seq = 570
count = 373
seq_step = 1
[390.172490] (kms_flip:7691) DEBUG: Vblank took 53us
[390.189211] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.666504
last_received_ts = 392.665833
last_seq = 570
current_ts = 392.683197
current_received_ts = 392.682617
current_seq = 571
count = 374
seq_step = 1
[390.189297] (kms_flip:7691) DEBUG: Vblank took 77us
[390.205884] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.683197
last_received_ts = 392.682617
last_seq = 571
current_ts = 392.699860
current_received_ts = 392.699310
current_seq = 572
count = 375
seq_step = 1
[390.205966] (kms_flip:7691) DEBUG: Vblank took 75us
[390.222425] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.699860
last_received_ts = 392.699310
last_seq = 572
current_ts = 392.716522
current_received_ts = 392.715851
current_seq = 573
count = 376
seq_step = 1
[390.222497] (kms_flip:7691) DEBUG: Vblank took 66us
[390.239170] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.716522
last_received_ts = 392.715851
last_seq = 573
current_ts = 392.733215
current_received_ts = 392.732605
current_seq = 574
count = 377
seq_step = 1
[390.239248] (kms_flip:7691) DEBUG: Vblank took 72us
[390.255761] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.733215
last_received_ts = 392.732605
last_seq = 574
current_ts = 392.749878
current_received_ts = 392.749207
current_seq = 575
count = 378
seq_step = 1
[390.255831] (kms_flip:7691) DEBUG: Vblank took 65us
[390.272516] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.749878
last_received_ts = 392.749207
last_seq = 575
current_ts = 392.766541
current_received_ts = 392.765991
current_seq = 576
count = 379
seq_step = 1
[390.272618] (kms_flip:7691) DEBUG: Vblank took 96us
[390.289157] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.766541
last_received_ts = 392.765991
last_seq = 576
current_ts = 392.783234
current_received_ts = 392.782623
current_seq = 577
count = 380
seq_step = 1
[390.289236] (kms_flip:7691) DEBUG: Vblank took 74us
[390.305841] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.783234
last_received_ts = 392.782623
last_seq = 577
current_ts = 392.799896
current_received_ts = 392.799316
current_seq = 578
count = 381
seq_step = 1
[390.305888] (kms_flip:7691) DEBUG: Vblank took 42us
[390.322350] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.799896
last_received_ts = 392.799316
last_seq = 578
current_ts = 392.816559
current_received_ts = 392.815826
current_seq = 579
count = 382
seq_step = 1
[390.322423] (kms_flip:7691) DEBUG: Vblank took 67us
[390.339135] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.816559
last_received_ts = 392.815826
last_seq = 579
current_ts = 392.833221
current_received_ts = 392.832642
current_seq = 580
count = 383
seq_step = 1
[390.339204] (kms_flip:7691) DEBUG: Vblank took 63us
[390.355836] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.833221
last_received_ts = 392.832642
last_seq = 580
current_ts = 392.849915
current_received_ts = 392.849335
current_seq = 581
count = 384
seq_step = 1
[390.355903] (kms_flip:7691) DEBUG: Vblank took 62us
[390.372416] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.849915
last_received_ts = 392.849335
last_seq = 581
current_ts = 392.866577
current_received_ts = 392.865936
current_seq = 582
count = 385
seq_step = 1
[390.372516] (kms_flip:7691) DEBUG: Vblank took 93us
[390.389085] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.866577
last_received_ts = 392.865936
last_seq = 582
current_ts = 392.883240
current_received_ts = 392.882599
current_seq = 583
count = 386
seq_step = 1
[390.389166] (kms_flip:7691) DEBUG: Vblank took 76us
[390.405846] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.883240
last_received_ts = 392.882599
last_seq = 583
current_ts = 392.899933
current_received_ts = 392.899353
current_seq = 584
count = 387
seq_step = 1
[390.405897] (kms_flip:7691) DEBUG: Vblank took 44us
[390.422324] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.899933
last_received_ts = 392.899353
last_seq = 584
current_ts = 392.916595
current_received_ts = 392.915863
current_seq = 585
count = 388
seq_step = 1
[390.422395] (kms_flip:7691) DEBUG: Vblank took 66us
[390.439090] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.916595
last_received_ts = 392.915863
last_seq = 585
current_ts = 392.933258
current_received_ts = 392.932617
current_seq = 586
count = 389
seq_step = 1
[390.439155] (kms_flip:7691) DEBUG: Vblank took 60us
[390.455824] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.933258
last_received_ts = 392.932617
last_seq = 586
current_ts = 392.949921
current_received_ts = 392.949371
current_seq = 587
count = 390
seq_step = 1
[390.455890] (kms_flip:7691) DEBUG: Vblank took 62us
[390.472411] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.949921
last_received_ts = 392.949371
last_seq = 587
current_ts = 392.966614
current_received_ts = 392.965973
current_seq = 588
count = 391
seq_step = 1
[390.472491] (kms_flip:7691) DEBUG: Vblank took 75us
[390.489060] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.966614
last_received_ts = 392.965973
last_seq = 588
current_ts = 392.983276
current_received_ts = 392.982605
current_seq = 589
count = 392
seq_step = 1
[390.489134] (kms_flip:7691) DEBUG: Vblank took 67us
[390.505661] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.983276
last_received_ts = 392.982605
last_seq = 589
current_ts = 392.999939
current_received_ts = 392.999237
current_seq = 590
count = 393
seq_step = 1
[390.505738] (kms_flip:7691) DEBUG: Vblank took 72us
[390.522506] (kms_flip:7691) DEBUG: name = flip
last_ts = 392.999939
last_received_ts = 392.999237
last_seq = 590
current_ts = 393.016632
current_received_ts = 393.016083
current_seq = 591
count = 394
seq_step = 1
[390.522571] (kms_flip:7691) DEBUG: Vblank took 60us
[390.539163] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.016632
last_received_ts = 393.016083
last_seq = 591
current_ts = 393.033295
current_received_ts = 393.032745
current_seq = 592
count = 395
seq_step = 1
[390.539233] (kms_flip:7691) DEBUG: Vblank took 65us
[390.555741] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.033295
last_received_ts = 393.032745
last_seq = 592
current_ts = 393.049957
current_received_ts = 393.049316
current_seq = 593
count = 396
seq_step = 1
[390.555821] (kms_flip:7691) DEBUG: Vblank took 75us
[390.572430] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.049957
last_received_ts = 393.049316
last_seq = 593
current_ts = 393.066620
current_received_ts = 393.066010
current_seq = 594
count = 397
seq_step = 1
[390.572501] (kms_flip:7691) DEBUG: Vblank took 66us
[390.588969] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.066620
last_received_ts = 393.066010
last_seq = 594
current_ts = 393.083313
current_received_ts = 393.082581
current_seq = 595
count = 398
seq_step = 1
[390.589036] (kms_flip:7691) DEBUG: Vblank took 62us
[390.605829] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.083313
last_received_ts = 393.082581
last_seq = 595
current_ts = 393.099976
current_received_ts = 393.099426
current_seq = 596
count = 399
seq_step = 1
[390.605902] (kms_flip:7691) DEBUG: Vblank took 66us
[390.622324] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.099976
last_received_ts = 393.099426
last_seq = 596
current_ts = 393.116638
current_received_ts = 393.115936
current_seq = 597
count = 400
seq_step = 1
[390.622424] (kms_flip:7691) DEBUG: Vblank took 94us
[390.639031] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.116638
last_received_ts = 393.115936
last_seq = 597
current_ts = 393.133331
current_received_ts = 393.132660
current_seq = 598
count = 401
seq_step = 1
[390.639110] (kms_flip:7691) DEBUG: Vblank took 73us
[390.655740] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.133331
last_received_ts = 393.132660
last_seq = 598
current_ts = 393.149994
current_received_ts = 393.149384
current_seq = 599
count = 402
seq_step = 1
[390.655818] (kms_flip:7691) DEBUG: Vblank took 73us
[390.672441] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.149994
last_received_ts = 393.149384
last_seq = 599
current_ts = 393.166656
current_received_ts = 393.166077
current_seq = 600
count = 403
seq_step = 1
[390.672511] (kms_flip:7691) DEBUG: Vblank took 65us
[390.689145] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.166656
last_received_ts = 393.166077
last_seq = 600
current_ts = 393.183319
current_received_ts = 393.182800
current_seq = 601
count = 404
seq_step = 1
[390.689244] (kms_flip:7691) DEBUG: Vblank took 93us
[390.705779] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.183319
last_received_ts = 393.182800
last_seq = 601
current_ts = 393.200012
current_received_ts = 393.199432
current_seq = 602
count = 405
seq_step = 1
[390.705857] (kms_flip:7691) DEBUG: Vblank took 73us
[390.722308] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.200012
last_received_ts = 393.199432
last_seq = 602
current_ts = 393.216675
current_received_ts = 393.215973
current_seq = 603
count = 406
seq_step = 1
[390.722412] (kms_flip:7691) DEBUG: Vblank took 98us
[390.739032] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.216675
last_received_ts = 393.215973
last_seq = 603
current_ts = 393.233337
current_received_ts = 393.232697
current_seq = 604
count = 407
seq_step = 1
[390.739104] (kms_flip:7691) DEBUG: Vblank took 66us
[390.755701] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.233337
last_received_ts = 393.232697
last_seq = 604
current_ts = 393.250031
current_received_ts = 393.249359
current_seq = 605
count = 408
seq_step = 1
[390.755773] (kms_flip:7691) DEBUG: Vblank took 66us
[390.772420] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.250031
last_received_ts = 393.249359
last_seq = 605
current_ts = 393.266693
current_received_ts = 393.266113
current_seq = 606
count = 409
seq_step = 1
[390.772497] (kms_flip:7691) DEBUG: Vblank took 72us
[390.789133] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.266693
last_received_ts = 393.266113
last_seq = 606
current_ts = 393.283356
current_received_ts = 393.282806
current_seq = 607
count = 410
seq_step = 1
[390.789207] (kms_flip:7691) DEBUG: Vblank took 68us
[390.805787] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.283356
last_received_ts = 393.282806
last_seq = 607
current_ts = 393.300018
current_received_ts = 393.299469
current_seq = 608
count = 411
seq_step = 1
[390.805867] (kms_flip:7691) DEBUG: Vblank took 74us
[390.822373] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.300018
last_received_ts = 393.299469
last_seq = 608
current_ts = 393.316711
current_received_ts = 393.316071
current_seq = 609
count = 412
seq_step = 1
[390.822447] (kms_flip:7691) DEBUG: Vblank took 69us
[390.839048] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.316711
last_received_ts = 393.316071
last_seq = 609
current_ts = 393.333374
current_received_ts = 393.332764
current_seq = 610
count = 413
seq_step = 1
[390.839126] (kms_flip:7691) DEBUG: Vblank took 73us
[390.855766] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.333374
last_received_ts = 393.332764
last_seq = 610
current_ts = 393.350037
current_received_ts = 393.349487
current_seq = 611
count = 414
seq_step = 1
[390.855845] (kms_flip:7691) DEBUG: Vblank took 73us
[390.872364] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.350037
last_received_ts = 393.349487
last_seq = 611
current_ts = 393.366699
current_received_ts = 393.366089
current_seq = 612
count = 415
seq_step = 1
[390.872411] (kms_flip:7691) DEBUG: Vblank took 42us
[390.888905] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.366699
last_received_ts = 393.366089
last_seq = 612
current_ts = 393.383392
current_received_ts = 393.382629
current_seq = 613
count = 416
seq_step = 1
[390.888977] (kms_flip:7691) DEBUG: Vblank took 67us
[390.905658] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.383392
last_received_ts = 393.382629
last_seq = 613
current_ts = 393.400055
current_received_ts = 393.399384
current_seq = 614
count = 417
seq_step = 1
[390.905735] (kms_flip:7691) DEBUG: Vblank took 71us
[390.922396] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.400055
last_received_ts = 393.399384
last_seq = 614
current_ts = 393.416718
current_received_ts = 393.416138
current_seq = 615
count = 418
seq_step = 1
[390.922475] (kms_flip:7691) DEBUG: Vblank took 72us
[390.939027] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.416718
last_received_ts = 393.416138
last_seq = 615
current_ts = 393.433411
current_received_ts = 393.432770
current_seq = 616
count = 419
seq_step = 1
[390.939102] (kms_flip:7691) DEBUG: Vblank took 69us
[390.955702] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.433411
last_received_ts = 393.432770
last_seq = 616
current_ts = 393.450073
current_received_ts = 393.449463
current_seq = 617
count = 420
seq_step = 1
[390.955774] (kms_flip:7691) DEBUG: Vblank took 65us
[390.972352] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.450073
last_received_ts = 393.449463
last_seq = 617
current_ts = 393.466736
current_received_ts = 393.466125
current_seq = 618
count = 421
seq_step = 1
[390.972402] (kms_flip:7691) DEBUG: Vblank took 44us
[390.989111] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.466736
last_received_ts = 393.466125
last_seq = 618
current_ts = 393.483398
current_received_ts = 393.482880
current_seq = 619
count = 422
seq_step = 1
[390.989186] (kms_flip:7691) DEBUG: Vblank took 69us
[391.005718] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.483398
last_received_ts = 393.482880
last_seq = 619
current_ts = 393.500092
current_received_ts = 393.499512
current_seq = 620
count = 423
seq_step = 1
[391.005792] (kms_flip:7691) DEBUG: Vblank took 66us
[391.022243] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.500092
last_received_ts = 393.499512
last_seq = 620
current_ts = 393.516754
current_received_ts = 393.516022
current_seq = 621
count = 424
seq_step = 1
[391.022323] (kms_flip:7691) DEBUG: Vblank took 75us
[391.038927] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.516754
last_received_ts = 393.516022
last_seq = 621
current_ts = 393.533417
current_received_ts = 393.532715
current_seq = 622
count = 425
seq_step = 1
[391.039006] (kms_flip:7691) DEBUG: Vblank took 73us
[391.055653] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.533417
last_received_ts = 393.532715
last_seq = 622
current_ts = 393.550110
current_received_ts = 393.549469
current_seq = 623
count = 426
seq_step = 1
[391.055726] (kms_flip:7691) DEBUG: Vblank took 67us
[391.072389] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.550110
last_received_ts = 393.549469
last_seq = 623
current_ts = 393.566772
current_received_ts = 393.566193
current_seq = 624
count = 427
seq_step = 1
[391.072467] (kms_flip:7691) DEBUG: Vblank took 72us
[391.089063] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.566772
last_received_ts = 393.566193
last_seq = 624
current_ts = 393.583435
current_received_ts = 393.582886
current_seq = 625
count = 428
seq_step = 1
[391.089137] (kms_flip:7691) DEBUG: Vblank took 68us
[391.105699] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.583435
last_received_ts = 393.582886
last_seq = 625
current_ts = 393.600098
current_received_ts = 393.599518
current_seq = 626
count = 429
seq_step = 1
[391.105778] (kms_flip:7691) DEBUG: Vblank took 73us
[391.122326] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.600098
last_received_ts = 393.599518
last_seq = 626
current_ts = 393.616791
current_received_ts = 393.616150
current_seq = 627
count = 430
seq_step = 1
[391.122375] (kms_flip:7691) DEBUG: Vblank took 42us
[391.139051] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.616791
last_received_ts = 393.616150
last_seq = 627
current_ts = 393.633453
current_received_ts = 393.632904
current_seq = 628
count = 431
seq_step = 1
[391.139131] (kms_flip:7691) DEBUG: Vblank took 73us
[391.155686] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.633453
last_received_ts = 393.632904
last_seq = 628
current_ts = 393.650116
current_received_ts = 393.649536
current_seq = 629
count = 432
seq_step = 1
[391.155765] (kms_flip:7691) DEBUG: Vblank took 73us
[391.172345] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.650116
last_received_ts = 393.649536
last_seq = 629
current_ts = 393.666809
current_received_ts = 393.666199
current_seq = 630
count = 433
seq_step = 1
[391.172417] (kms_flip:7691) DEBUG: Vblank took 66us
[391.189040] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.666809
last_received_ts = 393.666199
last_seq = 630
current_ts = 393.683472
current_received_ts = 393.682892
current_seq = 631
count = 434
seq_step = 1
[391.189176] (kms_flip:7691) DEBUG: Vblank took 130us
[391.205727] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.683472
last_received_ts = 393.682892
last_seq = 631
current_ts = 393.700134
current_received_ts = 393.699585
current_seq = 632
count = 435
seq_step = 1
[391.205806] (kms_flip:7691) DEBUG: Vblank took 74us
[391.222343] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.700134
last_received_ts = 393.699585
last_seq = 632
current_ts = 393.716797
current_received_ts = 393.716217
current_seq = 633
count = 436
seq_step = 1
[391.222421] (kms_flip:7691) DEBUG: Vblank took 72us
[391.239057] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.716797
last_received_ts = 393.716217
last_seq = 633
current_ts = 393.733490
current_received_ts = 393.732941
current_seq = 634
count = 437
seq_step = 1
[391.239148] (kms_flip:7691) DEBUG: Vblank took 85us
[391.255598] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.733490
last_received_ts = 393.732941
last_seq = 634
current_ts = 393.750153
current_received_ts = 393.749481
current_seq = 635
count = 438
seq_step = 1
[391.255670] (kms_flip:7691) DEBUG: Vblank took 65us
[391.272337] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.750153
last_received_ts = 393.749481
last_seq = 635
current_ts = 393.766815
current_received_ts = 393.766235
current_seq = 636
count = 439
seq_step = 1
[391.272416] (kms_flip:7691) DEBUG: Vblank took 71us
[391.289019] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.766815
last_received_ts = 393.766235
last_seq = 636
current_ts = 393.783508
current_received_ts = 393.782928
current_seq = 637
count = 440
seq_step = 1
[391.289110] (kms_flip:7691) DEBUG: Vblank took 85us
[391.305673] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.783508
last_received_ts = 393.782928
last_seq = 637
current_ts = 393.800171
current_received_ts = 393.799591
current_seq = 638
count = 441
seq_step = 1
[391.305751] (kms_flip:7691) DEBUG: Vblank took 73us
[391.322288] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.800171
last_received_ts = 393.799591
last_seq = 638
current_ts = 393.816833
current_received_ts = 393.816223
current_seq = 639
count = 442
seq_step = 1
[391.322366] (kms_flip:7691) DEBUG: Vblank took 72us
[391.339022] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.816833
last_received_ts = 393.816223
last_seq = 639
current_ts = 393.833527
current_received_ts = 393.832947
current_seq = 640
count = 443
seq_step = 1
[391.339129] (kms_flip:7691) DEBUG: Vblank took 101us
[391.355600] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.833527
last_received_ts = 393.832947
last_seq = 640
current_ts = 393.850189
current_received_ts = 393.849548
current_seq = 641
count = 444
seq_step = 1
[391.355677] (kms_flip:7691) DEBUG: Vblank took 72us
[391.372358] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.850189
last_received_ts = 393.849548
last_seq = 641
current_ts = 393.866852
current_received_ts = 393.866302
current_seq = 642
count = 445
seq_step = 1
[391.372435] (kms_flip:7691) DEBUG: Vblank took 71us
[391.388971] (kms_flip:7691) DEBUG: name = flip
last_ts = 393.866852
last_received_ts = 393.866302
last_seq = 642
current_ts = 393.883514
current_received_ts = 393.882935
current_seq = 643
count = 446
seq_step = 1
[391.390115] (kms_flip:7691) DEBUG: Vblank took 1128us
[391.390127] (kms_flip:7691) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[391.390256] (kms_flip:7691) CRITICAL: Failed assertion: end - start < 500
[391.390332] (kms_flip:7691) CRITICAL: Last errno: 4, Interrupted system call
[391.417646] (kms_flip:7691) igt_core-INFO: Stack trace:
[391.433270] (kms_flip:7691) igt_core-INFO:   #0 ../lib/igt_core.c:2074 __igt_fail_assert()
[391.434314] (kms_flip:7691) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[391.434365] (kms_flip:7691) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[391.434406] (kms_flip:7691) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
[391.434428] (kms_flip:7691) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[391.491696] (kms_flip:7691) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
[391.491761] (kms_flip:7691) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
[391.492045] (kms_flip:7691) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (8.769s)

Dmesg

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

<7> [459.138761] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430]

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

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

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

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

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

<7> [459.204373] 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> [459.204508] 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> [459.204624] 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> [459.204755] 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> [459.204867] 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> [459.204985] 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> [459.205091] 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> [459.205192] 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> [459.205290] 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> [459.205388] 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> [459.205483] 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> [459.205578] 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> [459.205676] 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> [459.205788] 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> [459.205901] 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> [459.206001] 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> [459.206091] 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> [459.206181] 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> [459.206269] 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> [459.206361] 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> [459.206442] 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> [459.206520] 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> [459.206597] 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> [459.206692] 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> [459.206792] 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> [459.206891] 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> [459.206982] 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> [459.207063] 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> [459.207144] 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> [459.207225] 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> [459.207305] 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> [459.207385] 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> [459.207465] 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> [459.207545] 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> [459.207622] 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> [459.207716] 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> [459.207811] 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> [459.207905] 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> [459.207989] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

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

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

<7> [459.208252] 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> [459.208341] 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> [459.208412] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [459.499232] 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> [459.499667] 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> [459.500000] 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> [459.500339] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0

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

<7> [459.501032] 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> [459.501302] 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> [459.501567] 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> [459.501901] 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> [459.502199] 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> [459.502432] 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> [459.502673] 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> [459.502929] 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> [459.503145] 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> [459.503381] 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> [459.503598] 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> [459.503790] 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> [459.503973] 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> [459.504149] 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> [459.504323] 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> [459.504488] 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> [459.504687] 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> [459.504856] 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> [459.505010] 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> [459.505158] 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> [459.505320] 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> [459.505482] 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> [459.505632] 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> [459.505767] 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> [459.505921] 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> [459.506074] 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> [459.506212] 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> [459.506349] 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> [459.506468] 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> [459.506601] 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> [459.506714] 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> [459.506822] 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> [459.506930] 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> [459.507044] 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> [459.507154] 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> [459.507255] 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> [459.507354] 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> [459.507449] 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> [459.507555] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset

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

<7> [459.507784] 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> [459.507907] 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> [459.508005] 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> [459.508086] 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> [459.508156] 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> [459.508222] 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> [459.508291] 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> [459.508381] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [459.510238] 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> [459.510320] 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> [459.510401] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

<7> [459.511592] 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> [459.511684] 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> [459.511766] 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> [459.511853] 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> [459.511957] 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> [459.512061] 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> [459.512157] 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> [459.512237] 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> [459.512315] 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> [459.512393] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [459.521121] 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> [459.992446] 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> [460.043461] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

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

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

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

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

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

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

<7> [460.257793] 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> [460.259941] 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> [460.261479] 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> [460.262298] 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> [460.263467] 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> [460.264860] 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> [460.265983] 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> [460.266432] 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> [460.267978] 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> [460.268410] 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> [460.269298] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B

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

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

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

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

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

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

<7> [462.831203] 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> [462.831885] 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> [467.786055] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

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

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

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

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