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

Detail	Value
Duration	8.42 seconds
Hostname	shard-lnl-5
Igt-Version	IGT-Version: 2.4-g00d5807a3 (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5067-b9819223b7e921730-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 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (8.421s)
Err	Starting dynamic subtest: B-eDP1 [240.707014] (kms_flip:4811) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [240.707086] (kms_flip:4811) CRITICAL: Failed assertion: end - start < 500 [240.707124] (kms_flip:4811) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG [238.689654] (kms_flip:4811) DEBUG: Vblank took 70us [238.706246] (kms_flip:4811) DEBUG: name = flip last_ts = 240.667038 last_received_ts = 240.666351 last_seq = 538 current_ts = 240.683716 current_received_ts = 240.683044 current_seq = 539 count = 306 seq_step = 1 [238.706327] (kms_flip:4811) DEBUG: Vblank took 75us [238.722901] (kms_flip:4811) DEBUG: name = flip last_ts = 240.683716 last_received_ts = 240.683044 last_seq = 539 current_ts = 240.700409 current_received_ts = 240.699722 current_seq = 540 count = 307 seq_step = 1 [238.722977] (kms_flip:4811) DEBUG: Vblank took 69us [238.739599] (kms_flip:4811) DEBUG: name = flip last_ts = 240.700409 last_received_ts = 240.699722 last_seq = 540 current_ts = 240.717087 current_received_ts = 240.716431 current_seq = 541 count = 308 seq_step = 1 [238.739675] (kms_flip:4811) DEBUG: Vblank took 69us [238.756228] (kms_flip:4811) DEBUG: name = flip last_ts = 240.717087 last_received_ts = 240.716431 last_seq = 541 current_ts = 240.733765 current_received_ts = 240.733078 current_seq = 542 count = 309 seq_step = 1 [238.756304] (kms_flip:4811) DEBUG: Vblank took 71us [238.772904] (kms_flip:4811) DEBUG: name = flip last_ts = 240.733765 last_received_ts = 240.733078 last_seq = 542 current_ts = 240.750458 current_received_ts = 240.749786 current_seq = 543 count = 310 seq_step = 1 [238.772982] (kms_flip:4811) DEBUG: Vblank took 70us [238.789565] (kms_flip:4811) DEBUG: name = flip last_ts = 240.750458 last_received_ts = 240.749786 last_seq = 543 current_ts = 240.767136 current_received_ts = 240.766464 current_seq = 544 count = 311 seq_step = 1 [238.789642] (kms_flip:4811) DEBUG: Vblank took 71us [238.806236] (kms_flip:4811) DEBUG: name = flip last_ts = 240.767136 last_received_ts = 240.766464 last_seq = 544 current_ts = 240.783813 current_received_ts = 240.783157 current_seq = 545 count = 312 seq_step = 1 [238.806319] (kms_flip:4811) DEBUG: Vblank took 75us [238.822904] (kms_flip:4811) DEBUG: name = flip last_ts = 240.783813 last_received_ts = 240.783157 last_seq = 545 current_ts = 240.800507 current_received_ts = 240.799835 current_seq = 546 count = 313 seq_step = 1 [238.822989] (kms_flip:4811) DEBUG: Vblank took 78us [238.839558] (kms_flip:4811) DEBUG: name = flip last_ts = 240.800507 last_received_ts = 240.799835 last_seq = 546 current_ts = 240.817184 current_received_ts = 240.816513 current_seq = 547 count = 314 seq_step = 1 [238.839635] (kms_flip:4811) DEBUG: Vblank took 71us [238.856218] (kms_flip:4811) DEBUG: name = flip last_ts = 240.817184 last_received_ts = 240.816513 last_seq = 547 current_ts = 240.833878 current_received_ts = 240.833191 current_seq = 548 count = 315 seq_step = 1 [238.856296] (kms_flip:4811) DEBUG: Vblank took 71us [238.872898] (kms_flip:4811) DEBUG: name = flip last_ts = 240.833878 last_received_ts = 240.833191 last_seq = 548 current_ts = 240.850555 current_received_ts = 240.849899 current_seq = 549 count = 316 seq_step = 1 [238.872975] (kms_flip:4811) DEBUG: Vblank took 71us [238.889551] (kms_flip:4811) DEBUG: name = flip last_ts = 240.850555 last_received_ts = 240.849899 last_seq = 549 current_ts = 240.867249 current_received_ts = 240.866562 current_seq = 550 count = 317 seq_step = 1 [238.889628] (kms_flip:4811) DEBUG: Vblank took 70us [238.906203] (kms_flip:4811) DEBUG: name = flip last_ts = 240.867249 last_received_ts = 240.866562 last_seq = 550 current_ts = 240.883926 current_received_ts = 240.883240 current_seq = 551 count = 318 seq_step = 1 [238.906281] (kms_flip:4811) DEBUG: Vblank took 70us [238.922877] (kms_flip:4811) DEBUG: name = flip last_ts = 240.883926 last_received_ts = 240.883240 last_seq = 551 current_ts = 240.900620 current_received_ts = 240.899933 current_seq = 552 count = 319 seq_step = 1 [238.922970] (kms_flip:4811) DEBUG: Vblank took 86us [238.939534] (kms_flip:4811) DEBUG: name = flip last_ts = 240.900620 last_received_ts = 240.899933 last_seq = 552 current_ts = 240.917297 current_received_ts = 240.916611 current_seq = 553 count = 320 seq_step = 1 [238.939612] (kms_flip:4811) DEBUG: Vblank took 71us [238.956200] (kms_flip:4811) DEBUG: name = flip last_ts = 240.917297 last_received_ts = 240.916611 last_seq = 553 current_ts = 240.933975 current_received_ts = 240.933289 current_seq = 554 count = 321 seq_step = 1 [238.956278] (kms_flip:4811) DEBUG: Vblank took 71us [238.972820] (kms_flip:4811) DEBUG: name = flip last_ts = 240.933975 last_received_ts = 240.933289 last_seq = 554 current_ts = 240.950668 current_received_ts = 240.949936 current_seq = 555 count = 322 seq_step = 1 [238.972926] (kms_flip:4811) DEBUG: Vblank took 100us [238.989569] (kms_flip:4811) DEBUG: name = flip last_ts = 240.950668 last_received_ts = 240.949936 last_seq = 555 current_ts = 240.967346 current_received_ts = 240.966705 current_seq = 556 count = 323 seq_step = 1 [238.989646] (kms_flip:4811) DEBUG: Vblank took 70us [239.006193] (kms_flip:4811) DEBUG: name = flip last_ts = 240.967346 last_received_ts = 240.966705 last_seq = 556 current_ts = 240.984039 current_received_ts = 240.983353 current_seq = 557 count = 324 seq_step = 1 [239.006306] (kms_flip:4811) DEBUG: Vblank took 105us [239.023126] (kms_flip:4811) DEBUG: name = flip last_ts = 240.984039 last_received_ts = 240.983353 last_seq = 557 current_ts = 241.000717 current_received_ts = 241.000259 current_seq = 558 count = 325 seq_step = 1 [239.023291] (kms_flip:4811) DEBUG: Vblank took 134us [239.039545] (kms_flip:4811) DEBUG: name = flip last_ts = 241.000717 last_received_ts = 241.000259 last_seq = 558 current_ts = 241.017395 current_received_ts = 241.016739 current_seq = 559 count = 326 seq_step = 1 [239.039642] (kms_flip:4811) DEBUG: Vblank took 86us [239.056277] (kms_flip:4811) DEBUG: name = flip last_ts = 241.017395 last_received_ts = 241.016739 last_seq = 559 current_ts = 241.034088 current_received_ts = 241.033463 current_seq = 560 count = 327 seq_step = 1 [239.056383] (kms_flip:4811) DEBUG: Vblank took 83us [239.072788] (kms_flip:4811) DEBUG: name = flip last_ts = 241.034088 last_received_ts = 241.033463 last_seq = 560 current_ts = 241.050766 current_received_ts = 241.050018 current_seq = 561 count = 328 seq_step = 1 [239.072903] (kms_flip:4811) DEBUG: Vblank took 99us [239.089451] (kms_flip:4811) DEBUG: name = flip last_ts = 241.050766 last_received_ts = 241.050018 last_seq = 561 current_ts = 241.067444 current_received_ts = 241.066711 current_seq = 562 count = 329 seq_step = 1 [239.089521] (kms_flip:4811) DEBUG: Vblank took 65us [239.106139] (kms_flip:4811) DEBUG: name = flip last_ts = 241.067444 last_received_ts = 241.066711 last_seq = 562 current_ts = 241.084137 current_received_ts = 241.083420 current_seq = 563 count = 330 seq_step = 1 [239.106199] (kms_flip:4811) DEBUG: Vblank took 56us [239.122818] (kms_flip:4811) DEBUG: name = flip last_ts = 241.084137 last_received_ts = 241.083420 last_seq = 563 current_ts = 241.100815 current_received_ts = 241.100113 current_seq = 564 count = 331 seq_step = 1 [239.122875] (kms_flip:4811) DEBUG: Vblank took 54us [239.139506] (kms_flip:4811) DEBUG: name = flip last_ts = 241.100815 last_received_ts = 241.100113 last_seq = 564 current_ts = 241.117508 current_received_ts = 241.116821 current_seq = 565 count = 332 seq_step = 1 [239.139556] (kms_flip:4811) DEBUG: Vblank took 48us [239.156177] (kms_flip:4811) DEBUG: name = flip last_ts = 241.117508 last_received_ts = 241.116821 last_seq = 565 current_ts = 241.134186 current_received_ts = 241.133514 current_seq = 566 count = 333 seq_step = 1 [239.156233] (kms_flip:4811) DEBUG: Vblank took 53us [239.172821] (kms_flip:4811) DEBUG: name = flip last_ts = 241.134186 last_received_ts = 241.133514 last_seq = 566 current_ts = 241.150879 current_received_ts = 241.150177 current_seq = 567 count = 334 seq_step = 1 [239.172877] (kms_flip:4811) DEBUG: Vblank took 53us [239.189479] (kms_flip:4811) DEBUG: name = flip last_ts = 241.150879 last_received_ts = 241.150177 last_seq = 567 current_ts = 241.167557 current_received_ts = 241.166855 current_seq = 568 count = 335 seq_step = 1 [239.189532] (kms_flip:4811) DEBUG: Vblank took 49us [239.206181] (kms_flip:4811) DEBUG: name = flip last_ts = 241.167557 last_received_ts = 241.166855 last_seq = 568 current_ts = 241.184235 current_received_ts = 241.183578 current_seq = 569 count = 336 seq_step = 1 [239.206230] (kms_flip:4811) DEBUG: Vblank took 47us [239.222805] (kms_flip:4811) DEBUG: name = flip last_ts = 241.184235 last_received_ts = 241.183578 last_seq = 569 current_ts = 241.200928 current_received_ts = 241.200226 current_seq = 570 count = 337 seq_step = 1 [239.222852] (kms_flip:4811) DEBUG: Vblank took 45us [239.239502] (kms_flip:4811) DEBUG: name = flip last_ts = 241.200928 last_received_ts = 241.200226 last_seq = 570 current_ts = 241.217606 current_received_ts = 241.216934 current_seq = 571 count = 338 seq_step = 1 [239.239553] (kms_flip:4811) DEBUG: Vblank took 48us [239.256185] (kms_flip:4811) DEBUG: name = flip last_ts = 241.217606 last_received_ts = 241.216934 last_seq = 571 current_ts = 241.234283 current_received_ts = 241.233643 current_seq = 572 count = 339 seq_step = 1 [239.256252] (kms_flip:4811) DEBUG: Vblank took 64us [239.272801] (kms_flip:4811) DEBUG: name = flip last_ts = 241.234283 last_received_ts = 241.233643 last_seq = 572 current_ts = 241.250977 current_received_ts = 241.250275 current_seq = 573 count = 340 seq_step = 1 [239.272856] (kms_flip:4811) DEBUG: Vblank took 52us [239.289466] (kms_flip:4811) DEBUG: name = flip last_ts = 241.250977 last_received_ts = 241.250275 last_seq = 573 current_ts = 241.267654 current_received_ts = 241.266953 current_seq = 574 count = 341 seq_step = 1 [239.289516] (kms_flip:4811) DEBUG: Vblank took 48us [239.306149] (kms_flip:4811) DEBUG: name = flip last_ts = 241.267654 last_received_ts = 241.266953 last_seq = 574 current_ts = 241.284332 current_received_ts = 241.283661 current_seq = 575 count = 342 seq_step = 1 [239.306203] (kms_flip:4811) DEBUG: Vblank took 50us [239.322767] (kms_flip:4811) DEBUG: name = flip last_ts = 241.284332 last_received_ts = 241.283661 last_seq = 575 current_ts = 241.301010 current_received_ts = 241.300293 current_seq = 576 count = 343 seq_step = 1 [239.322819] (kms_flip:4811) DEBUG: Vblank took 49us [239.339490] (kms_flip:4811) DEBUG: name = flip last_ts = 241.301010 last_received_ts = 241.300293 last_seq = 576 current_ts = 241.317703 current_received_ts = 241.317032 current_seq = 577 count = 344 seq_step = 1 [239.339535] (kms_flip:4811) DEBUG: Vblank took 40us [239.356115] (kms_flip:4811) DEBUG: name = flip last_ts = 241.317703 last_received_ts = 241.317032 last_seq = 577 current_ts = 241.334381 current_received_ts = 241.333679 current_seq = 578 count = 345 seq_step = 1 [239.356234] (kms_flip:4811) DEBUG: Vblank took 116us [239.372796] (kms_flip:4811) DEBUG: name = flip last_ts = 241.334381 last_received_ts = 241.333679 last_seq = 578 current_ts = 241.351059 current_received_ts = 241.350388 current_seq = 579 count = 346 seq_step = 1 [239.372848] (kms_flip:4811) DEBUG: Vblank took 49us [239.389443] (kms_flip:4811) DEBUG: name = flip last_ts = 241.351059 last_received_ts = 241.350388 last_seq = 579 current_ts = 241.367752 current_received_ts = 241.367050 current_seq = 580 count = 347 seq_step = 1 [239.389510] (kms_flip:4811) DEBUG: Vblank took 50us [239.406124] (kms_flip:4811) DEBUG: name = flip last_ts = 241.367752 last_received_ts = 241.367050 last_seq = 580 current_ts = 241.384430 current_received_ts = 241.383743 current_seq = 581 count = 348 seq_step = 1 [239.406178] (kms_flip:4811) DEBUG: Vblank took 47us [239.422797] (kms_flip:4811) DEBUG: name = flip last_ts = 241.384430 last_received_ts = 241.383743 last_seq = 581 current_ts = 241.401108 current_received_ts = 241.400436 current_seq = 582 count = 349 seq_step = 1 [239.422853] (kms_flip:4811) DEBUG: Vblank took 52us [239.439449] (kms_flip:4811) DEBUG: name = flip last_ts = 241.401108 last_received_ts = 241.400436 last_seq = 582 current_ts = 241.417786 current_received_ts = 241.417114 current_seq = 583 count = 350 seq_step = 1 [239.439508] (kms_flip:4811) DEBUG: Vblank took 55us [239.456117] (kms_flip:4811) DEBUG: name = flip last_ts = 241.417786 last_received_ts = 241.417114 last_seq = 583 current_ts = 241.434479 current_received_ts = 241.433792 current_seq = 584 count = 351 seq_step = 1 [239.456172] (kms_flip:4811) DEBUG: Vblank took 52us [239.472766] (kms_flip:4811) DEBUG: name = flip last_ts = 241.434479 last_received_ts = 241.433792 last_seq = 584 current_ts = 241.451157 current_received_ts = 241.450455 current_seq = 585 count = 352 seq_step = 1 [239.472825] (kms_flip:4811) DEBUG: Vblank took 55us [239.489451] (kms_flip:4811) DEBUG: name = flip last_ts = 241.451157 last_received_ts = 241.450455 last_seq = 585 current_ts = 241.467834 current_received_ts = 241.467163 current_seq = 586 count = 353 seq_step = 1 [239.489507] (kms_flip:4811) DEBUG: Vblank took 53us [239.506121] (kms_flip:4811) DEBUG: name = flip last_ts = 241.467834 last_received_ts = 241.467163 last_seq = 586 current_ts = 241.484528 current_received_ts = 241.483856 current_seq = 587 count = 354 seq_step = 1 [239.506172] (kms_flip:4811) DEBUG: Vblank took 48us [239.522755] (kms_flip:4811) DEBUG: name = flip last_ts = 241.484528 last_received_ts = 241.483856 last_seq = 587 current_ts = 241.501205 current_received_ts = 241.500504 current_seq = 588 count = 355 seq_step = 1 [239.522808] (kms_flip:4811) DEBUG: Vblank took 50us [239.539411] (kms_flip:4811) DEBUG: name = flip last_ts = 241.501205 last_received_ts = 241.500504 last_seq = 588 current_ts = 241.517883 current_received_ts = 241.517181 current_seq = 589 count = 356 seq_step = 1 [239.539464] (kms_flip:4811) DEBUG: Vblank took 51us [239.556059] (kms_flip:4811) DEBUG: name = flip last_ts = 241.517883 last_received_ts = 241.517181 last_seq = 589 current_ts = 241.534576 current_received_ts = 241.533844 current_seq = 590 count = 357 seq_step = 1 [239.556116] (kms_flip:4811) DEBUG: Vblank took 54us [239.572765] (kms_flip:4811) DEBUG: name = flip last_ts = 241.534576 last_received_ts = 241.533844 last_seq = 590 current_ts = 241.551254 current_received_ts = 241.550568 current_seq = 591 count = 358 seq_step = 1 [239.572829] (kms_flip:4811) DEBUG: Vblank took 61us [239.589413] (kms_flip:4811) DEBUG: name = flip last_ts = 241.551254 last_received_ts = 241.550568 last_seq = 591 current_ts = 241.567932 current_received_ts = 241.567245 current_seq = 592 count = 359 seq_step = 1 [239.589460] (kms_flip:4811) DEBUG: Vblank took 45us [239.606094] (kms_flip:4811) DEBUG: name = flip last_ts = 241.567932 last_received_ts = 241.567245 last_seq = 592 current_ts = 241.584625 current_received_ts = 241.583939 current_seq = 593 count = 360 seq_step = 1 [239.606161] (kms_flip:4811) DEBUG: Vblank took 65us [239.622759] (kms_flip:4811) DEBUG: name = flip last_ts = 241.584625 last_received_ts = 241.583939 last_seq = 593 current_ts = 241.601303 current_received_ts = 241.600616 current_seq = 594 count = 361 seq_step = 1 [239.622821] (kms_flip:4811) DEBUG: Vblank took 58us [239.639372] (kms_flip:4811) DEBUG: name = flip last_ts = 241.601303 last_received_ts = 241.600616 last_seq = 594 current_ts = 241.617981 current_received_ts = 241.617249 current_seq = 595 count = 362 seq_step = 1 [239.639408] (kms_flip:4811) DEBUG: Vblank took 34us [239.656039] (kms_flip:4811) DEBUG: name = flip last_ts = 241.617981 last_received_ts = 241.617249 last_seq = 595 current_ts = 241.634674 current_received_ts = 241.633942 current_seq = 596 count = 363 seq_step = 1 [239.656124] (kms_flip:4811) DEBUG: Vblank took 83us [239.672784] (kms_flip:4811) DEBUG: name = flip last_ts = 241.634674 last_received_ts = 241.633942 last_seq = 596 current_ts = 241.651352 current_received_ts = 241.650681 current_seq = 597 count = 364 seq_step = 1 [239.672845] (kms_flip:4811) DEBUG: Vblank took 57us [239.689393] (kms_flip:4811) DEBUG: name = flip last_ts = 241.651352 last_received_ts = 241.650681 last_seq = 597 current_ts = 241.668030 current_received_ts = 241.667328 current_seq = 598 count = 365 seq_step = 1 [239.689465] (kms_flip:4811) DEBUG: Vblank took 69us [239.706094] (kms_flip:4811) DEBUG: name = flip last_ts = 241.668030 last_received_ts = 241.667328 last_seq = 598 current_ts = 241.684723 current_received_ts = 241.684052 current_seq = 599 count = 366 seq_step = 1 [239.706143] (kms_flip:4811) DEBUG: Vblank took 47us [239.722755] (kms_flip:4811) DEBUG: name = flip last_ts = 241.684723 last_received_ts = 241.684052 last_seq = 599 current_ts = 241.701401 current_received_ts = 241.700729 current_seq = 600 count = 367 seq_step = 1 [239.722809] (kms_flip:4811) DEBUG: Vblank took 51us [239.739403] (kms_flip:4811) DEBUG: name = flip last_ts = 241.701401 last_received_ts = 241.700729 last_seq = 600 current_ts = 241.718079 current_received_ts = 241.717392 current_seq = 601 count = 368 seq_step = 1 [239.739449] (kms_flip:4811) DEBUG: Vblank took 45us [239.756048] (kms_flip:4811) DEBUG: name = flip last_ts = 241.718079 last_received_ts = 241.717392 last_seq = 601 current_ts = 241.734772 current_received_ts = 241.734055 current_seq = 602 count = 369 seq_step = 1 [239.756099] (kms_flip:4811) DEBUG: Vblank took 49us [239.772726] (kms_flip:4811) DEBUG: name = flip last_ts = 241.734772 last_received_ts = 241.734055 last_seq = 602 current_ts = 241.751450 current_received_ts = 241.750763 current_seq = 603 count = 370 seq_step = 1 [239.772777] (kms_flip:4811) DEBUG: Vblank took 49us [239.789412] (kms_flip:4811) DEBUG: name = flip last_ts = 241.751450 last_received_ts = 241.750763 last_seq = 603 current_ts = 241.768127 current_received_ts = 241.767456 current_seq = 604 count = 371 seq_step = 1 [239.789476] (kms_flip:4811) DEBUG: Vblank took 61us [239.806050] (kms_flip:4811) DEBUG: name = flip last_ts = 241.768127 last_received_ts = 241.767456 last_seq = 604 current_ts = 241.784805 current_received_ts = 241.784119 current_seq = 605 count = 372 seq_step = 1 [239.806106] (kms_flip:4811) DEBUG: Vblank took 53us [239.822717] (kms_flip:4811) DEBUG: name = flip last_ts = 241.784805 last_received_ts = 241.784119 last_seq = 605 current_ts = 241.801498 current_received_ts = 241.800797 current_seq = 606 count = 373 seq_step = 1 [239.822765] (kms_flip:4811) DEBUG: Vblank took 45us [239.839406] (kms_flip:4811) DEBUG: name = flip last_ts = 241.801498 last_received_ts = 241.800797 last_seq = 606 current_ts = 241.818176 current_received_ts = 241.817505 current_seq = 607 count = 374 seq_step = 1 [239.839458] (kms_flip:4811) DEBUG: Vblank took 49us [239.856059] (kms_flip:4811) DEBUG: name = flip last_ts = 241.818176 last_received_ts = 241.817505 last_seq = 607 current_ts = 241.834854 current_received_ts = 241.834183 current_seq = 608 count = 375 seq_step = 1 [239.856121] (kms_flip:4811) DEBUG: Vblank took 59us [239.872729] (kms_flip:4811) DEBUG: name = flip last_ts = 241.834854 last_received_ts = 241.834183 last_seq = 608 current_ts = 241.851532 current_received_ts = 241.850876 current_seq = 609 count = 376 seq_step = 1 [239.872785] (kms_flip:4811) DEBUG: Vblank took 53us [239.889392] (kms_flip:4811) DEBUG: name = flip last_ts = 241.851532 last_received_ts = 241.850876 last_seq = 609 current_ts = 241.868225 current_received_ts = 241.867554 current_seq = 610 count = 377 seq_step = 1 [239.889446] (kms_flip:4811) DEBUG: Vblank took 52us [239.906089] (kms_flip:4811) DEBUG: name = flip last_ts = 241.868225 last_received_ts = 241.867554 last_seq = 610 current_ts = 241.884903 current_received_ts = 241.884262 current_seq = 611 count = 378 seq_step = 1 [239.906156] (kms_flip:4811) DEBUG: Vblank took 63us [239.922725] (kms_flip:4811) DEBUG: name = flip last_ts = 241.884903 last_received_ts = 241.884262 last_seq = 611 current_ts = 241.901581 current_received_ts = 241.900925 current_seq = 612 count = 379 seq_step = 1 [239.922778] (kms_flip:4811) DEBUG: Vblank took 51us [239.939384] (kms_flip:4811) DEBUG: name = flip last_ts = 241.901581 last_received_ts = 241.900925 last_seq = 612 current_ts = 241.918274 current_received_ts = 241.917603 current_seq = 613 count = 380 seq_step = 1 [239.939434] (kms_flip:4811) DEBUG: Vblank took 48us [239.956075] (kms_flip:4811) DEBUG: name = flip last_ts = 241.918274 last_received_ts = 241.917603 last_seq = 613 current_ts = 241.934952 current_received_ts = 241.934311 current_seq = 614 count = 381 seq_step = 1 [239.956142] (kms_flip:4811) DEBUG: Vblank took 64us [239.972699] (kms_flip:4811) DEBUG: name = flip last_ts = 241.934952 last_received_ts = 241.934311 last_seq = 614 current_ts = 241.951630 current_received_ts = 241.950958 current_seq = 615 count = 382 seq_step = 1 [239.972756] (kms_flip:4811) DEBUG: Vblank took 54us [239.989374] (kms_flip:4811) DEBUG: name = flip last_ts = 241.951630 last_received_ts = 241.950958 last_seq = 615 current_ts = 241.968323 current_received_ts = 241.967651 current_seq = 616 count = 383 seq_step = 1 [239.989427] (kms_flip:4811) DEBUG: Vblank took 50us [240.006020] (kms_flip:4811) DEBUG: name = flip last_ts = 241.968323 last_received_ts = 241.967651 last_seq = 616 current_ts = 241.985001 current_received_ts = 241.984314 current_seq = 617 count = 384 seq_step = 1 [240.006073] (kms_flip:4811) DEBUG: Vblank took 51us [240.022725] (kms_flip:4811) DEBUG: name = flip last_ts = 241.985001 last_received_ts = 241.984314 last_seq = 617 current_ts = 242.001678 current_received_ts = 242.001038 current_seq = 618 count = 385 seq_step = 1 [240.022786] (kms_flip:4811) DEBUG: Vblank took 57us [240.039370] (kms_flip:4811) DEBUG: name = flip last_ts = 242.001678 last_received_ts = 242.001038 last_seq = 618 current_ts = 242.018372 current_received_ts = 242.017700 current_seq = 619 count = 386 seq_step = 1 [240.039424] (kms_flip:4811) DEBUG: Vblank took 51us [240.056042] (kms_flip:4811) DEBUG: name = flip last_ts = 242.018372 last_received_ts = 242.017700 last_seq = 619 current_ts = 242.035049 current_received_ts = 242.034393 current_seq = 620 count = 387 seq_step = 1 [240.056089] (kms_flip:4811) DEBUG: Vblank took 45us [240.072700] (kms_flip:4811) DEBUG: name = flip last_ts = 242.035049 last_received_ts = 242.034393 last_seq = 620 current_ts = 242.051727 current_received_ts = 242.051071 current_seq = 621 count = 388 seq_step = 1 [240.072768] (kms_flip:4811) DEBUG: Vblank took 64us [240.089375] (kms_flip:4811) DEBUG: name = flip last_ts = 242.051727 last_received_ts = 242.051071 last_seq = 621 current_ts = 242.068420 current_received_ts = 242.067749 current_seq = 622 count = 389 seq_step = 1 [240.089441] (kms_flip:4811) DEBUG: Vblank took 62us [240.106011] (kms_flip:4811) DEBUG: name = flip last_ts = 242.068420 last_received_ts = 242.067749 last_seq = 622 current_ts = 242.085098 current_received_ts = 242.084412 current_seq = 623 count = 390 seq_step = 1 [240.106059] (kms_flip:4811) DEBUG: Vblank took 46us [240.122663] (kms_flip:4811) DEBUG: name = flip last_ts = 242.085098 last_received_ts = 242.084412 last_seq = 623 current_ts = 242.101791 current_received_ts = 242.101089 current_seq = 624 count = 391 seq_step = 1 [240.122711] (kms_flip:4811) DEBUG: Vblank took 47us [240.139349] (kms_flip:4811) DEBUG: name = flip last_ts = 242.101791 last_received_ts = 242.101089 last_seq = 624 current_ts = 242.118469 current_received_ts = 242.117783 current_seq = 625 count = 392 seq_step = 1 [240.139404] (kms_flip:4811) DEBUG: Vblank took 52us [240.156004] (kms_flip:4811) DEBUG: name = flip last_ts = 242.118469 last_received_ts = 242.117783 last_seq = 625 current_ts = 242.135147 current_received_ts = 242.134460 current_seq = 626 count = 393 seq_step = 1 [240.156052] (kms_flip:4811) DEBUG: Vblank took 46us [240.172648] (kms_flip:4811) DEBUG: name = flip last_ts = 242.135147 last_received_ts = 242.134460 last_seq = 626 current_ts = 242.151825 current_received_ts = 242.151123 current_seq = 627 count = 394 seq_step = 1 [240.172700] (kms_flip:4811) DEBUG: Vblank took 49us [240.189346] (kms_flip:4811) DEBUG: name = flip last_ts = 242.151825 last_received_ts = 242.151123 last_seq = 627 current_ts = 242.168518 current_received_ts = 242.167831 current_seq = 628 count = 395 seq_step = 1 [240.189402] (kms_flip:4811) DEBUG: Vblank took 54us [240.206009] (kms_flip:4811) DEBUG: name = flip last_ts = 242.168518 last_received_ts = 242.167831 last_seq = 628 current_ts = 242.185196 current_received_ts = 242.184525 current_seq = 629 count = 396 seq_step = 1 [240.206063] (kms_flip:4811) DEBUG: Vblank took 51us [240.222632] (kms_flip:4811) DEBUG: name = flip last_ts = 242.185196 last_received_ts = 242.184525 last_seq = 629 current_ts = 242.201874 current_received_ts = 242.201157 current_seq = 630 count = 397 seq_step = 1 [240.222686] (kms_flip:4811) DEBUG: Vblank took 51us [240.239311] (kms_flip:4811) DEBUG: name = flip last_ts = 242.201874 last_received_ts = 242.201157 last_seq = 630 current_ts = 242.218552 current_received_ts = 242.217850 current_seq = 631 count = 398 seq_step = 1 [240.239365] (kms_flip:4811) DEBUG: Vblank took 52us [240.255977] (kms_flip:4811) DEBUG: name = flip last_ts = 242.218552 last_received_ts = 242.217850 last_seq = 631 current_ts = 242.235229 current_received_ts = 242.234543 current_seq = 632 count = 399 seq_step = 1 [240.256035] (kms_flip:4811) DEBUG: Vblank took 55us [240.272663] (kms_flip:4811) DEBUG: name = flip last_ts = 242.235229 last_received_ts = 242.234543 last_seq = 632 current_ts = 242.251923 current_received_ts = 242.251236 current_seq = 633 count = 400 seq_step = 1 [240.272720] (kms_flip:4811) DEBUG: Vblank took 54us [240.289303] (kms_flip:4811) DEBUG: name = flip last_ts = 242.251923 last_received_ts = 242.251236 last_seq = 633 current_ts = 242.268600 current_received_ts = 242.267899 current_seq = 634 count = 401 seq_step = 1 [240.289346] (kms_flip:4811) DEBUG: Vblank took 41us [240.305975] (kms_flip:4811) DEBUG: name = flip last_ts = 242.268600 last_received_ts = 242.267899 last_seq = 634 current_ts = 242.285278 current_received_ts = 242.284592 current_seq = 635 count = 402 seq_step = 1 [240.306031] (kms_flip:4811) DEBUG: Vblank took 53us [240.322634] (kms_flip:4811) DEBUG: name = flip last_ts = 242.285278 last_received_ts = 242.284592 last_seq = 635 current_ts = 242.301971 current_received_ts = 242.301270 current_seq = 636 count = 403 seq_step = 1 [240.322704] (kms_flip:4811) DEBUG: Vblank took 66us [240.339309] (kms_flip:4811) DEBUG: name = flip last_ts = 242.301971 last_received_ts = 242.301270 last_seq = 636 current_ts = 242.318634 current_received_ts = 242.317963 current_seq = 637 count = 404 seq_step = 1 [240.339387] (kms_flip:4811) DEBUG: Vblank took 76us [240.355990] (kms_flip:4811) DEBUG: name = flip last_ts = 242.318634 last_received_ts = 242.317963 last_seq = 637 current_ts = 242.335327 current_received_ts = 242.334656 current_seq = 638 count = 405 seq_step = 1 [240.356049] (kms_flip:4811) DEBUG: Vblank took 57us [240.372645] (kms_flip:4811) DEBUG: name = flip last_ts = 242.335327 last_received_ts = 242.334656 last_seq = 638 current_ts = 242.352005 current_received_ts = 242.351334 current_seq = 639 count = 406 seq_step = 1 [240.372715] (kms_flip:4811) DEBUG: Vblank took 66us [240.389306] (kms_flip:4811) DEBUG: name = flip last_ts = 242.352005 last_received_ts = 242.351334 last_seq = 639 current_ts = 242.368683 current_received_ts = 242.368011 current_seq = 640 count = 407 seq_step = 1 [240.389362] (kms_flip:4811) DEBUG: Vblank took 52us [240.405997] (kms_flip:4811) DEBUG: name = flip last_ts = 242.368683 last_received_ts = 242.368011 last_seq = 640 current_ts = 242.385376 current_received_ts = 242.384720 current_seq = 641 count = 408 seq_step = 1 [240.406053] (kms_flip:4811) DEBUG: Vblank took 53us [240.422628] (kms_flip:4811) DEBUG: name = flip last_ts = 242.385376 last_received_ts = 242.384720 last_seq = 641 current_ts = 242.402054 current_received_ts = 242.401367 current_seq = 642 count = 409 seq_step = 1 [240.422687] (kms_flip:4811) DEBUG: Vblank took 55us [240.439309] (kms_flip:4811) DEBUG: name = flip last_ts = 242.402054 last_received_ts = 242.401367 last_seq = 642 current_ts = 242.418732 current_received_ts = 242.418060 current_seq = 643 count = 410 seq_step = 1 [240.439367] (kms_flip:4811) DEBUG: Vblank took 56us [240.455888] (kms_flip:4811) DEBUG: name = flip last_ts = 242.418732 last_received_ts = 242.418060 last_seq = 643 current_ts = 242.435410 current_received_ts = 242.434662 current_seq = 644 count = 411 seq_step = 1 [240.455942] (kms_flip:4811) DEBUG: Vblank took 51us [240.472631] (kms_flip:4811) DEBUG: name = flip last_ts = 242.435410 last_received_ts = 242.434662 last_seq = 644 current_ts = 242.452087 current_received_ts = 242.451416 current_seq = 645 count = 412 seq_step = 1 [240.472681] (kms_flip:4811) DEBUG: Vblank took 47us [240.489266] (kms_flip:4811) DEBUG: name = flip last_ts = 242.452087 last_received_ts = 242.451416 last_seq = 645 current_ts = 242.468781 current_received_ts = 242.468079 current_seq = 646 count = 413 seq_step = 1 [240.489319] (kms_flip:4811) DEBUG: Vblank took 51us [240.505879] (kms_flip:4811) DEBUG: name = flip last_ts = 242.468781 last_received_ts = 242.468079 last_seq = 646 current_ts = 242.485458 current_received_ts = 242.484695 current_seq = 647 count = 414 seq_step = 1 [240.505929] (kms_flip:4811) DEBUG: Vblank took 47us [240.522601] (kms_flip:4811) DEBUG: name = flip last_ts = 242.485458 last_received_ts = 242.484695 last_seq = 647 current_ts = 242.502136 current_received_ts = 242.501434 current_seq = 648 count = 415 seq_step = 1 [240.522662] (kms_flip:4811) DEBUG: Vblank took 57us [240.539262] (kms_flip:4811) DEBUG: name = flip last_ts = 242.502136 last_received_ts = 242.501434 last_seq = 648 current_ts = 242.518814 current_received_ts = 242.518127 current_seq = 649 count = 416 seq_step = 1 [240.539317] (kms_flip:4811) DEBUG: Vblank took 53us [240.555934] (kms_flip:4811) DEBUG: name = flip last_ts = 242.518814 last_received_ts = 242.518127 last_seq = 649 current_ts = 242.535492 current_received_ts = 242.534805 current_seq = 650 count = 417 seq_step = 1 [240.555984] (kms_flip:4811) DEBUG: Vblank took 47us [240.572614] (kms_flip:4811) DEBUG: name = flip last_ts = 242.535492 last_received_ts = 242.534805 last_seq = 650 current_ts = 242.552185 current_received_ts = 242.551498 current_seq = 651 count = 418 seq_step = 1 [240.572666] (kms_flip:4811) DEBUG: Vblank took 49us [240.589228] (kms_flip:4811) DEBUG: name = flip last_ts = 242.552185 last_received_ts = 242.551498 last_seq = 651 current_ts = 242.568863 current_received_ts = 242.568130 current_seq = 652 count = 419 seq_step = 1 [240.589281] (kms_flip:4811) DEBUG: Vblank took 51us [240.605931] (kms_flip:4811) DEBUG: name = flip last_ts = 242.568863 last_received_ts = 242.568130 last_seq = 652 current_ts = 242.585541 current_received_ts = 242.584854 current_seq = 653 count = 420 seq_step = 1 [240.605981] (kms_flip:4811) DEBUG: Vblank took 48us [240.622621] (kms_flip:4811) DEBUG: name = flip last_ts = 242.585541 last_received_ts = 242.584854 last_seq = 653 current_ts = 242.602234 current_received_ts = 242.601562 current_seq = 654 count = 421 seq_step = 1 [240.622673] (kms_flip:4811) DEBUG: Vblank took 50us [240.639218] (kms_flip:4811) DEBUG: name = flip last_ts = 242.602234 last_received_ts = 242.601562 last_seq = 654 current_ts = 242.618912 current_received_ts = 242.618179 current_seq = 655 count = 422 seq_step = 1 [240.639270] (kms_flip:4811) DEBUG: Vblank took 49us [240.655939] (kms_flip:4811) DEBUG: name = flip last_ts = 242.618912 last_received_ts = 242.618179 last_seq = 655 current_ts = 242.635590 current_received_ts = 242.634918 current_seq = 656 count = 423 seq_step = 1 [240.655992] (kms_flip:4811) DEBUG: Vblank took 50us [240.672622] (kms_flip:4811) DEBUG: name = flip last_ts = 242.635590 last_received_ts = 242.634918 last_seq = 656 current_ts = 242.652267 current_received_ts = 242.651611 current_seq = 657 count = 424 seq_step = 1 [240.672678] (kms_flip:4811) DEBUG: Vblank took 53us [240.689190] (kms_flip:4811) DEBUG: name = flip last_ts = 242.652267 last_received_ts = 242.651611 last_seq = 657 current_ts = 242.668945 current_received_ts = 242.668198 current_seq = 658 count = 425 seq_step = 1 [240.689240] (kms_flip:4811) DEBUG: Vblank took 48us [240.705919] (kms_flip:4811) DEBUG: name = flip last_ts = 242.668945 last_received_ts = 242.668198 last_seq = 658 current_ts = 242.685638 current_received_ts = 242.684952 current_seq = 659 count = 426 seq_step = 1 [240.707007] (kms_flip:4811) DEBUG: Vblank took 1080us [240.707014] (kms_flip:4811) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [240.707086] (kms_flip:4811) CRITICAL: Failed assertion: end - start < 500 [240.707124] (kms_flip:4811) CRITICAL: Last errno: 4, Interrupted system call [240.730533] (kms_flip:4811) igt_core-INFO: Stack trace: [240.744017] (kms_flip:4811) igt_core-INFO: #0 ../lib/igt_core.c:2074 __igt_fail_assert() [240.745351] (kms_flip:4811) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [240.745437] (kms_flip:4811) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [240.745474] (kms_flip:4811) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() [240.745515] (kms_flip:4811) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [240.749212] (kms_flip:4811) igt_core-INFO: #5 [__libc_init_first+0x8a] [240.750043] (kms_flip:4811) igt_core-INFO: #6 [__libc_start_main+0x8b] [240.750236] (kms_flip:4811) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (8.421s)
Dmesg	<6> [308.414621] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [308.422027] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430] <7> [308.423227] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [308.424920] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [308.425272] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [308.425526] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [308.482187] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [308.482275] 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> [308.482521] 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> [308.482620] 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> [308.482717] 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> [308.482845] 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> [308.482947] 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> [308.483045] 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> [308.483135] 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> [308.483223] 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> [308.483311] 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> [308.483400] 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> [308.483492] 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> [308.483584] 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> [308.483673] 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> [308.483797] 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> [308.483924] 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> [308.484049] 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> [308.484138] 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> [308.484227] 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> [308.484318] 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> [308.484407] 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> [308.484498] 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> [308.484588] 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> [308.484676] 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> [308.484769] 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> [308.484857] 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> [308.484943] 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> [308.485032] 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> [308.485113] 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> [308.485192] 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> [308.485270] 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> [308.485347] 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> [308.485423] 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> [308.485500] 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> [308.485577] 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> [308.485654] 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> [308.485731] 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> [308.485843] 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> [308.485945] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [308.486045] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [308.486163] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [308.486241] 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> [308.486333] 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> [308.486401] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [308.486492] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [308.486578] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [308.486664] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [308.486788] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [308.486916] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [308.487042] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [308.487134] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [308.487217] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [308.487299] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [308.487381] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [308.487515] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [308.487632] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [308.487876] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [308.487991] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [308.689486] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [308.690260] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [308.709653] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [308.709998] 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> [308.710364] 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> [308.762349] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [308.762851] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [308.770216] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [308.770702] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [308.770760] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [308.772339] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [308.772915] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [308.773533] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [308.773996] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [308.774425] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [308.774801] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [308.775182] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [308.775593] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [308.775985] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [308.776370] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [308.776718] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [308.777059] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [308.777449] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [308.777782] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [308.778117] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [308.778559] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [308.778981] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [308.779370] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [308.779686] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [308.780254] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [308.780759] 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> [308.781323] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [308.781738] 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> [308.782232] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [308.782611] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [308.783537] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [308.783929] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [308.784249] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [308.784317] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [308.784490] 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> [308.784881] 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> [308.785211] 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> [308.785525] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [308.785811] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [308.786108] 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> [308.786440] 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> [308.786751] 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> [308.787009] 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> [308.787286] 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> [308.787541] 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> [308.787764] 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> [308.787998] 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> [308.788222] 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> [308.788415] 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> [308.788600] 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> [308.788789] 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> [308.789005] 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> [308.789260] 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> [308.789425] 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> [308.789580] 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> [308.789729] 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> [308.789880] 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> [308.790029] 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> [308.790191] 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> [308.790335] 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> [308.790468] 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> [308.790598] 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> [308.790723] 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> [308.790849] 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> [308.790980] 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> [308.791115] 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> [308.791240] 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> [308.791360] 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> [308.791480] 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> [308.791594] 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> [308.791704] 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> [308.791813] 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> [308.791922] 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> [308.792046] 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> [308.792165] 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> [308.792268] 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> [308.792368] 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> [308.792466] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [308.792600] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [308.792683] 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> [308.792785] 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> [308.792868] 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> [308.792947] 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> [308.793015] 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> [308.793080] 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> [308.793172] 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> [308.793270] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [308.793385] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [308.793485] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [308.793572] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [308.793657] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [308.793741] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [308.793824] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [308.793922] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [308.794013] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [308.794116] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [308.794248] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [308.794365] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [308.794462] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [308.794547] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [308.794633] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [308.794716] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [308.794799] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [308.794880] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [308.794960] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [308.795039] 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> [308.795132] 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> [308.795275] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [308.795401] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [308.795492] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [308.795571] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [308.795657] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [308.795742] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [308.795827] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [308.795911] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [308.795987] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [308.796065] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [308.796161] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [308.796285] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [308.796407] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [308.796488] 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> [308.796565] 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> [308.796641] 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> [308.796716] 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> [308.796792] 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> [308.796867] 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> [308.796941] 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> [308.797016] 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> [308.797104] 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> [308.797209] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [308.797318] 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> [308.797420] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [308.797508] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [308.797596] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [308.797681] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [308.797766] 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> [308.797848] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [308.797925] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [308.798001] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [308.798077] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [308.798183] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [308.798302] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [308.798404] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [308.798481] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [308.798558] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [308.798633] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x40000000 gamma_enable: 0 csc_enable: 0 <7> [308.798708] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 256 entries <7> [308.798783] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [308.798859] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [308.798935] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [308.799009] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [308.799091] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [308.799191] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [308.799302] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [308.799410] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [308.799498] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [308.799579] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [308.799654] 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> [308.799731] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [308.799808] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [308.799885] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [308.799966] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [308.800048] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [308.800152] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [308.800253] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [308.800363] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [308.800546] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [308.800599] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [308.800647] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [308.800754] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [308.800754] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [308.800906] 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> [308.801053] 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> [308.801187] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [308.801301] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [308.801407] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [308.801479] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [308.801548] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [308.801619] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [308.801690] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [308.801758] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [308.801840] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [308.801920] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [308.801990] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [308.802060] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [308.802151] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [308.802238] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [308.802321] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [308.802423] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [308.802585] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [308.802648] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [308.802758] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [308.804123] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [308.804239] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [308.806267] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [308.806390] 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> [309.272318] 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> [309.363552] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [309.364014] 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> [309.364399] 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> [309.400706] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [309.401110] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [309.401525] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [309.402226] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [309.576593] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [309.577068] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [309.577463] 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> [309.579641] 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> [309.581168] 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> [309.581993] 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> [309.583144] 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> [309.584514] 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> [309.585710] 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> [309.586118] 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> [309.587682] 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> [309.588068] 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> [309.589180] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [309.589696] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [309.590129] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [309.590596] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [309.623315] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [309.625147] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [309.625616] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <7> [312.179239] 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> [312.179807] 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> [316.773531] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [316.774208] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [316.774856] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [316.839121] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

8.42 seconds

Hostname

shard-lnl-5

Igt-Version

IGT-Version: 2.4-g00d5807a3 (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5067-b9819223b7e921730-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 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (8.421s)

Err

Starting dynamic subtest: B-eDP1
[240.707014] (kms_flip:4811) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[240.707086] (kms_flip:4811) CRITICAL: Failed assertion: end - start < 500
[240.707124] (kms_flip:4811) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
[238.689654] (kms_flip:4811) DEBUG: Vblank took 70us
[238.706246] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.667038
last_received_ts = 240.666351
last_seq = 538
current_ts = 240.683716
current_received_ts = 240.683044
current_seq = 539
count = 306
seq_step = 1
[238.706327] (kms_flip:4811) DEBUG: Vblank took 75us
[238.722901] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.683716
last_received_ts = 240.683044
last_seq = 539
current_ts = 240.700409
current_received_ts = 240.699722
current_seq = 540
count = 307
seq_step = 1
[238.722977] (kms_flip:4811) DEBUG: Vblank took 69us
[238.739599] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.700409
last_received_ts = 240.699722
last_seq = 540
current_ts = 240.717087
current_received_ts = 240.716431
current_seq = 541
count = 308
seq_step = 1
[238.739675] (kms_flip:4811) DEBUG: Vblank took 69us
[238.756228] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.717087
last_received_ts = 240.716431
last_seq = 541
current_ts = 240.733765
current_received_ts = 240.733078
current_seq = 542
count = 309
seq_step = 1
[238.756304] (kms_flip:4811) DEBUG: Vblank took 71us
[238.772904] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.733765
last_received_ts = 240.733078
last_seq = 542
current_ts = 240.750458
current_received_ts = 240.749786
current_seq = 543
count = 310
seq_step = 1
[238.772982] (kms_flip:4811) DEBUG: Vblank took 70us
[238.789565] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.750458
last_received_ts = 240.749786
last_seq = 543
current_ts = 240.767136
current_received_ts = 240.766464
current_seq = 544
count = 311
seq_step = 1
[238.789642] (kms_flip:4811) DEBUG: Vblank took 71us
[238.806236] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.767136
last_received_ts = 240.766464
last_seq = 544
current_ts = 240.783813
current_received_ts = 240.783157
current_seq = 545
count = 312
seq_step = 1
[238.806319] (kms_flip:4811) DEBUG: Vblank took 75us
[238.822904] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.783813
last_received_ts = 240.783157
last_seq = 545
current_ts = 240.800507
current_received_ts = 240.799835
current_seq = 546
count = 313
seq_step = 1
[238.822989] (kms_flip:4811) DEBUG: Vblank took 78us
[238.839558] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.800507
last_received_ts = 240.799835
last_seq = 546
current_ts = 240.817184
current_received_ts = 240.816513
current_seq = 547
count = 314
seq_step = 1
[238.839635] (kms_flip:4811) DEBUG: Vblank took 71us
[238.856218] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.817184
last_received_ts = 240.816513
last_seq = 547
current_ts = 240.833878
current_received_ts = 240.833191
current_seq = 548
count = 315
seq_step = 1
[238.856296] (kms_flip:4811) DEBUG: Vblank took 71us
[238.872898] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.833878
last_received_ts = 240.833191
last_seq = 548
current_ts = 240.850555
current_received_ts = 240.849899
current_seq = 549
count = 316
seq_step = 1
[238.872975] (kms_flip:4811) DEBUG: Vblank took 71us
[238.889551] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.850555
last_received_ts = 240.849899
last_seq = 549
current_ts = 240.867249
current_received_ts = 240.866562
current_seq = 550
count = 317
seq_step = 1
[238.889628] (kms_flip:4811) DEBUG: Vblank took 70us
[238.906203] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.867249
last_received_ts = 240.866562
last_seq = 550
current_ts = 240.883926
current_received_ts = 240.883240
current_seq = 551
count = 318
seq_step = 1
[238.906281] (kms_flip:4811) DEBUG: Vblank took 70us
[238.922877] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.883926
last_received_ts = 240.883240
last_seq = 551
current_ts = 240.900620
current_received_ts = 240.899933
current_seq = 552
count = 319
seq_step = 1
[238.922970] (kms_flip:4811) DEBUG: Vblank took 86us
[238.939534] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.900620
last_received_ts = 240.899933
last_seq = 552
current_ts = 240.917297
current_received_ts = 240.916611
current_seq = 553
count = 320
seq_step = 1
[238.939612] (kms_flip:4811) DEBUG: Vblank took 71us
[238.956200] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.917297
last_received_ts = 240.916611
last_seq = 553
current_ts = 240.933975
current_received_ts = 240.933289
current_seq = 554
count = 321
seq_step = 1
[238.956278] (kms_flip:4811) DEBUG: Vblank took 71us
[238.972820] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.933975
last_received_ts = 240.933289
last_seq = 554
current_ts = 240.950668
current_received_ts = 240.949936
current_seq = 555
count = 322
seq_step = 1
[238.972926] (kms_flip:4811) DEBUG: Vblank took 100us
[238.989569] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.950668
last_received_ts = 240.949936
last_seq = 555
current_ts = 240.967346
current_received_ts = 240.966705
current_seq = 556
count = 323
seq_step = 1
[238.989646] (kms_flip:4811) DEBUG: Vblank took 70us
[239.006193] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.967346
last_received_ts = 240.966705
last_seq = 556
current_ts = 240.984039
current_received_ts = 240.983353
current_seq = 557
count = 324
seq_step = 1
[239.006306] (kms_flip:4811) DEBUG: Vblank took 105us
[239.023126] (kms_flip:4811) DEBUG: name = flip
last_ts = 240.984039
last_received_ts = 240.983353
last_seq = 557
current_ts = 241.000717
current_received_ts = 241.000259
current_seq = 558
count = 325
seq_step = 1
[239.023291] (kms_flip:4811) DEBUG: Vblank took 134us
[239.039545] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.000717
last_received_ts = 241.000259
last_seq = 558
current_ts = 241.017395
current_received_ts = 241.016739
current_seq = 559
count = 326
seq_step = 1
[239.039642] (kms_flip:4811) DEBUG: Vblank took 86us
[239.056277] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.017395
last_received_ts = 241.016739
last_seq = 559
current_ts = 241.034088
current_received_ts = 241.033463
current_seq = 560
count = 327
seq_step = 1
[239.056383] (kms_flip:4811) DEBUG: Vblank took 83us
[239.072788] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.034088
last_received_ts = 241.033463
last_seq = 560
current_ts = 241.050766
current_received_ts = 241.050018
current_seq = 561
count = 328
seq_step = 1
[239.072903] (kms_flip:4811) DEBUG: Vblank took 99us
[239.089451] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.050766
last_received_ts = 241.050018
last_seq = 561
current_ts = 241.067444
current_received_ts = 241.066711
current_seq = 562
count = 329
seq_step = 1
[239.089521] (kms_flip:4811) DEBUG: Vblank took 65us
[239.106139] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.067444
last_received_ts = 241.066711
last_seq = 562
current_ts = 241.084137
current_received_ts = 241.083420
current_seq = 563
count = 330
seq_step = 1
[239.106199] (kms_flip:4811) DEBUG: Vblank took 56us
[239.122818] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.084137
last_received_ts = 241.083420
last_seq = 563
current_ts = 241.100815
current_received_ts = 241.100113
current_seq = 564
count = 331
seq_step = 1
[239.122875] (kms_flip:4811) DEBUG: Vblank took 54us
[239.139506] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.100815
last_received_ts = 241.100113
last_seq = 564
current_ts = 241.117508
current_received_ts = 241.116821
current_seq = 565
count = 332
seq_step = 1
[239.139556] (kms_flip:4811) DEBUG: Vblank took 48us
[239.156177] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.117508
last_received_ts = 241.116821
last_seq = 565
current_ts = 241.134186
current_received_ts = 241.133514
current_seq = 566
count = 333
seq_step = 1
[239.156233] (kms_flip:4811) DEBUG: Vblank took 53us
[239.172821] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.134186
last_received_ts = 241.133514
last_seq = 566
current_ts = 241.150879
current_received_ts = 241.150177
current_seq = 567
count = 334
seq_step = 1
[239.172877] (kms_flip:4811) DEBUG: Vblank took 53us
[239.189479] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.150879
last_received_ts = 241.150177
last_seq = 567
current_ts = 241.167557
current_received_ts = 241.166855
current_seq = 568
count = 335
seq_step = 1
[239.189532] (kms_flip:4811) DEBUG: Vblank took 49us
[239.206181] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.167557
last_received_ts = 241.166855
last_seq = 568
current_ts = 241.184235
current_received_ts = 241.183578
current_seq = 569
count = 336
seq_step = 1
[239.206230] (kms_flip:4811) DEBUG: Vblank took 47us
[239.222805] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.184235
last_received_ts = 241.183578
last_seq = 569
current_ts = 241.200928
current_received_ts = 241.200226
current_seq = 570
count = 337
seq_step = 1
[239.222852] (kms_flip:4811) DEBUG: Vblank took 45us
[239.239502] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.200928
last_received_ts = 241.200226
last_seq = 570
current_ts = 241.217606
current_received_ts = 241.216934
current_seq = 571
count = 338
seq_step = 1
[239.239553] (kms_flip:4811) DEBUG: Vblank took 48us
[239.256185] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.217606
last_received_ts = 241.216934
last_seq = 571
current_ts = 241.234283
current_received_ts = 241.233643
current_seq = 572
count = 339
seq_step = 1
[239.256252] (kms_flip:4811) DEBUG: Vblank took 64us
[239.272801] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.234283
last_received_ts = 241.233643
last_seq = 572
current_ts = 241.250977
current_received_ts = 241.250275
current_seq = 573
count = 340
seq_step = 1
[239.272856] (kms_flip:4811) DEBUG: Vblank took 52us
[239.289466] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.250977
last_received_ts = 241.250275
last_seq = 573
current_ts = 241.267654
current_received_ts = 241.266953
current_seq = 574
count = 341
seq_step = 1
[239.289516] (kms_flip:4811) DEBUG: Vblank took 48us
[239.306149] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.267654
last_received_ts = 241.266953
last_seq = 574
current_ts = 241.284332
current_received_ts = 241.283661
current_seq = 575
count = 342
seq_step = 1
[239.306203] (kms_flip:4811) DEBUG: Vblank took 50us
[239.322767] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.284332
last_received_ts = 241.283661
last_seq = 575
current_ts = 241.301010
current_received_ts = 241.300293
current_seq = 576
count = 343
seq_step = 1
[239.322819] (kms_flip:4811) DEBUG: Vblank took 49us
[239.339490] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.301010
last_received_ts = 241.300293
last_seq = 576
current_ts = 241.317703
current_received_ts = 241.317032
current_seq = 577
count = 344
seq_step = 1
[239.339535] (kms_flip:4811) DEBUG: Vblank took 40us
[239.356115] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.317703
last_received_ts = 241.317032
last_seq = 577
current_ts = 241.334381
current_received_ts = 241.333679
current_seq = 578
count = 345
seq_step = 1
[239.356234] (kms_flip:4811) DEBUG: Vblank took 116us
[239.372796] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.334381
last_received_ts = 241.333679
last_seq = 578
current_ts = 241.351059
current_received_ts = 241.350388
current_seq = 579
count = 346
seq_step = 1
[239.372848] (kms_flip:4811) DEBUG: Vblank took 49us
[239.389443] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.351059
last_received_ts = 241.350388
last_seq = 579
current_ts = 241.367752
current_received_ts = 241.367050
current_seq = 580
count = 347
seq_step = 1
[239.389510] (kms_flip:4811) DEBUG: Vblank took 50us
[239.406124] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.367752
last_received_ts = 241.367050
last_seq = 580
current_ts = 241.384430
current_received_ts = 241.383743
current_seq = 581
count = 348
seq_step = 1
[239.406178] (kms_flip:4811) DEBUG: Vblank took 47us
[239.422797] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.384430
last_received_ts = 241.383743
last_seq = 581
current_ts = 241.401108
current_received_ts = 241.400436
current_seq = 582
count = 349
seq_step = 1
[239.422853] (kms_flip:4811) DEBUG: Vblank took 52us
[239.439449] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.401108
last_received_ts = 241.400436
last_seq = 582
current_ts = 241.417786
current_received_ts = 241.417114
current_seq = 583
count = 350
seq_step = 1
[239.439508] (kms_flip:4811) DEBUG: Vblank took 55us
[239.456117] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.417786
last_received_ts = 241.417114
last_seq = 583
current_ts = 241.434479
current_received_ts = 241.433792
current_seq = 584
count = 351
seq_step = 1
[239.456172] (kms_flip:4811) DEBUG: Vblank took 52us
[239.472766] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.434479
last_received_ts = 241.433792
last_seq = 584
current_ts = 241.451157
current_received_ts = 241.450455
current_seq = 585
count = 352
seq_step = 1
[239.472825] (kms_flip:4811) DEBUG: Vblank took 55us
[239.489451] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.451157
last_received_ts = 241.450455
last_seq = 585
current_ts = 241.467834
current_received_ts = 241.467163
current_seq = 586
count = 353
seq_step = 1
[239.489507] (kms_flip:4811) DEBUG: Vblank took 53us
[239.506121] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.467834
last_received_ts = 241.467163
last_seq = 586
current_ts = 241.484528
current_received_ts = 241.483856
current_seq = 587
count = 354
seq_step = 1
[239.506172] (kms_flip:4811) DEBUG: Vblank took 48us
[239.522755] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.484528
last_received_ts = 241.483856
last_seq = 587
current_ts = 241.501205
current_received_ts = 241.500504
current_seq = 588
count = 355
seq_step = 1
[239.522808] (kms_flip:4811) DEBUG: Vblank took 50us
[239.539411] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.501205
last_received_ts = 241.500504
last_seq = 588
current_ts = 241.517883
current_received_ts = 241.517181
current_seq = 589
count = 356
seq_step = 1
[239.539464] (kms_flip:4811) DEBUG: Vblank took 51us
[239.556059] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.517883
last_received_ts = 241.517181
last_seq = 589
current_ts = 241.534576
current_received_ts = 241.533844
current_seq = 590
count = 357
seq_step = 1
[239.556116] (kms_flip:4811) DEBUG: Vblank took 54us
[239.572765] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.534576
last_received_ts = 241.533844
last_seq = 590
current_ts = 241.551254
current_received_ts = 241.550568
current_seq = 591
count = 358
seq_step = 1
[239.572829] (kms_flip:4811) DEBUG: Vblank took 61us
[239.589413] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.551254
last_received_ts = 241.550568
last_seq = 591
current_ts = 241.567932
current_received_ts = 241.567245
current_seq = 592
count = 359
seq_step = 1
[239.589460] (kms_flip:4811) DEBUG: Vblank took 45us
[239.606094] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.567932
last_received_ts = 241.567245
last_seq = 592
current_ts = 241.584625
current_received_ts = 241.583939
current_seq = 593
count = 360
seq_step = 1
[239.606161] (kms_flip:4811) DEBUG: Vblank took 65us
[239.622759] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.584625
last_received_ts = 241.583939
last_seq = 593
current_ts = 241.601303
current_received_ts = 241.600616
current_seq = 594
count = 361
seq_step = 1
[239.622821] (kms_flip:4811) DEBUG: Vblank took 58us
[239.639372] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.601303
last_received_ts = 241.600616
last_seq = 594
current_ts = 241.617981
current_received_ts = 241.617249
current_seq = 595
count = 362
seq_step = 1
[239.639408] (kms_flip:4811) DEBUG: Vblank took 34us
[239.656039] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.617981
last_received_ts = 241.617249
last_seq = 595
current_ts = 241.634674
current_received_ts = 241.633942
current_seq = 596
count = 363
seq_step = 1
[239.656124] (kms_flip:4811) DEBUG: Vblank took 83us
[239.672784] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.634674
last_received_ts = 241.633942
last_seq = 596
current_ts = 241.651352
current_received_ts = 241.650681
current_seq = 597
count = 364
seq_step = 1
[239.672845] (kms_flip:4811) DEBUG: Vblank took 57us
[239.689393] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.651352
last_received_ts = 241.650681
last_seq = 597
current_ts = 241.668030
current_received_ts = 241.667328
current_seq = 598
count = 365
seq_step = 1
[239.689465] (kms_flip:4811) DEBUG: Vblank took 69us
[239.706094] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.668030
last_received_ts = 241.667328
last_seq = 598
current_ts = 241.684723
current_received_ts = 241.684052
current_seq = 599
count = 366
seq_step = 1
[239.706143] (kms_flip:4811) DEBUG: Vblank took 47us
[239.722755] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.684723
last_received_ts = 241.684052
last_seq = 599
current_ts = 241.701401
current_received_ts = 241.700729
current_seq = 600
count = 367
seq_step = 1
[239.722809] (kms_flip:4811) DEBUG: Vblank took 51us
[239.739403] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.701401
last_received_ts = 241.700729
last_seq = 600
current_ts = 241.718079
current_received_ts = 241.717392
current_seq = 601
count = 368
seq_step = 1
[239.739449] (kms_flip:4811) DEBUG: Vblank took 45us
[239.756048] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.718079
last_received_ts = 241.717392
last_seq = 601
current_ts = 241.734772
current_received_ts = 241.734055
current_seq = 602
count = 369
seq_step = 1
[239.756099] (kms_flip:4811) DEBUG: Vblank took 49us
[239.772726] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.734772
last_received_ts = 241.734055
last_seq = 602
current_ts = 241.751450
current_received_ts = 241.750763
current_seq = 603
count = 370
seq_step = 1
[239.772777] (kms_flip:4811) DEBUG: Vblank took 49us
[239.789412] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.751450
last_received_ts = 241.750763
last_seq = 603
current_ts = 241.768127
current_received_ts = 241.767456
current_seq = 604
count = 371
seq_step = 1
[239.789476] (kms_flip:4811) DEBUG: Vblank took 61us
[239.806050] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.768127
last_received_ts = 241.767456
last_seq = 604
current_ts = 241.784805
current_received_ts = 241.784119
current_seq = 605
count = 372
seq_step = 1
[239.806106] (kms_flip:4811) DEBUG: Vblank took 53us
[239.822717] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.784805
last_received_ts = 241.784119
last_seq = 605
current_ts = 241.801498
current_received_ts = 241.800797
current_seq = 606
count = 373
seq_step = 1
[239.822765] (kms_flip:4811) DEBUG: Vblank took 45us
[239.839406] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.801498
last_received_ts = 241.800797
last_seq = 606
current_ts = 241.818176
current_received_ts = 241.817505
current_seq = 607
count = 374
seq_step = 1
[239.839458] (kms_flip:4811) DEBUG: Vblank took 49us
[239.856059] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.818176
last_received_ts = 241.817505
last_seq = 607
current_ts = 241.834854
current_received_ts = 241.834183
current_seq = 608
count = 375
seq_step = 1
[239.856121] (kms_flip:4811) DEBUG: Vblank took 59us
[239.872729] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.834854
last_received_ts = 241.834183
last_seq = 608
current_ts = 241.851532
current_received_ts = 241.850876
current_seq = 609
count = 376
seq_step = 1
[239.872785] (kms_flip:4811) DEBUG: Vblank took 53us
[239.889392] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.851532
last_received_ts = 241.850876
last_seq = 609
current_ts = 241.868225
current_received_ts = 241.867554
current_seq = 610
count = 377
seq_step = 1
[239.889446] (kms_flip:4811) DEBUG: Vblank took 52us
[239.906089] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.868225
last_received_ts = 241.867554
last_seq = 610
current_ts = 241.884903
current_received_ts = 241.884262
current_seq = 611
count = 378
seq_step = 1
[239.906156] (kms_flip:4811) DEBUG: Vblank took 63us
[239.922725] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.884903
last_received_ts = 241.884262
last_seq = 611
current_ts = 241.901581
current_received_ts = 241.900925
current_seq = 612
count = 379
seq_step = 1
[239.922778] (kms_flip:4811) DEBUG: Vblank took 51us
[239.939384] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.901581
last_received_ts = 241.900925
last_seq = 612
current_ts = 241.918274
current_received_ts = 241.917603
current_seq = 613
count = 380
seq_step = 1
[239.939434] (kms_flip:4811) DEBUG: Vblank took 48us
[239.956075] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.918274
last_received_ts = 241.917603
last_seq = 613
current_ts = 241.934952
current_received_ts = 241.934311
current_seq = 614
count = 381
seq_step = 1
[239.956142] (kms_flip:4811) DEBUG: Vblank took 64us
[239.972699] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.934952
last_received_ts = 241.934311
last_seq = 614
current_ts = 241.951630
current_received_ts = 241.950958
current_seq = 615
count = 382
seq_step = 1
[239.972756] (kms_flip:4811) DEBUG: Vblank took 54us
[239.989374] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.951630
last_received_ts = 241.950958
last_seq = 615
current_ts = 241.968323
current_received_ts = 241.967651
current_seq = 616
count = 383
seq_step = 1
[239.989427] (kms_flip:4811) DEBUG: Vblank took 50us
[240.006020] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.968323
last_received_ts = 241.967651
last_seq = 616
current_ts = 241.985001
current_received_ts = 241.984314
current_seq = 617
count = 384
seq_step = 1
[240.006073] (kms_flip:4811) DEBUG: Vblank took 51us
[240.022725] (kms_flip:4811) DEBUG: name = flip
last_ts = 241.985001
last_received_ts = 241.984314
last_seq = 617
current_ts = 242.001678
current_received_ts = 242.001038
current_seq = 618
count = 385
seq_step = 1
[240.022786] (kms_flip:4811) DEBUG: Vblank took 57us
[240.039370] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.001678
last_received_ts = 242.001038
last_seq = 618
current_ts = 242.018372
current_received_ts = 242.017700
current_seq = 619
count = 386
seq_step = 1
[240.039424] (kms_flip:4811) DEBUG: Vblank took 51us
[240.056042] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.018372
last_received_ts = 242.017700
last_seq = 619
current_ts = 242.035049
current_received_ts = 242.034393
current_seq = 620
count = 387
seq_step = 1
[240.056089] (kms_flip:4811) DEBUG: Vblank took 45us
[240.072700] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.035049
last_received_ts = 242.034393
last_seq = 620
current_ts = 242.051727
current_received_ts = 242.051071
current_seq = 621
count = 388
seq_step = 1
[240.072768] (kms_flip:4811) DEBUG: Vblank took 64us
[240.089375] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.051727
last_received_ts = 242.051071
last_seq = 621
current_ts = 242.068420
current_received_ts = 242.067749
current_seq = 622
count = 389
seq_step = 1
[240.089441] (kms_flip:4811) DEBUG: Vblank took 62us
[240.106011] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.068420
last_received_ts = 242.067749
last_seq = 622
current_ts = 242.085098
current_received_ts = 242.084412
current_seq = 623
count = 390
seq_step = 1
[240.106059] (kms_flip:4811) DEBUG: Vblank took 46us
[240.122663] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.085098
last_received_ts = 242.084412
last_seq = 623
current_ts = 242.101791
current_received_ts = 242.101089
current_seq = 624
count = 391
seq_step = 1
[240.122711] (kms_flip:4811) DEBUG: Vblank took 47us
[240.139349] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.101791
last_received_ts = 242.101089
last_seq = 624
current_ts = 242.118469
current_received_ts = 242.117783
current_seq = 625
count = 392
seq_step = 1
[240.139404] (kms_flip:4811) DEBUG: Vblank took 52us
[240.156004] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.118469
last_received_ts = 242.117783
last_seq = 625
current_ts = 242.135147
current_received_ts = 242.134460
current_seq = 626
count = 393
seq_step = 1
[240.156052] (kms_flip:4811) DEBUG: Vblank took 46us
[240.172648] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.135147
last_received_ts = 242.134460
last_seq = 626
current_ts = 242.151825
current_received_ts = 242.151123
current_seq = 627
count = 394
seq_step = 1
[240.172700] (kms_flip:4811) DEBUG: Vblank took 49us
[240.189346] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.151825
last_received_ts = 242.151123
last_seq = 627
current_ts = 242.168518
current_received_ts = 242.167831
current_seq = 628
count = 395
seq_step = 1
[240.189402] (kms_flip:4811) DEBUG: Vblank took 54us
[240.206009] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.168518
last_received_ts = 242.167831
last_seq = 628
current_ts = 242.185196
current_received_ts = 242.184525
current_seq = 629
count = 396
seq_step = 1
[240.206063] (kms_flip:4811) DEBUG: Vblank took 51us
[240.222632] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.185196
last_received_ts = 242.184525
last_seq = 629
current_ts = 242.201874
current_received_ts = 242.201157
current_seq = 630
count = 397
seq_step = 1
[240.222686] (kms_flip:4811) DEBUG: Vblank took 51us
[240.239311] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.201874
last_received_ts = 242.201157
last_seq = 630
current_ts = 242.218552
current_received_ts = 242.217850
current_seq = 631
count = 398
seq_step = 1
[240.239365] (kms_flip:4811) DEBUG: Vblank took 52us
[240.255977] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.218552
last_received_ts = 242.217850
last_seq = 631
current_ts = 242.235229
current_received_ts = 242.234543
current_seq = 632
count = 399
seq_step = 1
[240.256035] (kms_flip:4811) DEBUG: Vblank took 55us
[240.272663] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.235229
last_received_ts = 242.234543
last_seq = 632
current_ts = 242.251923
current_received_ts = 242.251236
current_seq = 633
count = 400
seq_step = 1
[240.272720] (kms_flip:4811) DEBUG: Vblank took 54us
[240.289303] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.251923
last_received_ts = 242.251236
last_seq = 633
current_ts = 242.268600
current_received_ts = 242.267899
current_seq = 634
count = 401
seq_step = 1
[240.289346] (kms_flip:4811) DEBUG: Vblank took 41us
[240.305975] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.268600
last_received_ts = 242.267899
last_seq = 634
current_ts = 242.285278
current_received_ts = 242.284592
current_seq = 635
count = 402
seq_step = 1
[240.306031] (kms_flip:4811) DEBUG: Vblank took 53us
[240.322634] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.285278
last_received_ts = 242.284592
last_seq = 635
current_ts = 242.301971
current_received_ts = 242.301270
current_seq = 636
count = 403
seq_step = 1
[240.322704] (kms_flip:4811) DEBUG: Vblank took 66us
[240.339309] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.301971
last_received_ts = 242.301270
last_seq = 636
current_ts = 242.318634
current_received_ts = 242.317963
current_seq = 637
count = 404
seq_step = 1
[240.339387] (kms_flip:4811) DEBUG: Vblank took 76us
[240.355990] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.318634
last_received_ts = 242.317963
last_seq = 637
current_ts = 242.335327
current_received_ts = 242.334656
current_seq = 638
count = 405
seq_step = 1
[240.356049] (kms_flip:4811) DEBUG: Vblank took 57us
[240.372645] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.335327
last_received_ts = 242.334656
last_seq = 638
current_ts = 242.352005
current_received_ts = 242.351334
current_seq = 639
count = 406
seq_step = 1
[240.372715] (kms_flip:4811) DEBUG: Vblank took 66us
[240.389306] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.352005
last_received_ts = 242.351334
last_seq = 639
current_ts = 242.368683
current_received_ts = 242.368011
current_seq = 640
count = 407
seq_step = 1
[240.389362] (kms_flip:4811) DEBUG: Vblank took 52us
[240.405997] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.368683
last_received_ts = 242.368011
last_seq = 640
current_ts = 242.385376
current_received_ts = 242.384720
current_seq = 641
count = 408
seq_step = 1
[240.406053] (kms_flip:4811) DEBUG: Vblank took 53us
[240.422628] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.385376
last_received_ts = 242.384720
last_seq = 641
current_ts = 242.402054
current_received_ts = 242.401367
current_seq = 642
count = 409
seq_step = 1
[240.422687] (kms_flip:4811) DEBUG: Vblank took 55us
[240.439309] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.402054
last_received_ts = 242.401367
last_seq = 642
current_ts = 242.418732
current_received_ts = 242.418060
current_seq = 643
count = 410
seq_step = 1
[240.439367] (kms_flip:4811) DEBUG: Vblank took 56us
[240.455888] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.418732
last_received_ts = 242.418060
last_seq = 643
current_ts = 242.435410
current_received_ts = 242.434662
current_seq = 644
count = 411
seq_step = 1
[240.455942] (kms_flip:4811) DEBUG: Vblank took 51us
[240.472631] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.435410
last_received_ts = 242.434662
last_seq = 644
current_ts = 242.452087
current_received_ts = 242.451416
current_seq = 645
count = 412
seq_step = 1
[240.472681] (kms_flip:4811) DEBUG: Vblank took 47us
[240.489266] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.452087
last_received_ts = 242.451416
last_seq = 645
current_ts = 242.468781
current_received_ts = 242.468079
current_seq = 646
count = 413
seq_step = 1
[240.489319] (kms_flip:4811) DEBUG: Vblank took 51us
[240.505879] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.468781
last_received_ts = 242.468079
last_seq = 646
current_ts = 242.485458
current_received_ts = 242.484695
current_seq = 647
count = 414
seq_step = 1
[240.505929] (kms_flip:4811) DEBUG: Vblank took 47us
[240.522601] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.485458
last_received_ts = 242.484695
last_seq = 647
current_ts = 242.502136
current_received_ts = 242.501434
current_seq = 648
count = 415
seq_step = 1
[240.522662] (kms_flip:4811) DEBUG: Vblank took 57us
[240.539262] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.502136
last_received_ts = 242.501434
last_seq = 648
current_ts = 242.518814
current_received_ts = 242.518127
current_seq = 649
count = 416
seq_step = 1
[240.539317] (kms_flip:4811) DEBUG: Vblank took 53us
[240.555934] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.518814
last_received_ts = 242.518127
last_seq = 649
current_ts = 242.535492
current_received_ts = 242.534805
current_seq = 650
count = 417
seq_step = 1
[240.555984] (kms_flip:4811) DEBUG: Vblank took 47us
[240.572614] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.535492
last_received_ts = 242.534805
last_seq = 650
current_ts = 242.552185
current_received_ts = 242.551498
current_seq = 651
count = 418
seq_step = 1
[240.572666] (kms_flip:4811) DEBUG: Vblank took 49us
[240.589228] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.552185
last_received_ts = 242.551498
last_seq = 651
current_ts = 242.568863
current_received_ts = 242.568130
current_seq = 652
count = 419
seq_step = 1
[240.589281] (kms_flip:4811) DEBUG: Vblank took 51us
[240.605931] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.568863
last_received_ts = 242.568130
last_seq = 652
current_ts = 242.585541
current_received_ts = 242.584854
current_seq = 653
count = 420
seq_step = 1
[240.605981] (kms_flip:4811) DEBUG: Vblank took 48us
[240.622621] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.585541
last_received_ts = 242.584854
last_seq = 653
current_ts = 242.602234
current_received_ts = 242.601562
current_seq = 654
count = 421
seq_step = 1
[240.622673] (kms_flip:4811) DEBUG: Vblank took 50us
[240.639218] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.602234
last_received_ts = 242.601562
last_seq = 654
current_ts = 242.618912
current_received_ts = 242.618179
current_seq = 655
count = 422
seq_step = 1
[240.639270] (kms_flip:4811) DEBUG: Vblank took 49us
[240.655939] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.618912
last_received_ts = 242.618179
last_seq = 655
current_ts = 242.635590
current_received_ts = 242.634918
current_seq = 656
count = 423
seq_step = 1
[240.655992] (kms_flip:4811) DEBUG: Vblank took 50us
[240.672622] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.635590
last_received_ts = 242.634918
last_seq = 656
current_ts = 242.652267
current_received_ts = 242.651611
current_seq = 657
count = 424
seq_step = 1
[240.672678] (kms_flip:4811) DEBUG: Vblank took 53us
[240.689190] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.652267
last_received_ts = 242.651611
last_seq = 657
current_ts = 242.668945
current_received_ts = 242.668198
current_seq = 658
count = 425
seq_step = 1
[240.689240] (kms_flip:4811) DEBUG: Vblank took 48us
[240.705919] (kms_flip:4811) DEBUG: name = flip
last_ts = 242.668945
last_received_ts = 242.668198
last_seq = 658
current_ts = 242.685638
current_received_ts = 242.684952
current_seq = 659
count = 426
seq_step = 1
[240.707007] (kms_flip:4811) DEBUG: Vblank took 1080us
[240.707014] (kms_flip:4811) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[240.707086] (kms_flip:4811) CRITICAL: Failed assertion: end - start < 500
[240.707124] (kms_flip:4811) CRITICAL: Last errno: 4, Interrupted system call
[240.730533] (kms_flip:4811) igt_core-INFO: Stack trace:
[240.744017] (kms_flip:4811) igt_core-INFO:   #0 ../lib/igt_core.c:2074 __igt_fail_assert()
[240.745351] (kms_flip:4811) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[240.745437] (kms_flip:4811) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[240.745474] (kms_flip:4811) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
[240.745515] (kms_flip:4811) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[240.749212] (kms_flip:4811) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[240.750043] (kms_flip:4811) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[240.750236] (kms_flip:4811) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (8.421s)

Dmesg

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

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

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

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

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

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

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

<7> [308.482275] 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> [308.482521] 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> [308.482620] 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> [308.482717] 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> [308.482845] 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> [308.482947] 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> [308.483045] 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> [308.483135] 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> [308.483223] 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> [308.483311] 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> [308.483400] 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> [308.483492] 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> [308.483584] 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> [308.483673] 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> [308.483797] 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> [308.483924] 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> [308.484049] 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> [308.484138] 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> [308.484227] 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> [308.484318] 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> [308.484407] 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> [308.484498] 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> [308.484588] 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> [308.484676] 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> [308.484769] 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> [308.484857] 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> [308.484943] 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> [308.485032] 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> [308.485113] 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> [308.485192] 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> [308.485270] 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> [308.485347] 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> [308.485423] 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> [308.485500] 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> [308.485577] 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> [308.485654] 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> [308.485731] 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> [308.485843] 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> [308.485945] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [308.784490] 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> [308.784881] 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> [308.785211] 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> [308.785525] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0

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

<7> [308.786108] 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> [308.786440] 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> [308.786751] 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> [308.787009] 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> [308.787286] 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> [308.787541] 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> [308.787764] 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> [308.787998] 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> [308.788222] 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> [308.788415] 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> [308.788600] 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> [308.788789] 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> [308.789005] 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> [308.789260] 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> [308.789425] 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> [308.789580] 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> [308.789729] 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> [308.789880] 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> [308.790029] 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> [308.790191] 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> [308.790335] 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> [308.790468] 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> [308.790598] 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> [308.790723] 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> [308.790849] 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> [308.790980] 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> [308.791115] 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> [308.791240] 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> [308.791360] 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> [308.791480] 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> [308.791594] 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> [308.791704] 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> [308.791813] 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> [308.791922] 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> [308.792046] 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> [308.792165] 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> [308.792268] 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> [308.792368] 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> [308.792466] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset

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

<7> [308.792683] 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> [308.792785] 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> [308.792868] 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> [308.792947] 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> [308.793015] 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> [308.793080] 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> [308.793172] 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> [308.793270] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [308.795039] 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> [308.795132] 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> [308.795275] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

<7> [308.796488] 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> [308.796565] 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> [308.796641] 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> [308.796716] 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> [308.796792] 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> [308.796867] 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> [308.796941] 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> [308.797016] 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> [308.797104] 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> [308.797209] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [308.806390] 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> [309.272318] 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> [309.363552] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

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

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

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

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

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

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

<7> [309.577463] 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> [309.579641] 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> [309.581168] 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> [309.581993] 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> [309.583144] 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> [309.584514] 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> [309.585710] 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> [309.586118] 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> [309.587682] 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> [309.588068] 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> [309.589180] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B

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

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

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

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

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

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

<7> [312.179239] 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> [312.179807] 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> [316.773531] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

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

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

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

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